dart-lang / sdk

The Dart SDK, including the VM, JS and Wasm compilers, analysis, core libraries, and more.
https://dart.dev
BSD 3-Clause "New" or "Revised" License
10.21k stars 1.57k forks source link

Provide debugging information about what scheduled a microtask #54749

Open dnfield opened 9 months ago

dnfield commented 9 months ago

A Flutter application developer may see a timeline like the following:

image

In a sufficiently large application, it's very difficult to tell where the microtasks running there came from (and what could be done to reduce them, if anything).

It would be really nice to have some way to provide debugging information about how many microtasks are running, what scheduled them, and how long they took. This could be in the form of the timeline or some sort of extension in the VM service.

/cc @bkonyi @kenzieschmoll @rmacnak-google

dnfield commented 8 months ago

FWIW, I've in the past done things like building a local engine/dart SDK with scheduleMicrotask hacked to add information about the top few frmes of the stack trace to the timeline argument. I don't think this is quite the right way to do it though - it's a lot of information to stuff into the timeline, and there are limits to what different recorders can handle (no arguments for systracing, max trace event name lengths).

It's also pretty expensive even in debug mode. But it can help identify e.g. a really noisy plugin or package that can be slimmed down to not just think that scheduleMicrotask is free :)

mkustermann commented 8 months ago

One can intercept microtasks by running code in a specialized zone by providing a ZoneDelegate.scheduleMicrotask. That callback could then capture StackTrace.current. It could issue a timeline event for every such call (probably overwhelming) or take the last N frames of the stack trace, make a running statistic and report this statistic every once in a while.

As the zone allows interception of scheduling of microtasks, it can also wrap the closure in another closure that would measure time before/after and report it (or include it into some running statistic that are reported once in a while).

That's where I'd start (but of course, taking a stack trace, stringifying it, etc has a certain cost, but that's a cost you have to bear if you want per-microtask information).

dnfield commented 8 months ago

I really hope that the sdk can provide a solution for this that doesn't involve zones. There is no guarantee that the zone code is running in is configured or programmed correctly, and creating zones adds overhead to all async execution.

kenzieschmoll commented 8 months ago

If tracing for this scenario is expensive, we should add this behind a service extension, similar to what we do for other expensive but helpful tracing tasks (like tracing widget builds or paints)

bkonyi commented 8 months ago

This is definitely not something we would want enabled by default.

What sort of information are we looking to collect and how much detail are we looking for? This type of tracing seems like a good fit for the timeline, but given the frequency of executing microtasks it could introduce a lot of noise in the timeline.

If we collect execution times and stack traces as Martin suggested, we could build a profile of microtasks similar to the CPU profile and display it in a tree view in DevTools. We could also perform sampling rather than collecting full traces to reduce the performance overhead as well.

dnfield commented 8 months ago

The things I want to know are:

lrhn commented 8 months ago

If we take "microtask" to mean system microtask, ignoring if someone build their own microtask queue on top, then the place to intercept is the scheduleMicrotask of the root zone, and the microtask queue which runs the scheduled tasks.

Counting how many microtasks rub is easy. Counting how much time the each took to run should be doable, just have a stopwatch, reset it before starting each microtask callback, and check it when control returns to the microtask queue.

It's the "who started it" which is complicated. If we can capture a stack trace (cheaply, if possible, maybe lumped in depth) when someone calls Zone.scheduleMicrotask or the top level scheduleMicrotask, then the most important stack grants should be near the top of the stack. But not necessarily at the top, since both futures and streams schedule microtasks.

It's also possible to enumerate all microtasks, and remember for each microtask, which other microtask scheduled it. Not always useful, but might be.