Reading a performance trace

Where did the time go?

Asha is on the Leaf and Kettle page again, on her phone, on the bus. This week the shop added a small "Chat with us" button. It comes from a chat company. Its code loads from that company's server. Asha writes to the shop: "Your page got slower".

In The Performance panel you learned to record. So you record two things: the page loading, and one tap on Add to cart. The panel fills with rows of coloured bars. Each bar is something the browser did. Where do you even start?

Start with what Asha felt. Her first question is simple: why did it take so long to see anything? The course recorded the store in Chrome, on a phone-sized screen. The CPU is the chip that runs the code. The course made it 4 times slower, so a laptop behaves more like a phone. Here are two times from that recording:

1// The store's load. Times are in ms after the load started.2const lastFileArrived = 37.9;3const firstPaint = 405.8;4 5console.log(`Every file the page needs had arrived by ${lastFileArrived} ms.`);6console.log(`The first text or picture appeared at ${firstPaint} ms.`);7console.log(`That leaves ${(firstPaint - lastFileArrived).toFixed(1)} ms to explain.`);

• Line 1 is a comment. Times are in milliseconds (ms), thousandths of a second, counted from the start of the load.
• Line 2 is when the last file the page needs finished downloading. The page is its HTML plus four files. They are styles.css, app.js, the chat widget's widget.js, and the picture hero.svg.
• Line 3 is the first paint: the moment the first text or picture appeared on the screen. Its full name is First Contentful Paint, or FCP.
• Line 5 prints Every file the page needs had arrived by 37.9 ms.
• Line 6 prints The first text or picture appeared at 405.8 ms.
• Line 7 subtracts one from the other. It prints That leaves 367.9 ms to explain.

So the network wasn't the problem. Everything had arrived in under 40 ms. Then, for 367.9 ms, the screen showed no text and no pictures. Something kept the browser from drawing.

To find out what, you read the recording. A recording is called a trace. It's a long list of events. Each event is a thing the browser did, with when it started and how long it took. Here is the whole load in one picture. It shows three of the files and the first paint. It also shows the main thread, which does the page's work.

Even before you know every part of it, you can see where to look. The files arrive early, and then everything waits for the main thread.

That's how you read a trace. Each section of this lesson adds one tool for walking back.

1. The tracks show what each part of the browser was doing at that moment.
2. The flame chart shows what ran inside one task: which function called which.
3. The tables add the time up, so you can see which function cost the most.
4. The arrows lead from an event back to the code that set it off, even a second earlier.
5. The 1st / 3rd party split tells you whose code it was: the shop's, or the chat company's.

Some of what you'll read comes from JavaScript samples. To take them, Chrome checks over and over which function is running, and writes it down. The JavaScript lesson CPU profiling in depth shows how those samples are taken. This lesson reads them inside a page's trace.

The Network, Frames, Main, and Interactions tracks

When a recording opens, the panel draws it as rows stacked one above the other. Each row is a track: what one part of the browser did, and when. Every track shares the same clock.

The Main track: one task at a time

Start with the Main track. It shows the main thread, the head cook from Processes and threads. It reads the HTML, works out styles and layout, paints, and runs your JavaScript. It does one job at a time. Each job, from start to finish, is a task, drawn as one bar.

A long task is a task that runs for more than 50 ms. While it runs, the main thread can't start anything else. A tap has to wait, and so does the next update to the screen. DevTools marks each long task with a red triangle. It also shades the part over 50 ms in red. The store's load had 4 long tasks.

1// The load's long tasks: when each started, and how long it ran, in ms.2const longTasks = [3  { start: 34.9, ms: 245.9, inside: "the picture, hero.svg" },4  { start: 289, ms: 99, inside: "the page's layout and paint" },5  { start: 389, ms: 144.2, inside: "the store's start-up code" },6  { start: 548.1, ms: 108.2, inside: "the chat widget's script" },7];8 9for (const task of longTasks) console.log(`At ${task.start} ms: ${task.ms} ms on ${task.inside}.`);

