Sampling dict seems to falsely indicate an empty stack

[JonasBa]

Hey everyone, really excited to see this spec move forward, I think the potential for further improving the user experience with this is big and I'm looking forward to seeing the potential it unlocks and thank you for putting work into this!

I have been implementing support for the trace format in our flamegraph visualizing tool at Specto and have been comparing the output with the built-in Chrome profiler when I noticed that the sampling seems to produce holes, or at least indicate that the stack was empty at interval when it in fact wasn't.

I'm attaching a visual comparison between a trace collected with the self profiling spec and display in our dashboard and a concurrent trace collected via chrome devtools.

Specto (traced with JS Self Profiling at 2ms sampling rate):

Chrome (traced via devtools profiler)

If I investigate the samples array and track down the Flamegraph.init call which should occur twice in the lifetime of the trace (confirmed by the chrome trace and by manually tracking down code execution), it does indeed look like the samples indicate that the stack had been empty at certain sampling intervals (index 516, 517, 524... are not associated to any stack)

508: {stackId: 116, timestamp: 30355.960000008345}
509: {stackId: 116, timestamp: 30367.539999991655}
510: {stackId: 116, timestamp: 30378.125}
511: {stackId: 116, timestamp: 30388.75}
512: {stackId: 116, timestamp: 30399.335000008345}
513: {stackId: 116, timestamp: 30410.75}
514: {stackId: 116, timestamp: 30420.875}
515: {stackId: 116, timestamp: 30430.960000008345}
516: {timestamp: 30441.044999986887}
517: {timestamp: 30451.125}
518: {stackId: 116, timestamp: 30462.914999991655}
519: {stackId: 116, timestamp: 30473.789999991655}
520: {stackId: 116, timestamp: 30484.164999991655}
521: {stackId: 116, timestamp: 30494.210000008345}
522: {stackId: 116, timestamp: 30504.75}
523: {stackId: 116, timestamp: 30516.289999991655}
524: {timestamp: 30526.5}
525: {stackId: 116, timestamp: 30537.419999986887}
526: {timestamp: 30547.585000008345}
527: {stackId: 116, timestamp: 30557.625}
528: {timestamp: 30569.085000008345}
529: {timestamp: 30580.794999986887}
530: {stackId: 116, timestamp: 30591.625}
531: {stackId: 116, timestamp: 30602.5}
532: {timestamp: 30612.710000008345}
533: {timestamp: 30623.960000008345}
534: {stackId: 116, timestamp: 30634.164999991655}
535: {stackId: 116, timestamp: 30645.5}
536: {stackId: 116, timestamp: 30655.664999991655}
537: {stackId: 116, timestamp: 30666.039999991655}
538: {stackId: 116, timestamp: 30677.414999991655}

So my question here is:

1. Is this expected behaviour? The spec states that the stackId is optional, but it does not say if the absence of it should be interpreted as an empty stack?
2. If this is expected behaviour, how should this case be reconciled?

[acomminos]

Interesting, I'd guess this is a bug in the Chromium implementation's stack filtration. Definitely not expected behaviour.

Do you mind filing a Chromium bug with details about what platform and Chrome version that you're on? Thanks!

[JonasBa]

@acomminos Thanks, I just submitted the bug - https://bugs.chromium.org/p/chromium/issues/detail?id=1263007

@acomminos I also noticed that Chromium seems to set the lowest sampling interval to 10ms, is there any privacy or security reasoning behind that?

[nicjansma]

FWIW looks like it's multiples of 16ms for Windows and 10ms for other platforms

[magenish]

Also noticed the same issue, ive uploaded an example code here:https://github.com/magenish/Profiler-fragmentation

[JonasBa]

From the discussion in https://bugs.chromium.org/p/chromium/issues/detail?id=1263007, it seems that this could be a valid case where a non JS related task is running (like GC). The code in my example was in fact triggering a lot of GC (resizing array) which I suspect showed up as empty.