Beyond web developer tools: strace

[cross-posted from 2011 Performance Calendar]

Rich developer tools are available for all modern web browsers. They are typically easy to use and can provide all of the information necessary to optimize web pages. It is rare to need to go beyond the unified networking/scripting/rendering view of the Web Inspector's Timeline panel.

But they aren't always perfect: a tool may be missing information, may disagree with another tool, or may just be incorrect. For instance, a recent bug occasionally caused two Navigation Timing metrics to be incorrect in Chrome (and the Inspector).

When these rare situations arise, great engineers are able to go beyond a browser's developer tools to find out exactly what the browser is telling the operating system to do. On Linux, this source of ultimate truth can be found using strace. This tool can trace each system call made by a browser. Since every network and file access entails a system call, and this is where browsers spend a lot of their time, it is perfect for debugging many types of browser performance issues.

What about other platforms?

In this post, I introduce strace because the syntax is clean and no setup is required. But most systems have an equivalent tool for tracing system calls. Mobile developers will be happy to hear that strace is fully supported by Android. OS X users will find dtrace offers more powerful functionality at the expense of less intuitive syntax (unfortunately not ported to iOS). Finally, Event Tracing for Windows (ETW), while harder to setup, supports a friendly GUI.

Getting started

To use it: open a terminal and invoke strace at the command prompt. This invocation prints all system calls while starting Google Chrome to google.com:

$ strace -f -ttt -T google-chrome http://www.google.com/

I've added -f to follow forks, -ttt to print the timestamp of each call and -T to print the duration of each call.

Zeroing in

If you run the command above, you'll probably be overwhelmed by the amount of stuff going on in a modern web browser. To filter down to something interesting, try using the -e argument. For examining only file or network access, try -e trace=file or -e trace=network. The man page has many more examples.

An example: local storage

As a concrete example, let's trace local storage performance in Chrome. First I opened a local storage quota test page. Then I retrieved the Chrome browser processes' ID from Chrome's task manager (Wrench > Tools > Task Manager) and attached strace to that process using the -p switch.

$ strace -f -T -p <process id> -e trace=open,read,write

The output shows the timestamps, arguments and return value of every open, read, and write system call. The man page for each call explains the arguments and return values. The first call of interest to us is this open:

open("/home/tonyg/.config/google-chrome/Default/Local Storage/http_arty.name_0.localstorage-journal", O_RDWR|O_CREAT, 0640) = 114 <0.000391>

This shows us that Chrome has opened this file for reading and writing (and possibly created it). The name of the file is a big clue that this is where local storage is saved for arty's web page. The return value, 114, is the file descriptor which will identify it in later reads and writes. Now we can look for read and write calls which operate on fd 114, for example:

write(114, "\0\0\00020\0001\0002\0003\0004\0005\0006\0007\0008\0009\0000\0001\0002\0003\0"..., 1024 <unfinished ...>
<... write resumed> ) = 1024 <0.425476>

These two lines show a 1,024 byte write of the data beginning with the string above to the local storage file (114). This write happened to take 425ms. Note that the call is split into two lines with possibly others in between because another thread preempted it. This is common for slower calls like this.

We've only scratched the surface

There are options for dumping the full data read/written from the network or filesystem. Running with -c displays aggregate statistic about the time spent in the most common calls. I've also found that some practical python scripting can quickly parse these traces into a variety of useful formats.

This brief introduction hardly does this tool justice. I merely hope it provides the courage to explore deeper into the stack the next time you run into a tricky performance problem.

Finding memory leaks

Over lunch last week Mikhail Naganov (creator of the DevTools Heap Profiler) and I were discussing how invaluable it has been to have the same insight into JavaScript memory usage that we have into applications written in languages like C++ or Java. But the heap profiler doesn't seem to get as much attention from developers as I think it deserves. There could be two explanations: either leaking memory isn't a big problem for web sites or there is a problem but developers aren't aware of it.

Are memory leaks a problem?

For traditional pages where the user is encouraged to navigate from page to page, memory leaks should almost never be a problem. However, for any page that encourages interaction, memory management must be considered. Most realize that ultimately if too much memory is consumed the page will be killed, forcing the user to reload it. However, even before all memory is exhausted performance problems arise:

• A large JavaScript heap means garbage collections may take longer.
• Greater system memory pressure means fewer things can be cached (both in the browser and the OS).
• The OS may start paging or thrashing which can make the whole system feel sluggish.

These problems are of course exacerbated on mobile devices which have less RAM.

A real world walkthrough

So, in order to demonstrate this is a real world problem and how easily the heap profiler can diagnose it, I set out to find a memory leak in the wild. A peak at the task manager (Wrench > Tools > Task Manager) for my open tabs showed a good candidate for investigation: Facebook is consuming 410MB!!

Pinpoint the leaky action

The first step in finding a memory leak is to isolate the action that leaks. So I loaded facebook.com in a new tab. The fresh instance used only 49MB -- another indicator the 410MB might have been due to a leak. To observe memory use over time, I opened the Inspector's Timeline panel, selected the Memory tab and pressed the record button. At rest, the page displays a typical pattern of allocation and garbage collection. This is not a leak.

While keeping an eye on the graph, I began navigating around the site. I eventually noticed that each time I clicked the Events link on the left side, memory usage would rise but never be collected. This is how the usage grows as I repeatedly click the link. A quintessential leak.

As an aside, this leak isn't a browser bug. The OS task manager shows similar memory growth when performing the same action in Firefox.

Find the leaked memory