• Lines 3 to 6 are the four long tasks. Each says when it started, how long it ran, and what the trace says was inside.
• Line 9 prints one sentence per task. The first two are At 34.9 ms: 245.9 ms on the picture, hero.svg. and At 289 ms: 99 ms on the page's layout and paint.
• The last two are At 389 ms: 144.2 ms on the store's start-up code. and At 548.1 ms: 108.2 ms on the chat widget's script.

Three are easy to name.

• The second is the browser working out where everything goes on the page, then painting it.
• The third is the store's own start-up code in app.js. It runs on DOMContentLoaded, an event the browser fires once it has read all of the HTML.
• The fourth is the chat widget's script running.

The first one is the surprise. It's a picture. Why would a picture keep the main thread busy for a quarter of a second?

Most pictures don't. But hero.svg is an SVG: a picture written as text, as a list of shapes. Chrome draws it by building a small document of its own, much like a web page. Chromium is the project Chrome is built from. Its code says: "Internally, SVGImage creates a IsolatedSVGDocumentHost and reuses the existing paint code in Blink to draw the image". Blink is the part of Chrome that turns pages into pixels.

The store's hero.svg is 580 KB of text, with 14,000 dots in it. Reading it took 162.7 ms. Next came a style recalculation of 14,029 elements, which took 53.5 ms. Then layout took 24.6 ms. All of it ran on the main thread, in one long task. So an SVG doesn't only cost download time. Every shape in it is work for the head cook.

Now the red parts. Here is how far each long task ran past 50 ms:

1// How long each long task ran, in ms. DevTools shades the part over 50 ms red.2const longTasks = [245.9, 99, 144.2, 108.2];3const redParts = longTasks.map((ms) => ms - 50);4 5console.log(`The red parts: ${redParts.map((ms) => ms.toFixed(1)).join(", ")} ms.`);6console.log(`In all, ${redParts.reduce((sum, ms) => sum + ms, 0).toFixed(1)} ms over the limit.`);

• Line 2 holds how long each long task ran.
• Line 3 takes 50 ms off each one. What's left is the part DevTools shades red.
• Line 5 prints The red parts: 195.9, 49.0, 94.2, 58.2 ms.
• Line 6 adds them up. It prints In all, 397.3 ms over the limit.

Nearly 400 ms of red, in a load that took well under a second. A long task with a big red part is the first place to look. Nothing else can happen on the main thread while it runs.

The Network track: arrived isn't the same as used

The Network track draws each request as a bar. Chrome's DevTools docs split each bar into four parts, from left to right.

• A thin line on the left: everything before the request is sent, such as opening a connection.
• A light part: sending the request and waiting for the server to answer.
• A dark part: downloading the file.
• A thin line on the right. In the docs' words, it's "the time spent waiting for the main thread".

That last line answers part of Asha's question. The files arrived early, then waited for the head cook to be free.

1// When each file's last byte arrived, and when the main thread got to it, in ms.2const files = {3  "app.js": { arrived: 33, handled: 284.9 },4  "widget.js": { arrived: 37.9, handled: 287.4 },5  "hero.svg": { arrived: 33.5, handled: 279.7 },6};7 8for (const [file, { arrived, handled }] of Object.entries(files)) {9  console.log(`${file} arrived at ${arrived} ms, then waited ${(handled - arrived).toFixed(1)} ms.`);10}

• Lines 3 to 5 hold three files. For each, they say when its last byte arrived, and when the main thread got to it.
• Line 9 subtracts the two times for each file, and prints a sentence.
• It prints app.js arrived at 33 ms, then waited 251.9 ms. and widget.js arrived at 37.9 ms, then waited 249.5 ms.
• Then it prints hero.svg arrived at 33.5 ms, then waited 246.2 ms.

All three waited about a quarter of a second. Now look at when the waits end. Each one ends within 7 ms of 280.8 ms, the moment the hero.svg task finished. The head cook was reading the picture, and everything else queued behind it.

Why it matters: a long thin line on the right of a Network bar isn't a slow server. A faster server won't shorten it. Freeing the main thread will.

