Google Chrome	71.0.3578.98 (Official Build) (64-bit)
Revision	15234034d19b85dcd9a03b164ae89d04145d8368-refs/branch-heads/3578@{#897}
OS	Linux


I am using console.time() / console.timeEnd() to collect performance data and am seeing a ~1 ms overhead (on a modern desktop) from calling timeEnd()

This overhead makes the time/timeEnd features unsuitable for collecting fine-grained performance data.



See the attached test case which demonstrates the issue.

What steps will reproduce the problem?
(1) Open the attached HTML file (verify.html)
(2) In the DevTools "performance" tab, record a timeline.
(3) Find the time/timeEnd records

-> The first tests: "top stacked" and "top seq" call time/timeEnd 10 times and take ~3ms on my desktop.

-> The second test:, "deep100 stacked" call time/timeEnd 10 times from a call stack that is 100 frames deep.  That takes ~12ms on my desktop.

-> Finally, there is a hand-rolled function that called window.performance.now 20 times. This takes 37us.

What is the expected result?

1) Calling console.time / console.timeEnd should be as fast as calling window.performance.now explicitly.
2) Calling console.timeEnd() from a frame deep in a call stack should be as fast as calling timeEnd() from a shallow frame.

What happens instead?

console.timeEnd() appears to have a large amount of overhead and its run-time is dependent on the depth of the call stack.


Additional Info:

Looking at InspectorInstrumentation::stopConsoleTimingImpl in third_party/WebKit/Source/WebCore/inspector/InspectorInstrumentation.cpp:

the method is collecting stack frame information so the InspectorConsoleAgent can get the 0th frame's source information to display in the console.


Possible solutions:
-> Don't create script call stacks on timeEnd() calls and remove the call stack information from the console logs.  Since time/timeEnd are performance features, a fast run-time is more important than the extra information.

OR

-> Only collect information for the 0th call stack frame, since that is all the is used by the InspectorConsoleAgent.  This would give timeEnd() consistent run-time characteristics.


 

Deleted: Verify.html 3.3 KB

Verify.html 3.3 KB View Download