Now that we know we have a leak, the obvious next question is what is leaking. The heap profiler's ability to compare heap snapshots is the perfect tool to answer it. To use it, I reloaded a new instance and took a snapshot by clicking the heap snapshot button at the bottom of the Profiles panel. Next, I performed the leaky action a prime number of times in hopes that it might be easy to spot. So I clicked Events 13 times and immediately took a second snapshot. To compare before and after, I highlighted the second snapshot and selected Comparison view.

The comparison view displays the difference between any two snapshots. I sorted by delta to look for any objects that grew by the same number of times I clicked: 13. Sure enough, there were 13 more UIPagelets on the heap after my clicks than before.

Expanding the UIPagelet shows us each instance. Let's look at the first.

Each instance has an _element property that points to a DOM node. Expanding that node, we can see that it is part of a detached DOM tree of 136 nodes. This means that 136 nodes are no longer visible in the page, but are being held alive by a JavaScript reference. There are legitimate reasons to do this, but it is also easy and common to do it by accident.

Note that all memory statistics reported by the tool reflect only the memory allocated in the JavaScript heap. This does not include native memory used by the DOM objects. So we cannot readily determine how much memory those 136 nodes are using. It all depends on their content -- for example leaking images can burn through memory very quickly.

Determine what prevents collection

After finding the leaked memory the last question is what is preventing it from being collected. To answer this we simply highlight any node and the retaining path will be shown (I typically change it to show paths to window objects instead of paths to GC roots). Here we see a very simple path. The UIPagelets are stored in a __UIControllerRegistry object.

At first I wondered if this might intentionally keep DOM nodes alive as a cache. However, that doesn't seem to be the case. A search of the source JS shows several places where items are added to the __UIControllerRegistry, but I couldn't find anywhere where they are cleaned up. So this appears to be a case where retaining the DOM nodes is purely accidental. The fix is to remove references to these nodes so they may be collected.

Takeaway

The point of the post is not that facebook has a leak. Facebook is an extremely well engineered site and large apps all deal with memory leaks from time to time. The point is to demonstrate how readily leaks can be diagnosed even with no knowledge of the source.

For anyone with an interactive web site, I highly recommend using your site for a few minutes with the memory timeline enabled to watch for any suspicious growth. If you have to solve any issues, the manual has excellent tutorials.

How a web page loads

The major web browsers load web pages in basically the same way. This process is known as parsing and is described by the HTML5 specification. A high-level understanding of this process is critical to writing web pages that load efficiently.

Parsing overview

As chunks of the HTML source become available from the network (or cache, filesystem, etc), they are streamed to the HTML parser. Next, in a process known as tokenization, the parser iterates through the source generating a token for (most notably) each start tag, end tag and character outside of a tag.

For example the input source <b>hello</b> yields 7 tokens:

start-tag { name: b }
character { data: h }
character { data: e }
character { data: l }
character { data: l }
character { data: o }
end-tag { name: b }

After each token is generated it is serially passed to the next major subsystem: the tree builder. The tree builder dynamically modifies the Document's DOM tree to reflect the new token.

The 7 input tokens above yield the following DOM tree:

<html>
  <head>
  <body>
    <b>
      "hello"

Fetching subresources

A frequent operation performed by the tree builder is creating a new HTML element and inserting it into the Document. It is at the point of insertion that HTML elements which load subresources begin fetching the subresource.

Running scripts

This parsing algorithm seems to translate HTML source into a DOM tree as efficiently as possible. That is, except for one wrinkle: scripts. When the tree builder encounters an end-tag token for a script, it must serially execute the script before parsing can continue (unless the associated script start-tag has the defer or async attribute).

There are two significant preconditions which must be fulfilled before a script can execute:

1. If the script is external its source must be fully downloaded.
   
2. For any script, all stylesheets in the document must be fully downloaded.
   

This means often the parser must idly wait while scripts and stylesheets are downloaded.

Why must parsing halt?

Well, a script may document.write something which affects further parsing or it may query something about the DOM which would yield incorrect results if parsing had continued (for instance the number of image elements in the DOM).

Why wait for stylesheets?

A script may expect to access the CSSOM directly or it may query an attribute of a DOM node which depends on the stylesheet (for example, how wide is a certain <table>).

Is it inefficient to block parsing?

Yes. Subresource download times often have a large constant factor limited by round trip time. This means it is faster to download two resources in parallel than to download the same two in serial. More obviously, the browser is also free to do CPU work while waiting on the network. For these reasons it is critical to efficient loading of a web page that subresource fetches are initiated as soon as possible. When parsing is blocked, the tree builder is not able to insert subsequent elements into the DOM, and thus subsequent subresource downloads are not initiated even if the HTML source which includes them is already available to the parser.

Mitigating blocking

As I've blogged previously, when the parser becomes blocked WebKit will run a lightweight parser known as the preload scanner. It mitigates the blocking problem by scanning ahead and fetching certain subresource that may be required. Other browsers employ similar techniques.

It is important to note that even with preload scanning, parsing is still blocked. Nodes cannot be added to the DOM tree. Although I haven't covered how a DOM tree becomes a render tree, layout or painting, it should be obvious that before a node is in the DOM tree it cannot be painted to the screen.

Finishing parsing

After the entire source has been parsed, first all deferred scripts will be executed (waiting for their source and all pending stylesheets to download). Their completion triggers the DOMContentLoaded event to be fired. Next, the parser will wait for any pending async scripts to finish loading and executing. Finally, once all subresources have finished downloading, the window's load event will be fired and parsing is complete.

Takeaway

With this understanding, it becomes clear how important it is to carefully consider where and how stylesheets and scripts are included in the document. Those decisions can have a significant impact on the efficiency of the page load.