The Frames and Interactions tracks: what Asha saw and did

The Frames track shows each frame: one picture of the page on the screen. The docs name four kinds:

• An idle frame, in white: nothing changed.
• A frame, in green: drawn in time.
• A partially presented frame, in yellow: Chrome got only some of the changes on screen in time.
• A dropped frame, in red: Chrome couldn't draw it in time.

Chrome drew 4 frames in the whole load recording. Tick Screenshots before you record, and you can see each one.

The Interactions track shows each tap, click or key press. An interaction has three parts:

• Input delay: from the tap until the page's code starts to run.
• Processing: the page's event handlers running.
• Presentation delay: from the end of the handlers until the next frame is on the screen.

The track draws processing as a bar. The two delays are thin lines on either side. The docs call those lines "whiskers". An interaction over 200 milliseconds gets a red triangle in its corner. 200 ms is also the limit for a good Interaction to Next Paint (INP). INP is the Core Web Vital for how fast a page answers. Here is Asha's tap:

1// The tap on Add to cart, in three parts, in ms.2const click = { inputDelay: 2.5, processing: 157.9, presentationDelay: 137.7 };3const total = click.inputDelay + click.processing + click.presentationDelay;4 5console.log(`The click took ${total.toFixed(1)} ms, from the tap to the next frame.`);6console.log(`Its event handlers ran for ${click.processing} ms.`);7console.log(`The last ${click.presentationDelay} ms came after they finished.`);

• Line 2 holds the three parts of the tap on Add to cart, from the click recording.
• Line 3 adds them up.
• Line 5 prints The click took 298.1 ms, from the tap to the next frame.
• Line 6 prints Its event handlers ran for 157.9 ms.
• Line 7 prints The last 137.7 ms came after they finished.

The tap is well over 200 ms. So it gets a red triangle. And nearly half of it came after the handlers had finished. That was the browser getting the next frame onto the screen. So a faster handler would help, but only with part of the wait.

Try both recordings. In the load, click a file's bar. You'll see when it arrived and when the main thread got to it. Or click a long task to see what was inside. Then switch to the click, and select the interaction.

Flame charts, self time, and total time

The Interactions track told you the tap's handlers ran for 157.9 ms. But which code? Zoom into the Main track at that moment, and the task opens up. Under it, you see what ran inside. Under each of those, you see what they ran. This view is called a flame chart.

The docs say it in three short sentences: "The x-axis represents the recording over time. The y-axis represents the call stack. The events on top cause the events below". One at a time:

• Left to right is time, as on every other track.
• Top to bottom is the call stack: the chain of functions calling each other. A function sits right under the one that called it.
• The top row is the root activity: the thing that made the browser start this work. When you click a page, the docs say, the root activity is an Event.

Here is the tap's flame chart, built from the click recording's JavaScript samples:

Read it from the top. The click event ran the store's click handler. The handler called two functions. buildIndex sorts 200,000 old order prices, and showTeas puts the teas on the page. buildIndex called one more. It's the small function it gives sort to compare two prices, called the comparator.

Two times for every bar

Every bar in a flame chart has two times. The docs define them.

• Total time is "the time spent in that activity or any of its children". It's how wide the bar is.
• Self time is "the time directly spent in that activity". It's the part of the bar with nothing under it.

The "children" are the functions it called, also called its callees. Here are the two times for buildIndex:

1// buildIndex, from the click's flame chart, in ms.2const buildIndex = { total: 134.7, self: 118.7 };3 4console.log(`buildIndex ran for ${buildIndex.total} ms in all.`);5console.log(`${buildIndex.self} ms of that was its own code.`);6console.log(`${(buildIndex.total - buildIndex.self).toFixed(1)} ms was in functions it called.`);

• Line 2 holds buildIndex's two times from the click.
• Line 4 prints buildIndex ran for 134.7 ms in all.
• Line 5 prints 118.7 ms of that was its own code.
• Line 6 takes the self time away from the total. It prints 16.0 ms was in functions it called.

