logging icon indicating copy to clipboard operation
logging copied to clipboard

Send logs to Dart DevTools.

Open CoderDake opened this issue 1 year ago • 13 comments

As part of some product excellence pursuits for Dart Devtools we would like to make sure that package:logging records are also sent to Dart Devtools.

TBD i'm going to reach out to package members to ask about the best way to test this.

CoderDake avatar Mar 25 '24 21:03 CoderDake

Maybe opt-in, but defaulting here seems a bit too far. My $0.02

kevmoo avatar Mar 25 '24 21:03 kevmoo

Hmm, yes, this is a core package, and I'd be concerned that developer.log() is not zero cost (esp. when there's a debugging client hooked up). I'm curious - what options have been discussed here?

devoncarew avatar Mar 25 '24 21:03 devoncarew

@devoncarew in @bkonyi 's doc on Developer Tooling exploration, he points out that package:logging should at least have a default handler that forwards logs to developer.log. That is probably the only other option that has been looked at right now. I think this approach essentially accomplishes the same thing without having to set up another listener though.

Opt in could be a possibility for sure, but I think @bkonyi mentioned that he would prefer the dev logging by default. Perhaps he can comment on it's importance in his own words though.

CoderDake avatar Mar 26 '24 15:03 CoderDake

I don't think enabling this by default will result in much of a performance regression. For release mode applications, this log(...) is effectively a no-op and we can probably make further optimizations in dart:developer and package:logging to avoid unnecessary work when dart.vm.product is defined. I would be more concerned about logging performance issues related to expensive string interpolation operations that aren't tree-shaken out, even in the absence of a logging callback (I'm not sure how much of an issue this is, but I strongly suspect existing logging code isn't totally free).

Not using log(...) by default in package:logging seriously hampers the ability of developer tooling to provide structured logging support in DevTools and IDEs and puts the onus on developers to configure their logging to work correctly with first-party tooling. Most users are going to default to implementing their logging using print or stdout.writeln, completely bypassing the structured logging support already part of the SDK. This will make it more difficult for the tooling team to justify making investments in improving the Dart logging experience which, when compared to solutions like Logcat and XCodes log viewer, is extremely lacking, particularly in VSCode.

bkonyi avatar Mar 26 '24 15:03 bkonyi

I'm also worried about enabling this by default.

avoid unnecessary work when dart.vm.product is defined

What are the impacts of extra dart:developer log() calls on the web? @sigmundch

natebosch avatar Mar 26 '24 16:03 natebosch

I'm very much in favor of making structured logging visible to developers and improving the support for logging in our libraries and developer tools. I think this meeds a bit more thought however than can be done in a few line PR.

One possible design would be for dart:developer to have a way to register a logging provider. When in a log view of a developer tool - like devtools - the user could toggle on the 'package:logging' stream, which would then listen for all package:logging log events. This would be zero cost when logging wasn't being used.

devoncarew avatar Mar 26 '24 16:03 devoncarew

Thankfully for production (dart2js) this should be a noop - our patch for log is completely empty.

However, we had issues in the past with overhead from dart:developer log during development, if I recall correctly. I believe it was because of how these APIs got mapped to Chrome APis. @nshahan - you probably recall the details better than I do. Is it still a concern for us?

sigmundch avatar Mar 26 '24 16:03 sigmundch

AFAIK @elliette discovered and fixed the problem we had with our dart:developer logging implementation. I'm only not 100% sure it is fixed because I was never actually able to reproduce the problem myself and there are still sporadic unconfirmed reports of the problem still appearing. It isn't confirmed if the fix was actually live for those yet.

nshahan avatar Mar 26 '24 17:03 nshahan

One possible design would be for dart:developer to have a way to register a logging provider. When in a log view of a developer tool - like devtools - the user could toggle on the 'package:logging' stream, which would then listen for all package:logging log events. This would be zero cost when logging wasn't being used.

This is already the case for log(...). If there's no listeners on the Logging stream, the event is never built and processed by the VM service.

bkonyi avatar Mar 26 '24 17:03 bkonyi

One possible design would be for dart:developer to have a way to register a logging provider. When in a log view of a developer tool - like devtools - the user could toggle on the 'package:logging' stream, which would then listen for all package:logging log events. This would be zero cost when logging wasn't being used.

This is already the case for log(...). If there's no listeners on the Logging stream, the event is never built and processed by the VM service.

Although DDS does store a log history by default, which would cause this stream to be listened to immediately if the VM service is enabled. However, in situations where the VM service isn't enabled, there's no event created or sent.

bkonyi avatar Mar 26 '24 17:03 bkonyi

AFAIK @elliette discovered and fixed the problem we had with our dart:developer logging implementation. I'm only not 100% sure it is fixed because I was never actually able to reproduce the problem myself and there are still sporadic unconfirmed reports of the problem still appearing. It isn't confirmed if the fix was actually live for those yet.

Some context on what happens for dart:developer logs on the web:

  • The dart:developer implementation of log for DDC calls Chrome's console.debug API
  • DWDS listens for the console.debug events and adds them to the Logging stream
  • Before https://github.com/dart-lang/webdev/pull/2333, we were sending the truncated version of the log to that stream, now we send the full log
  • Dart DevTools listens for events to the Logging stream and displays them

The issue that was reported saying this wasn't working was because the DWDS change wasn't in the reporter's version of Flutter: https://github.com/dart-lang/webdev/issues/2400#issuecomment-2023195858

elliette avatar Mar 27 '24 16:03 elliette

It sounds like we could benefit from some data on the approaches. I'll set out to test these to see what types of impacts there are.

To ensure I understand the concerns involved though. I'd like to try to summarize the approaches to be tested and how to test them. Please let me know if the following seems to touch the points in contention

App to test against

Use the CPU profiler to analyse the runtime of the following code in a flutter app (it would be run after clicking a button.)

  void _runLoggingtest() {
    final defaultTag = getCurrentTag();
    final logTestTag = UserTag('Log Test');
    logTestTag.makeCurrent();
    for (var i = 0; i < 1000000; i++) {
      log.fine('Log test i: $i');
    }
    defaultTag.makeCurrent();
  }

Cases to test

  1. No changes. Just test the app as is
  2. This PR's change to package:logging
  3. Add log.onRecord.listen((record) => developer.log(...record)) to the test app
    • this would be a quick way to test @devoncarew's idea of a record listener that does the work for us.

States to test against

  • debug
  • profile
  • release

CoderDake avatar Mar 27 '24 21:03 CoderDake

Note: I'll use Stopwatch instead of the userTags (at Ben's advice)

CoderDake avatar Mar 28 '24 15:03 CoderDake