CODEWITHSUNDEEP
javascriptgoogle-chrome-devtools
O. R. Mapper
O. R. Mapper

Reputation: 20710

How to interpret Chrome's JS profiling timeline?

I have minimized and anonymized the function names/calls in this question (and accordingly retouched the image). The actual names and callstack depth should be of no concern for answering this question.

I am trying to find a bottleneck in a web application by means of Google Chrome's timeline. However, I am not sure how to interpret the data displayed after recording a timeline.

For instance, I am using the following function:

function obj.a = function (x, y) {
    console.log('a(' + x + ', ' + y + ')');
    return x.getNested().b(y);
};

After profiling it, the flame chart and the event log make it seem as if console.log and b were invoked more than once by a. For instance, the event log looks like this:

event log

Other invocations of a appear to (randomly?) feature even more nested invocations of b and log.

The official documentation such as How to use the timeline tool only provides unhelpful statements such as

When the JS profiler is enabled, your flame chart shows every JavaScript function that was called.

So, how is the JS profiling information displayed om the Timeline panel supposed to be read and interpreted for finding out which function call requires how much time?

Upvotes: 2

Views: 708

Answers (2)

alph
alph

Reputation: 676

This is an artifact of any sampling profiler. The sampling profiler works in the following way, it takes program stack samples on a periodic basis known as sampling interval (in Chrome it is either 0.1ms or 1ms).

A main drawback of the sampling profiler is that it does not see what happens to the program between samples. E.g. it cannot detect all function entry and exit events. However it is good on providing aggregated statistical view on function execution times.

In your example it had likely exited and entered "a" function between taking samples with "b" and "log" being the top frames.

Upvotes: 2

Gideon Pyzer
Gideon Pyzer

Reputation: 23948

I have created an example where we have three functions that get executed, where the last one, c, calls the first one in a loop.

Example:

function a() {
    console.log("a");
}

function b() {
    console.log("b");
}

function c() {
    for (var i = 0; i < 10000; i++) {
        console.log("c");
        a();
    }
}

a();
b();
c();

The Event Log looks like this:

Events

You can see the three calls a, b, c at the top. The c can be expanded and you will see a load of a calls as you would expect. My understanding for the reason the c calls are repeated several times is due to CPU interrupts. The CPU is given a slice of time to run the JavaScript, it then gets interrupted, and does some other job and then comes back, so the Timeline shows the resuming of the function when the CPU context returns to the JavaScript.

Nested Events

The Call Tree tab should give you a nicer view of the execution times for each function, as per below:

Call Tree

Upvotes: 0

Related Questions