That 16.0 ms is the comparator. Its bar is 16 ms wide. It calls nothing, so its self time and its total time are the same.

But most of buildIndex's time is its own. Why? It makes 200,000 numbers and sorts them. The sorting runs inside the JavaScript engine: the part of Chrome that runs JavaScript. In these samples, it has no bar of its own. So it counts as buildIndex's self time.

Now the click handler, one row down from the top:

1// The store's click handler, from the click's flame chart, in ms.2const clickHandler = { total: 150.7, self: 0.1 };3 4console.log(`The click handler ran for ${clickHandler.total} ms in all.`);5console.log(`Only ${clickHandler.self} ms of that was its own code.`);

• Line 2 holds the click handler's two times.
• Line 4 prints The click handler ran for 150.7 ms in all.
• Line 5 prints Only 0.1 ms of that was its own code.

The handler's bar is as wide as the click event above it. Yet almost none of it is its own. It started the work and waited while its callees did it. There's almost nothing to fix in the handler itself.

Why it matters: read a flame chart from the top down. Find a wide bar, then follow it down to the bars with the most self time. That's where the work really happened. In the tap, it's buildIndex. In the first playground, switch to the click and select each bar to see both of its times.

Bottom-up, call tree, and event log

A flame chart is good for one task. But a whole load has many tasks. The same function can run in several of them. To add it all up, the panel has three tables under the tracks. Each is in its own tab: Bottom-up, Call tree and Event log. Each one only shows the part of the recording you've selected.

Read this table across: each row is one tab, the question it answers, and how it lays out the time.

Bottom-up and the Call tree can put different functions first. That isn't a mistake. They look at different times. Here are two rows from the load: the store's start-up code and the function it calls.

1// Two rows from the load's samples, in ms.2const rows = [3  { name: "the DOMContentLoaded listener", total: 136.2, self: 0.2 },4  { name: "buildIndex", total: 134.1, self: 113.2 },5];6 7const mostTotal = [...rows].sort((a, b) => b.total - a.total)[0];8const mostSelf = [...rows].sort((a, b) => b.self - a.self)[0];9console.log(`Most total time: ${mostTotal.name}.`);10console.log(`Most self time: ${mostSelf.name}.`);

• Lines 3 and 4 hold the two rows. One is the DOMContentLoaded listener. The other is buildIndex, which it calls.
• Line 7 sorts the rows by total time and keeps the first. Line 8 does the same by self time.
• Line 9 prints Most total time: the DOMContentLoaded listener.
• Line 10 prints Most self time: buildIndex.

The listener started the work, so its total time is the biggest. The Call tree starts from what began the work. So the listener is near its top, with buildIndex nested under it. buildIndex did the work, so its self time is the biggest. That puts it at the top of Bottom-up.

Why it matters: ask "what started this?" and open the Call tree. Ask "where did the time really go?" and open Bottom-up. Ask "what happened just before?" and open the Event log.

Try all three on the whole load. In Bottom-up, see how high up the chat widget's code comes. Then open the Call tree and find widget.js. Its rows have big total times but almost no self time. The work happens further down, in what they call.

Following a task from cause to effect

Asha has one more complaint. A second after the page appears, the tea list jumps down. This is called a layout shift. It's something visible moving from one frame to the next, without the user asking for it.

The trace shows the shift at 1539.3 ms. But the shift is only the effect. The detective's question is: what caused it? For that, the Main track can draw arrows.

An event that causes another one later is called an initiator. The Main track "can show arrows that connect the following initiators and the events they caused". Here are three of the pairs on the docs' list.

• Install Timer to Timer Fired: code calls setTimeout, and later the timer's function runs.
• Request Idle Callback to Fire Idle Callback: code asks to run something when the browser is free. Later, it runs.
• A change to styles or layout, to the Recalculate styles or Layout that it caused.

To see an arrow, select either end of it in the flame chart. The Summary tab then links to the other end: "Initiator for" on the cause, and "Initiated by" on the effect. Click the link to jump there. The Network track does the same for files. Click a request, and it draws an arrow from its initiator to the request.

