Making sense of Scout, and the data underneath

top-act-en
Adobe Scout gives you a ton of beautiful data to look at, but interpreting it isn’t so straightforward. This post will take a peek at what kind of data Scout gathers behind the scenes and how it creates all the pretty pictures, so you can more easily grok just what’s going on. (Or to put it more plainly, I recently wrote an ADC article on Scout’s custom telemetry APIs, and this post covers a few things I learned while writing it but didn’t include in the article.)

The absolute basics:

When you start a profiling session Flash opens a socket connection to Scout and sends down a bunch of data. Most of the data that winds up represented in Scout’s main panels is the names and timing details of a bunch of defined activities. (Besides activities there are also trace statements, Stage3D commands and textures, and some other things.) Scout parses all those activity details and whips them into easily (?) understandable charts and graphs.

Activities

By “activity” Scout means a block of time devoted to a given functionality. Activities in Scout have the following features:

  • Each one has a name, a start time and an end time. Some activities also have other parameters.
  • Activities are nested. If Activity A starts before Activity B and ends afterwards, Scout considers B to be a child activity of A.
  • Based on the timing data it gets, Scout calculates a total time and a self time for each activity.
    • Total time is just the period between the activity’s start and end.
    • Self time is the time spent on that activity but not its children. In other words, an activity’s self time is it’s total time, minus the total times of its immediate child activities.

If you’ve looked at Scout’s custom telemetry APIs, activities are essentially the same thing as custom span metrics. There are some small differences in how they’re handled but nothing that concerns us here.

Concrete example

Suppose that Flash sends* the following sort of data to Scout:

Scout will then parse this into self/total times as follows:

As you can see, the nestedness of parent/child activities is inferred from timing. Incidentally if you use the custom span metric API to define activities that don’t nest (e.g. B starts during A but ends afterwards), viewing the data in Scout will generate an error or just not display. So when defining your own nested metrics, be careful to end them in the reverse order that you started them.

* Note: to be absolutely precise, Flash doesn’t send Scout start and end times for each activity, but end times and durations. The result is the same though.

 Interpreting the data

With the previous explanation in mind, the data that shows up in Scout should now be a little easier to interpret. First, in the Activity Sequence panel, all the activities Scout knows for a single frame about are listed up, with their nested relationships intact:

act-seq-en

You can even see each activity’s start time, though that’s usually not useful so it’s turned off by default. (Right-click the column titles to change which ones are visible.)

(Incidentally, Scout normally filters out any activity that would have a total time of less than 0.5ms. To toggle this behavior click the “Hide small items” button, at the far upper left in the image above.)

The Top Activities panel, on the other hand, ignores the activities’ start times and nesting relationships so that it can show aggregate data over multiple frames. Now multiple instances of the same activity are grouped (by activity name) rather than showing up multiple times as in the sequence panel, so Scout gives a count of how many times they occurred during the selected span.

top-act2-en

The data behind the two panels is identical, it’s just marshalled and displayed differently. And hopefully understanding the data behind the panels will make the implications more obvious. For example, if you invoke Flash’s renderer via APIs like BitmapData.draw(), the rendering activity will be a child of the ActionScript activity. So the only way to distinguish that rendering from general DisplayList rendering is to look in the Activity Sequence panel, where nesting is preserved. If you check the Top Activities panel, all the rendering activities will be grouped, regardless of whether Flash invoked them automatically or you did manually.

Finally, a quick note about the Summary panel:

summary-en

It may not be immediately obvious but the times shown for each entry in the Summary panel are the self times of the related activity. The summary panel just groups activities into some predefined categories and displays the sum of the self times for each. (The easiest way to see which activity name belongs to which category is to just look at the colors Scout uses.)

The ActionScript panel

The data shown in Scout’s AS panel is a completely different animal from everything discussed so far. The reason being, if Flash sent an activity to Scout every time an AS3 function was called, profiling overhead would bring things to a grinding halt. So instead, Flash samples the call stack every millisecond or so, and Scout guesses what’s going on. For example, if Flash sent along data like this:

Scout can look at that and guess that FunctionC was executing for around 2ms. But whether it executed once or dozens of times during that time isn’t known, and FunctionC may have called FunctionD between two of the samples (if FunctionD returned quickly). That’s why the AS panel gives somewhat approximate results, and why you should select a long timespan of data (i.e. a large sample) if you want to get accurate results in the AS panel.

That completes our look under the covers of Scout’s data. If anything is still unclear, leave a comment or let me know on twitter!

4 thoughts on “Making sense of Scout, and the data underneath”

  1. Interesting post, Scout is a really useful tool, especially when developing AIR apps and targeting older iOS or Android devices.

    But something is still unclear to me. In your screenshot from the summary panel, we can see that there are 154 ms in the Other section: 34 ms for Garbage Collection, 7 ms for SWF Processing, 10 ms for Event Processing, and 103 ms for Other Overhead. 34 + 7 + 10 + 103 = 154 and this always seems to be true, ok.

    But now open the ActionScript section and try to add the self times of each subsection. You will notice that the sum isn’t right. It’s often not far off, but in some of my tests this sum doesn’t even reach half of the time labelled for the ActionScript section.

    For example, an app slows down, ActionScript is the preponderant section, let’s say 100 ms each frame for a second (so 10 FPS, the app isn’t fluid), but the sum Buit-In Packages, User Packages, and Stage3D subsections is only 40 ms. The sum of self time from all functions in the ActionScript panel (in Bottom-Up mode) is also lesser or equal to 40 ms. Consequently more than half of the computation time isn’t known and cannot be optimized. Do you know where this time goes? Or am I missing something?

    1. Hey, great question. I haven’t checked w/ engineering but I’m 90% sure the reason is that once you expand “ActionScript” in the summary panel, all the package-specific data is coming from the ActionScript sampling, which is inherently inexact, as described in the article.

      As for the details, from my tests it seems to have a lot to do with whether processing is done in a few slow functions or a lot of fast ones. It’s easy to see why – if Scout samples the call stack every millisecond and the same function is on the top for 30 samples in a row, Scout can easily assume that function was executing for about 29-31ms. But if every sample has a different function on top of the stack, it becomes sort of a guessing game to tell what happened.

      With that said, my guess is that in your case Scout isn’t really “missing” 60% of the time spent, it’s more like it’s underreporting across the board – i.e. it’s probably correct about which functions took the longest to execute, even if the numbers for how long they took are way off. But usually the only dependable way to get better data from the sampler is to have more samples. Ideally you do this by selecting a long span on the timeline, but if you need better data for something only happens once, you might try profiling a build of your app that has been tweaked to do that processing 10 or 100 times more than is needed. My guess is that having more samples to look at should make the AS sampler data a lot more accurate. (If you try this, let me know if it works!)

      1. There is indeed a lot of small function calls in my test, so maybe that’s it but I’m really not sure. I suspect more and more a couple of ANE, many function calls, maybe causing some overhead Scout isn’t able to sample correctly. It’s really difficult to evaluate, a lot of modules are running concurrently :|

Leave a Reply

Your email address will not be published. Required fields are marked *

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code class="" title="" data-url=""> <del datetime=""> <em> <i> <q cite=""> <strike> <strong> <pre class="" title="" data-url=""> <span class="" title="" data-url="">