Trace calls to Canvas::saveLayer

[dnfield]

These calls tend to be expensive on rasterization. Adding traces can make it easier to tell how many times they're happening per frame on expensive-to-rasterize frames

Fixes flutter/flutter#92840

/cc @kenzieschmoll @jacob314

[dnfield]

@flar AFAICT, I don't want to add these to the dispatchers for DisplayList, since that would duplicate tracing. Please let me know if I'm misunderstanding anything there.

[chinmaygarde]

The cost of the save layer is not just isolated to this scope. There will be significant time taken in the flush waiting on the GPU to service this workload. So, perhaps a more actionable metric is to have a counter that tracks the number of save layers?

[chinmaygarde]

TRACE_COUNTER instead of TRACE_EVENT I mean.

[dnfield]

Counters won't show up in systracing. My idea here is that devtools could manually count these, and developers would be able to more easily see what callstacks were resulting in them. Then we'd want something like debugging the SKP that resulted and you could visually see what parts of the draw used a savelayer.

[dnfield]

(so yes, these trace events will be very small, but devtools will be able to scan for them and know they result in more expensive operations later)

[flar]

It's not just that the bulk of the work happens in a different phase of the pipeline (i.e. flush vs LayerTree.Paint), it's that even the saveLayer call itself doesn't really do the work. It remembers a few items you told it, then later the restore applies that work. So there are many reasons why this timed event isn't capturing any real work.

Why doesn't devtools scan for the counter events? They are just another type of event in the Chrome Tracing.

[chinmaygarde]

Why doesn't devtools scan for the counter events?

Discussing this in person, it looks like devtools should be able to detect counter events. systrace is an issue though and I am investigating if counters are not supported by systrace or whether this is a limitation with our trace logger to systrace. In any case, it looks like our use case ought to be address by just tracing to the timeline.

[jacob314]

it would be great to switch this to a counter as these events are adding noise to the trace right now without clear user value.

[dnfield]

We didn't use counters because it wouldn't be seen by users. The action a user should take is to turn on debugTracePaintEnabled and remove or rewrite the render object adding this call.

[zanderso]

... without clear user value.

I don't remember the full context of this discussion---if these are trace events we explicitly added for the benefit of end-users, then we should certainly try to make them more useful---but in general, it's been our practice to add trace events as needed to assist Engine developers in zeroing in on issues, be they performance issues or otherwise. So (in general, maybe not for this specific case) if a trace event is too noisy, the corrective action would be to filter it before an end-user sees it.

[kenzieschmoll]

Can we add an arg to these trace events "devtoolsTag": "saveLayer" or "devtoolsTag": "skia"? This would be a bit more robust than just string matching on the name. If there are more interesting skia calls that we'd consider tracking and counting in DevTools, then I like the arg "devtoolsTag": "skia", as that would be extensible to surface more data from skia in the future.

"devtoolsTag" args are added for shader events currently.

[flar]

@flar AFAICT, I don't want to add these to the dispatchers for DisplayList, since that would duplicate tracing. Please let me know if I'm misunderstanding anything there.

saveLayer calls captured in a DisplayList aren't duplicates of any other saveLayer that appears in the rest of the source code.

[dnfield]

@flar AFAICT, I don't want to add these to the dispatchers for DisplayList, since that would duplicate tracing. Please let me know if I'm misunderstanding anything there.

saveLayer calls captured in a DisplayList aren't duplicates of any other saveLayer that appears in the rest of the source code.

@flar AFAICT, I don't want to add these to the dispatchers for DisplayList, since that would duplicate tracing. Please let me know if I'm misunderstanding anything there.

saveLayer calls captured in a DisplayList aren't duplicates of any other saveLayer that appears in the rest of the source code.

I'm speaking specifically about calls in https://github.com/flutter/engine/blob/master/flow/display_list_canvas.cc

[dnfield]

Talked with Chinmay offline a bit, I'll look at getting this set up as a counter. @kenzieschmoll do you still need special args there for counters?

[kenzieschmoll]

We may not need a "devtoolsTag" arg then. Will the counter event be sent for each call to saveLayer? Or will the saveLayer call count be included in the event args? See https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview#heading=h.msg3086636uq for an example with "cats" and "dogs"

[chinmaygarde]

Will the counter event be sent for each call to saveLayer?

Ideally, it would be sent once per frame after the rasterization. This should significantly reduce the trace size and also be easier to collect.

[dnfield]

I've updated this to emit an FML_TRACE_COUNTER at the end of each layer tree paint. It required a bit of plumbing.

I should ideally write several more tests for individual components of this rather than the integration-type test I wrote in Dart. Before I do that I'd like to make sure this approach seems reasonable to @chinmaygarde and @kenzieschmoll will be able to consume it properly in devtools. The event comes out in the timeline looking like this:

     {
        "name":"LayerTree::SaveLayerCount",
        "cat":"Embedder",
        "tid":10755,
        "pid":32564,
        "ts":293539251550,
        "ph":"C",
        "args":{
           "count":"2"
        }
     },