Here is the store's promotion banner, from the load recording.

1// Four events from the load, in the order they happened. Times are in ms.2const chain = [3  { at: 531.8, event: "Install Timer", detail: "app.js line 1818, for 1000 ms" },4  { at: 1532.9, event: "Timer Fired", detail: "its callback ran 0.7 ms" },5  { at: 1534.9, event: "Layout", detail: "3.4 ms" },6  { at: 1539.3, event: "Layout Shift", detail: "score 0.1369, content moved 120 px down" },7];8 9for (const step of chain) console.log(`${step.at} ms: ${step.event}, ${step.detail}`);10console.log(`fired ${(chain[1].at - chain[0].at).toFixed(1)} ms after it was installed`);

• Lines 3 to 6 are four events from the load, in the order they happened.
• Line 9 prints each one. The first two are 531.8 ms: Install Timer, app.js line 1818, for 1000 ms and 1532.9 ms: Timer Fired, its callback ran 0.7 ms.
• The next two are 1534.9 ms: Layout, 3.4 ms and 1539.3 ms: Layout Shift, score 0.1369, content moved 120 px down.
• Line 10 takes the install time from the fired time, and prints fired 1001.1 ms after it was installed.

Now walk it backwards, the way the detective would:

1. At 1539.3 ms, the layout shift moved the content 120 px down.
2. Just before it, at 1534.9 ms, a 3.4 ms layout worked out where everything should go.
3. Just before that, at 1532.9 ms, a timer fired. Its function ran for only 0.7 ms. It put a promotion banner into the page, above the teas.
4. The arrow from Timer Fired leads back a whole second, to 531.8 ms. That's app.js line 1818, inside the store's start-up code, calling setTimeout with 1000 ms.

Without the arrow, you'd see a 0.7 ms function and a 3.4 ms layout, far from anything slow. Neither looks guilty. The arrow joins them to the line that set it all up.

Why it matters: that one shift scored 0.1369. web.dev asks sites to keep Cumulative Layout Shift (CLS) at 0.1 or less. CLS is the Core Web Vital for things jumping around. This single shift was enough to miss it. The fix belongs at line 1818: keep space for the banner before it arrives.

Third-party and first-party breakdowns

Back to the chat widget. Code that you write and serve yourself is first-party. Code from another company, loaded from its server, is third-party. Chat widgets, ads, analytics and video players are all third-party. It's like a guest cook in your kitchen. The dish is theirs, but they use your stove. Your orders wait while they cook.

The panel has two tools for telling them apart.

• Dim 3rd parties is a checkbox in the action bar at the top. Tick it, and the panel "grays out third-party-related events from the performance trace and leaves only the first-party highlighted".
• The 1st / 3rd party table is in the Summary tab. Select a stretch of the recording, with no single event selected. The table lists each company with its transfer size, the bytes it downloaded, and its main-thread time.

The course split the load's JavaScript time the same way, by where the code came from. In the recording, the store was served from 127.0.0.1 and the widget from localhost: two different origins. An origin is the scheme, host and port of an address.

1// The load's JavaScript time on the main thread, by where the code came from, in ms.2const javascriptMs = { "The store, from 127.0.0.1": 137.9, "The chat widget, from localhost": 107.6 };3const total = Object.values(javascriptMs).reduce((sum, ms) => sum + ms, 0);4 5for (const [who, ms] of Object.entries(javascriptMs)) {6  console.log(`${who}: ${ms} ms, ${Math.round((ms / total) * 100)}% of all the JavaScript.`);7}

• Line 2 holds the JavaScript time each origin spent on the main thread, from the samples.
• Line 3 adds the two together.
• Line 6 prints each one's time, and its share of the whole.
• It prints The store, from 127.0.0.1: 137.9 ms, 56% of all the JavaScript.
• Then it prints The chat widget, from localhost: 107.6 ms, 44% of all the JavaScript.

The chat widget is one small button. Yet it ran more than three-quarters as much JavaScript as the whole store. And it ran as one long task, of 108.2 ms.

