Sponsored By

In-depth: Using Chrome://tracing to view your inline profiling data

In this reprinted <a href="http://altdevblogaday.com/">#altdevblogaday</a> in-depth piece, Google's game developer advocate and Blizzard veteran Colt McAnlis shares how game developers can take advantage of Chrome's inline profiling.

Game Developer, Staff

August 24, 2012

10 Min Read

In this reprinted #altdevblogaday in-depth piece, Google's game developer advocate and Blizzard veteran Colt McAnlis shares how game developers can take advantage of Chrome's inline profiling. If you have an inline profiling system, with some slight modifications, you can view that data in the Chrome web browser rather than writing a visualization tool yourself. Having a nice graphical representation of profiling data is crucial to finding critical hotspots in a realtime application. Creating a viewer application for that custom data is a massive time sink, so before you start writing ones, know your options.

Getting started with profiling your game

Ahh performance — that three syllable word that accounts for the headache-causing and most often avoided part of the game development cycle. Once in a development blue moon, your manager will ramble into your office in a deep sweat, shouting about performance and expect you to do something about it. Eventually you'll search the Internet to find ways to uncover the hotspots in your code. You'll also learn some important information to consider when deciding what kind of profiling to use in order to discover where your code is spending its time. You'll find that profiling generally can be done two ways: First, invasive (or inline) profiling requires you to modify your existing source code to track the amount of time a given segment takes. This generally involves littering your code with scope-based macros that handle timing, buffering, and logging of that particular data to some output. Alternatively, non-invasive (or external) profiling lets you gather performance information from existing compiled libraries by sampling the callstack of the running application at regular intervals, and checking the current program counter against a known set of debugging symbol data. Each type of profiling has its pros and cons. External profiling does a great job at keeping your existing codebase clean, but suffers from a lack of resolution and overwhelming data density. Most external profilers will generate sample data by polling the target application at regular intervals (usually capped at 1ms), so the granularity of your sampling is limited by that constraint. If you make a call to 30 separate functions during that millisecond sampling interval, that information won't be displayed in the resulting data (rather you may see a single function taking 1ms of time). In addition, external profilers are non-discriminatory, meaning they sample your data and give information for whatever functions are being called, on whatever threads, regardless of what you're looking for. The excess data can make it difficult to navigate the profiling timeline to see what's really going on. There are several benefits and drawbacks to consider when using inline profiling. Inline profiling offers you the opportunity to choose the resolution you need because you can use high frequency timers right in your code. It also provides additional flexibility and granularity since you can get insert timings at a per-function and per scope level. However, it does so with the sacrifice of littering your codebase with functions to evaluate timings. This code change is so invasive that many developers have to create separate builds and testing configurations during production to properly exclude the profiling functions at runtime. Another drawback of inline profiling is that you often must create a viewer application in order to perform any useful type of analysis on the data you're logging. Writing a custom viewer is a non-trivial task; and woe to those engineers who decide to develop an entire in-game viewing system for the data. They often expend man-years of effort sunk into drawing boxes on a screen and adding proper UI information to navigate massive datasets.

Using chrome://tracing to peek under the hood

If you didn't already know, Google Chrome is a pretty awesome web browser. But what you may not know is that it comes with an inline profiling subsystem that you can use by browsing to chrome://tracing. What's great about this tool is that it allows you to capture profiling data about what Chrome is doing under the hood, so you can properly adjust your javascript execution, or optimize your asset loading. Chrome://tracing offers an intimate view of the browser's performance, recording all of Chrome's activities across every thread, tab, and process. Do you know what's going on under the hood of your web browser? chrome://tracing does. The tracing tool was built with two main features in mind. Firstly, to provide a view of what Chrome is doing under the hood, and secondly, it allows you to profile your Javascript code by inserting custom begin/end segments into the stream. Chrome 19+ javascript APIs expose the console.time("eventname") and console.timeEnd("eventname") events, allowing you to directly profile your custom Javascript code alongside the rest of what Chrome is executing.

Viewing external profile data files

One of the more unsung features of the tool is that it allows you to load external log files, which is the coolest part of the tool for non-web and non-mobile developers. By modifying your game's existing inline-profiling code to output a JSON object compatible with the chrome://tracing tab, you can use it as your visualization tool for your game's profiling purposes. For you Indie developers out there, this gives you the same tool functionality that all the pros get, but for a much smaller price-tag : FREE. The chrome://tracing tab acts as a visualizer for inline profiling data. You can scan, scrub, select, and more with this tool, allowing you to analyze your game profile data directly.

Understanding the chrome://tracing JSON data