[chinmaygarde]

Looks good to me. Offline, we spoke about potentially using a SkCanvasVirtualEnforcer to track this but the downside of that is all canvas creation in the engine would need to be updated. OTOH, the downside of this approach is that we may potentially missing bumping up the counter as the code evolves.

[kenzieschmoll]

One thing that would be very helpful from the DevTools side is if we can add the frame number to the event args. This will allow us to link this counter event with the proper frame it belongs to. We already have access to this frame number somewhere in the engine and pass it to a couple other events as a "frame_number" arg.

[flar]

After looking at this amount of plumbing I feel as if we should be using the events instead.

There is too much disruption of various systems and the accounting is wrong in some places in ways that fixing will only add a lot more accounting. Prepare on a layer, for instance, could end up just doing a touch on the cache entry, or it could find that the cache entry is already populated and do no work at all, or it could try to populate the cache and fail due to conditions deeper in the code. Adding a save layer count on every call to prepare is more often to be over-accounting than anything.

The accounting for save layers in the flutter::Picture object would end up being redundant for display lists who could easily tell you how many save layers they have directly or even do the savelayer events themselves at the site where they invoke it.

SkPicture may not do all of those saveLayers because peephole optimizations may delete them, or RTree code may bypass them.

All in all I think the events were far simpler. As far as trying to measure the duration of the saveLayer events - which is a meaningless exercise, there are instantaneous trace events which do not measure a duration and those would be reasonable to use for the saveLayers. Using (non-duration) events would also show you where in the timeline they happened rather than just the count.

[flar]

What saveLayer is this counting for?

[dnfield]

Rasterizing this layer for the cache is effectively a saveLayer - although your point about this possibly touching the cache without updating the image is well taken.

[flar]

I can imagine that the hit rate on this specific count being true is probably very low. But it can vary case by case.

[flar]

Also, this increment only accounts for the saveLayer in this layer's own Paint() call. Consider that this layer has children and those children can also contain saveLayer calls and this increment of 1 can't even hope to account for all of those.

While we could design another accounting workaround for that issue, this is perhaps yet another reason that using trace events localized at the sites of the saveLayer calls would greatly improve the accuracy of these metrics in a less convoluted way.

[flar]

This may be a better mechanism than duration events or counts:

engine/fml/trace_event.h

Line 119 in bbc4615

#define TRACE_EVENT_INSTANT0(category_group, name) \

[flar]

Will the counter event be sent for each call to saveLayer?

Ideally, it would be sent once per frame after the rasterization. This should significantly reduce the trace size and also be easier to collect.

After looking at the new code I don't think "easier to collect" rang true in the end. Tagging the sites with instant events looks a lot less invasive to the architecture.

[dnfield]

The main problem with instant events is that they definitely do not show up in systracing, and it would be a shame to lose this information when using systracing. That was the real reason for using the duration based events, rather than to actually capture any timing information. See https://github.com/dart-lang/sdk/blob/56e7532f99f85150968bed6b54f3301960a1bcd3/runtime/vm/timeline_android.cc#L61-L90

Perhaps a fix for that would be to have Dart emit instant events as B/E couples with the same or some trivially small timestamp in the systrace recorder? Instant events tend to be hard to see though.

As far as optimizations removing saveLayer - it'd be nice if we could capture those, but I'm mainly concerned with making it clearer to developers when their app is using saveLayer for a particular frame so that they can find and eliminate it, rather than relying on an optimization that may stop working due to seemingly unrelated changes in their application.

[dnfield]

The "easier to collect" part was also referring to how devtools would collect this information, now to how the engine would :)

[flar]

Ah, yes, devtools would have to look for them as it scans the events, but I'm presuming it already scans the events anyway, so that is just adding another case to the scanner?

I looked for the documentation of the systrace format, but couldn't find anything. Having a zero length event should be fine - or we could wrap the call to canvas->saveLayer like was done before even if that isn't very meaningful, it would disrupt our code less to not have to "find" a place to increment a counter from every location that uses saveLayer.

[flar]

I just noticed this. Even though I am pushing for switching back to tagging the saveLayer calls themselves with events as it is more accurate and less disruptive, I thought I'd point out a problem with this specific change if for no other reason than to educate.

This call is preparing the children for a cache entry. There is not an implicit saveLayer involved when those children are rasterized like there is when "this" is cached. So, this specific increment is incorrect in all cases.

[dnfield]

Per offline discussion:

• I've reverted this back to the simple TRACE_EVENT0 tracking of saveLayer. This is self-admittedly not directly measuring the expensive part, but will help with ongoing investigations into raster related jank while we develop a better solution.
• We're not using instant traces because those get dropped on the floor for systracing by the Dart VM. They also are not visible in DevTools/observatory views.
• We're not using counters because the duration events will help us correlate these saveLayer calls with the RenderObjects making them, which can be helpful for debugging.
• I'll work on a proposal to get more wholistic views into "operations that we know are expensive."