The widget loads with async. That lets the browser keep reading the HTML while the script downloads. But async only changes when a script runs, not how long. Once it runs, the main thread is busy with it until it finishes.

Why it matters: before you add a third-party script, check its cost in the 1st / 3rd party table. If it's big, ask whether it can load later, for example when someone first opens the chat.

Which view answers it?

Each question below is one you might ask about a trace. Sort it by the table that answers it. Ask yourself: is it about where time went directly, about what started the work, or about order?

Common mix-ups

• "Total time is what a function cost by itself." No. Total time includes everything it called. In the tap, buildIndex ran 134.7 ms in all, and 118.7 ms of that was its own.
• "A long Network bar means a slow server." No. The thin line on the right is time spent waiting for the main thread. app.js arrived at 33 ms, but its bar ran on to 284.9 ms.
• "Pictures only cost download time." No. Reading hero.svg took 162.7 ms of the main thread, and its style and layout came after that.
• "An async third-party script can't slow the page down." No. async changes when a script runs, not how long. The widget ran as a 108.2 ms long task.
• "The top of a flame chart is the slowest part." No. The top is what started the work. Look lower down, at the bars with the most self time.
• "An interaction's cost is all in its handler." No. The tap took 298.1 ms, and 137.7 ms of that came after the handlers had finished.
• "The cause of a problem sits right next to it in the trace." No. The timer that moved the content was set a whole second earlier, at 531.8 ms.

Practice exercises

Try each one before you open the hints.

// Four events from the load, in the order they happened. Times are in ms.
const chain = [
  { at: 531.8, event: "Install Timer", detail: "app.js line 1818, for 1000 ms" },
  { at: 1532.9, event: "Timer Fired", detail: "its callback ran 0.7 ms" },
  { at: 1534.9, event: "Layout", detail: "3.4 ms" },
  { at: 1539.3, event: "Layout Shift", detail: "score 0.1369, content moved 120 px down" },
];

for (const step of chain) console.log(`${step.at} ms: ${step.event}, ${step.detail}`);
console.log(`shifted ${(chain[3].at - chain[1].at).toFixed(1)} ms after it fired`);

// The load's JavaScript time on the main thread, by where the code came from, in ms.
const javascriptMs = { "The store, from 127.0.0.1": 137.9, "The chat widget, from localhost": 107.6 };
const total = Object.values(javascriptMs).reduce((sum, ms) => sum + ms, 0);

for (const [who, ms] of Object.entries(javascriptMs)) {
  console.log(`${who}: ${ms} ms, ${((ms / total) * 100).toFixed(1)}% of all the JavaScript.`);
}

Check your understanding

For each question, ask which track or table shows it, and whether it's about self time, total time, or order.

Key takeaways

• Start from the moment that hurt, such as the first paint, a slow tap or a jump, and walk backwards.
• Every track shares one clock. Read straight down to see what happened at the same moment.
• A long task keeps the main thread busy for more than 50 ms. Nothing else runs on it until the task ends.
• The thin line on the right of a Network bar is waiting for the main thread, not for the server.
• In a flame chart, a function sits under the one that called it. Total time is the bar's width. Self time is the part with nothing under it.
• Bottom-up finds where time was spent directly. The Call tree finds what started the work. The Event log keeps the order.
• Initiator arrows lead from an effect back to its cause, even a second earlier.
• Dim 3rd parties and the 1st / 3rd party table split the time between your code and other companies'.

Sources

The facts on this page come from these docs, specs and source files:

• Performance features reference, Kayce Basques and Sofia Emelianova, Chrome DevTools.
• Event loop processing model, HTML Standard, WHATWG.
• svg_image.h, Chromium source.
• Interaction to Next Paint (INP), web.dev.
• TraceEvents.ts, devtools-frontend source.
• Cumulative Layout Shift (CLS), web.dev.
• The script element: async, HTML Standard, WHATWG.

Coming next: Performance insights. The panel can read a trace for you and point at likely causes. You'll check each one with the tools from this lesson.