Javascript Tracing (about:tracing with console.time/timeEnd) not working?

[Nick Evans]

I cannot reproduce the method for Javascript tracing described in:

http://www.chromium.org/developers/how-tos/trace-event-profiling-tool/tracing-event-instrumentation.

But I was able to do this the last time I tried (about a year ago). Has something changed or am I forgetting something?

[Windows 7, 64 bit, Chrome 45.0.2454.85 m]

1. Open test.html in Chrome.
2. Open chrome://tracing/ in another tab.
3. Record > All Record Categories > Record.
4. Switch to the test.html tab for a few seconds.
5. Switch back to the tracing tab and 'stop'.

Result (tracing.png): 'Foo' should appear (but doesn't) under CrRendererMain > V8.Execute (because Foo sleeps for 1 s and V8.Execute runs for 1 s).

I would appreciate any help because I presume that the fault lies with me, not Chrome.

[Dan Sinclair]

The Foo items are showing up. They're in the second row under your renderer. The one titled 'Foo'.

Thanks,

dan

--
--
Chromium Discussion mailing list: chromium...@chromium.org
View archives, change email options, or unsubscribe:
http://groups.google.com/a/chromium.org/group/chromium-discuss

[Nick Evans]

Those 'Foo's are from the category blink.console, rather than v8. blink.console seems to list them alphabetically and individually (without a self time or ancestors/descendants). I'm not sure what the purpose of the blink.console category is, but the data isn't very useful for tracing JS performance.

When I last used chrome tracing (about a year ago), the console events were included in the V8 flame chart, e.g. http://www.html5rocks.com/en/tutorials/games/abouttracing/manualtags.png.

Do JS console events no longer appear in the V8 flame chart? Is this a bug or by design? Or am I doing something wrong?

[Dan Sinclair]

On Wed, Sep 2, 2015 at 10:56 AM Nick Evans <nick.ev...@gmail.com> wrote:

Those 'Foo's are from the category blink.console, rather than v8. blink.console seems to list them alphabetically and individually (without a self time or ancestors/descendants). I'm not sure what the purpose of the blink.console category is, but the data isn't very useful for tracing JS performance.

If you'd like to trace JS performance we are adding support for the v8 sampling profiler. The visualization isn't in the current released chrome, but can be used if you run the dev server for github.com/catapult-project/catapult and load your traces in there. This gives much better information on JS time.

 

When I last used chrome tracing (about a year ago), the console events were included in the V8 flame chart, e.g. http://www.html5rocks.com/en/tutorials/games/abouttracing/manualtags.png.

I don't think we ever logged these under v8. If memory serves, they used to be logged under webkit.console and we moved them to blink.console. It's possible we changed the type of event so they get their own slice instead of being placed under another slice. 

Is there something wrong with having them displayed as their own slice? Or does it make correlation more difficult? I'm not sure when/why the change was made, but it should be possible to track it down through the source control.

dan

[Nick Evans]

Thanks Dan.

I've googled around and found some screenshots:

* Console events in CrRendererMain and in the same flame chart as v8 events:
- May 2012 -- http://www.html5rocks.com/en/tutorials/games/abouttracing/#toc-addingtags

* Console events in CrRendererMain but in a separate flame chart from v8 events:
- August 2012 -- http://www.gamasutra.com/view/news/176420/Indepth_Using_Chrometracing_to_view_your_inline_profiling_data.php
- December 2012 -- https://www.youtube.com/watch?v=nxXkquTPng8&t=39m10s and https://www.youtube.com/watch?v=nxXkquTPng8&t=53m28s
- October 2013 -- http://stackoverflow.com/questions/19332422/profiling-webgl-with-chrome-tracing.

Someone else was recently confused by blink.console and the lack of a flame chart for their console events:
- May 2015 -- https://www.reddit.com/r/webdev/comments/36bthn/how_come_my_data_doesnt_show_up_in_chrometracing/

I guess separating the console events from v8 isn't a problem, but displaying the events in alphabetical order instead of a flame chart is quite annoying, e.g. here is 'one' calling 'two' calling 'three':


Shall I raise an issue on https://code.google.com/p/chromium/issues/list or is tracing a separate project?

Thanks again for your help.

[Dan Sinclair]

The events were never v8 events, the stacking in the first image doesn't mean they were in the v8 category. We stack things in slices based on the process, thread and timestamps.

It's strange they are stacking they way they do now, as far as I know it isn't sorted by name in the UI, but maybe that was added. I don't think they should be separate slices, but all in one slice, but would need to figure out if we changed to async events or something else for the console logging. You can file tracing bugs against github.com/catapult-project/catapult.

As a side note, devtools has a flamechart which is different from the timeline slices in tracing.

dan

[Nick Evans]

https://github.com/catapult-project/catapult/issues/1434