[dnfield]

I also believe that this version will not double-count or incorrectly count raster caching as a save layer, unless the save layer call actually happens in Layer::Paint.

[flar]

This is incorrect. This line is only recording a saveLayer and has nothing to do with the execution of saveLayers.

The recorded picture can be reused on every single frame from here on and it won't be recorded (there's not much that can be done for that with SkP, but DL could record them as they execute).

The recorded picture could be a mistake and never used even once.

This trace will appear on the build thread, not the raster thread.

There is everything wrong with this event.

[dnfield]

I know that this record won't be enough, but in most cases it will provide signal about where in developer code someone actually triggered a saveLayer. My more recent concern is that it might not be enough, since things like drawColor and drawPaint might also trigger a saveLayer.

How would you suggest achieving this?

[flar]

Where are the trace events on the auto save layers used in other layers? Also, DL should be tracing the events in the canvas adapter in display_list_canvas.cc.

[dnfield]

The AutoSaveLayer tracing is definitely missing here.

I was under the impression that tracing it in the canvas adapter in display_list_canvas.cc would be duplicating events - e.g. that UI's Canvas::saveLayer would eventually make that same call into the adapter's saveLayer. Is that not the case?

[flar]

canvas.cc records a request that may be executed anywhere from 0 to 1000 times (or more). It is basically throwing stats at the wall.

dl_canvas.cc has a 1:1 ratio of times it calls saveLayer to times when we actually do saveLayer work. (The only caveat is that Skia might elide some of them due to culling, but that should be rare and the same thing could be said about any other way of accounting them.)

Calling the latter a duplicate doesn't really ring true to me. The naive call site in canvas.cc should be considered the duplicate call site compared to dl_canvas.cc.

While it is true that this might leave us with no accounting at all if DL is disabled, when DL is enabled we have a 100% (99.9%?) accurate count.

If we were coding for SkPicture, I would count the saveLayer calls while recording and remember them in the Picture and have picture_layer try to do something with that (dl_layer can ignore the count if dl_canvas.cc does the events). If DL remains enabled by default, that code would never get used, though.

[flar]

Another thing to consider is that calling saveLayer on an SkRecorder canvas might eventually be elided due to peephole optimizers (ignoring how many times the Picture gets used). We eventually want to add a similar capability to DL as well. In that case, calling saveLayer in canvas.cc will literally disappear before it ever gets to the point of asking Skia for real work to be done (and regardless of how many times the Picture is reused).

[dnfield]

Part of the goal here is for developers to have a way to know what parts of their application code are resulting in saveLayers.

I'm fine with tracing at the DisplayListDispatcher::saveLayer, but that shows up on the raster thread rather than the UI thread, and makes it very difficult to figure out which RenderObject actually called saveLayer - which is actionable information the developer can use to remove/alter that renderObject.

The idea here is still not to say "this call is intrinsically expensive," but to say that it will result in expense later and there's something you can do about it. I still believe this tracing/mechanism can be refined further of course, but I do not think we should drop the tracing in canvas.cc. I suspect that rather than tracing when the DisplayListBuilder actually adds it to Skia, we probably want to surface Skia's trace of OpsTask::onExecute to see whether Skia actually ended up using it to do GPU work.

[flar]

Then we should use 2 mechanisms.

And how is emitting an event going to accomplish your associativity goal? Events are already something that is delivered asynchronously so I would think it would be really hard to trace an event from the timeline into calls they are making.

If you want them to know when saveLayer calls are being used in their widgets, why not have this show up in the widget/RO dumps that they request when debugging the app?

[dnfield]

Then we should use 2 mechanisms.

Yes, that is the plan :) More information is forthcoming.

And how is emitting an event going to accomplish your associativity goal?

We're not there yet. But, emitting the event here will mean that when they turn on https://api.flutter.dev/flutter/rendering/debugProfilePaintsEnabled.html, they will see exactly which RenderObject was painting when saveLayer was called. This probably isn't enough though, since drawColor or drawPaint can end up resulting in a savelayer too.

[dnfield]

And with this trace, even without turning on that flag for now, @goderbauer and I will be able to more clearly see in CI generated traces on low end phones how many times these events are emitted and whether they're involved in the worst raster times we're seeing.

[flar]

This is really simple to fix.

Change the name of the event in canvas.cc to something indicating that a saveLayer is being recorded. That not only makes it more accurate, it prevents it from being confused with the calls in the raster code which are not the same kind of action. One is recording a request for a call, the other is actually doing the saveLayer.

Add 2 event calls to AutoSaveLayer and dl_canvas.cc which will bring the code to nearly 100% accounting for all saveLayers being executed during rasterization.

You get all of the utility of having the ui.Canvas calls tagged without having to worry about "duplicate calls which are not duplicates at all and in fact have different countability" while achieving greater accuracy for the "how many saveLayers executed in this frame" justification in the original description.

[flar]

I drafted the fix as #29598