4

Here is my javascript code, it is pretty simple: 

console.profile();
var count = 1000;
var fn1 = function () {
    for (var i = 0; i < count; i++) {
        console.log("THIS IS FN1");
    }
}

var fn2 = function () {
    for (var i = 0; i < count; i++) {
        console.log("THIS IS FN2");
    }
    fn1();
}

fn2();
console.profileEnd();

and this is my profile screenshot:

enter image description here

Why there are some gap in the image, just like my black rectangle marked?

What does this gap mean?

hh54188
  • 14,887
  • 32
  • 113
  • 184
  • 3
    What you are supposed to see is 1000 tiny `log` calls on the top of `fn2`. However, since `log` calls take almost no time and since profiling data are sampled you end up with some calls being merged into one block and others being missed. You can increase sampling interval by turning on **"High resolution CPU profiling"** in the DevTools settings. You should then get something like this: http://i.imgur.com/E67WWqX.png . However, it still doesn't explain why `f2` is splitted into couple of blocks even though is called only once. – Konrad Dzwinel Dec 17 '13 at 10:35

1 Answers1

11

You see this non-uniform sequence of gaps between log calls on top of fn2 and fn1 because the profiler is sampling and gives you only statistical information. It will stop JS thread and capture current call stack roughly once per 1ms (100us in high res mode) and width of each bar is proportional to the number of consecutive samples where we've seen the same call stack.

The split of fn2 is a bug. Since we stop JS thread in random state it is not always possible to iterate JS call stack because e.g. top frame may be half-constructed. We do our best to determine current state of the VM and crawl call stack but sometimes our heuristics fail in which case we may end up capturing incomplete stack like in your case.

Yury Semikhatsky
  • 2,144
  • 13
  • 12