The tracing data format is a non-optimized JSON file containing a sequence of event blocks. Each block includes the following name/value pairs:

  • 'cat' – the category for this event. Useful when doing larger grouping (eg "UnitUpdates")

  • 'name' – the name of this event (eg 'PathingUpdate')

  • 'pid' – the processor ID that spawned this event

  • 'tid' – the thread ID that spawned this event

  • 'ts' – the processor time stamp at the time this event was created

  • 'ph' – the phase or type of this event

  • 'args' – any programmatic metadata that's attached to this event

For an example, a JSON file with a single begin/end sample is listed below. Note that an event include descriptions of its category as well as its name. Some events occur in pairs, which are marked by complementary phases (B/E or S/F – read more about that below).

[
{
     "cat": "MY_SUBSYSTEM",  //catagory
     "pid": 4260,  //process ID
     "tid": 4776, //thread ID
     "ts": 2168627922668, //time-stamp of this event
     "ph": "B", // Begin sample
     "name": "doSomethingCostly", //name of this event
     "args": { //arguments associated with this event.
       }
},
]

Some sample data from the profiler's format. You can see there's a named category, as well as a name of the scoped event we're tracking. Some events come in pairs of phases (see below).

Understanding the phase ('ph') tag

Sample Begin/End events ( ph = B / E )

The most common event types are sample begin and sample end, denoted by setting the phase tag to "B" and "E" respectively. These events define the start and end points of a sampling time interval.

Instant events ( ph = I )

Instant events, denoted with an "I" phase tag, are great for tossing extra information into the stream to mark actions or events in your game, such as LevelLoadComplete, or SuperHugeMonsterStartedAttack. Instant markers in the timeline appear as small triangles. The visual difference is crucial when scrubbing over large portions of data.

Async Start/Finish events ( ph = S/F )

Async events can occur across multiple threads/processes. They are useful for tracing operations like texture loads that can start activity on other threads. The start of an async event is denoted by setting the phase tag to "S" (for start) and the end by setting the tag to "F" (for finish).

Event metadata (args)

Along with instances, chrome://tracing supports per-sample metadata (called args in the format), which can be filled in with name/value pairs of arbitrary data. This appends information to a specific event. Anyone who's scrubbed through inline profiling data will tell you that these types of markers are invaluable when you get barraged by a flood of samples with the same call stack and need a way to determine the data associated with each instance. Every Event and Instance can have annotated data associated with it, which is very helpful in tracking down unique data relating to a sample.

Adding capture-specific metadata

Another nice feature of the JSON format for capture analysis is the ability to append specific capture-specific metadata to the trace that may be helpful in analysis of the bigger picture. For instance, storing what developer did the capture, what OS they are running, hardware specs, etc. As mentioned, chrome:tracing will gladly accept the following syntax:

[
{       "cat": "MY_SUBSYSTEM", …..   },
{     "cat": "MY_SUBSYSTEM",...       },
]

And in order to add meta data, you can modify the format thusly:

{
traceEvents: [ /*the previous format data goes here*/ ],
someData: "this is some capture specific data",
someMoreData: "generated by [email protected]"
}

When you utilize the second form of the JSON format, upon file-load, a button in the UI will popup labeled 'METADATA' that shows all the non-trace event data in a stringified form.

Generating a chrome://tracing compliant JSON file

As discussed, the JSON file format itself is fairly straightforward. If you'd like to grab an example file, you can generate a version of the output by simply loading chrome://tracing and hitting the Record tab, running, then hitting the Stop tracing button. This action will record the inline profiling events generated by all the open tabs and processes running in Chrome. You can then save the data to disk and examine its format. If reverse engineering the data isn't your thing, you could also take a look at the Chromium source code, and grab the actual files that Chrome uses to format the JSON data, and subsequently the macros that are used inside Chrome to generate trace data as well. If reverse engineering the Chromium source code isn't your thing, I've extracted the correct files from the source tree, which you can grab via github.

Moving chrome://tracing forward

The tracing page inside of Chrome offers a powerful timeline viewing tool, and like any tool, it is constantly being improved. Here's what you need to know about working with chrome://tracing in the future.

  1. Like most Google products, the Javascript front-end code for rendering the timeline is open sourced, which is highly valuable for those of you looking to embed the process in your own applications, build-bot, or compliance testing web pages.

  2. Make sure you can find and report bugs with the tracing tool inside of chrome.

  3. In Case the JSON format doesn't suit your fancy, the chrome://tracing authors accept contributions on what types of timeline file/data formats to support.

  4. The Systrace feature recently added to the Android SDK lets developers use the same profiling UI to analyze the performance of their native applications.

Looking for more information? Check out the how to use chrome://tracing guide and get started using this powerful tool to display profiling data from your game. [This piece was reprinted from #AltDevBlogADay, a shared blog initiative started by @mike_acton devoted to giving game developers of all disciplines a place to motivate each other to write regularly about their personal game development passions.]

Daily news, dev blogs, and stories from Game Developer straight to your inbox

You May Also Like