"debug style" scopes for enabling timeline demarcation of timing measurements

[runspired]

High Level

• Uses performance.mark to capture timings when available (instead of performance.now).
• Uses performance.measure to push a measurement into the timeline when this API is available.
• Uses console.time and console.timeEnd with our existing now() to capture timings and push measurements into the timeline when mark and measure are not available.

Concerns

• Performance: using mark improves the speed of collecting timings
• Performance: adding measurements slows us down minimally so long as performance.measure is available, but these are off by default to be user enabled, and the active scopes can be controlled.
• Session: this changes slightly how data is stored on the session, but this a minimal compat function within HeimdallTree enables the different expectations to seamlessly interop (and has test coverage)

Discussion

The primary new addition is the PerformanceMeasure class.

This API is similar to the Performance interface https://developer.mozilla.org/en-US/docs/Web/API/Performance
however, it diverges in a couple of key scenarios detailed below:

1. To support enabling/disabling timeline measuring by "scope", it introduces a trace() method which enhances the mark functionality by expecting more information about the nature of the mark being requested.

2. To support measurements appearing in the timeline for Safari and Node, it additionally falls back to console.time(<label>) and console.timeEnd(<label>). Whereas performance.measure uses async marks and can be called after-the-fact to add the annotation to the timeline, the console variant is synchronous and must be called at the same point at which the mark is created. This is another motivation for the trace API having extend information about the nature of the mark requested.

3. Additionally, performance.measure expects to be given the names of two previously created marks; however, performance.mark intentionally supports calling mark with the same name repeatedly. This makes these two APIs at odds. Instead of using the name passed into heimdall.start(), we use the traceId we generate for that mark to ensure a unique mark name.

Usage

On your heimdall instance:

heimdall.enableTimelineScopes(<scopeMatchQuery>);

Calls to this method are "additive only" at the moment.

Miscellaneous Questions

• id is currently an index into the events array. traceId can replace id entirely either by Heimdall generating a similar monotonic ID or by having Heimdall's start|stop|resume methods utilize the traceId that calling _trace generates. Either scenario would improve our ability to segment the data, utilize a buffer approach, and stream it if desired.

Many thanks to @twokul for pairing with me on the PerformanceMeasure class.

[stefanpenner]

• needs tests
• how does this perform?

[runspired]

@stefanpenner

• RE (1) I can (and will) unit test the "off/on" logic but I'm pretty sure there is no way to integration test the rest of it, as it would require diffing a timeline screenshot

• RE (2) really bad when on, but it doesn't matter as you only activate it when needed. Turning this on is something you only do if you want to investigate some profiles and are looking for a quick way to narrow things down. Leaving the timeline API on all the time would be crazy.

Sidenote: React's similar implementation has an "on/off" via query param toggle which is kinda nice.

[stefanpenner]

but I'm pretty sure there is no way to integration test the rest of it, as it would require diffing a timeline screenshot

Spying on console.time and console.timeEnd and ensuring they are invoked correctly should do the trick re: acceptance level testing.

RE (2) really bad when on, but it doesn't matter as you only activate it when needed. Turning this on is something you only do if you want to investigate some profiles and are looking for a quick way to narrow things down. Leaving the timeline API on all the time would be crazy.

Its good that this doesn't cause issues when disabled. Although the fact that people enabling this to get further time information itself skews times is unfortunate.

It may be worth investing time in ensuring that overhead is a minimal as we can reasonably provide.

[runspired]

@stefanpenner here's an example of the perf hit:

I asked on twitter and @addyosmani suggested this: https://twitter.com/addyosmani/status/810942392249393152

https://developer.mozilla.org/en-US/docs/Web/API/Performance/measure

Which I suspect may help our trace-events integration anyway? cc @krisselden

[runspired]

Post refactor (compare to above screenshot):

[runspired]

A few comments:

• we may want to consider simply always marking with performance.mark instead of performance.now when in the browser, and only conditionally check whether to call `performance.measure. This diverges the APIs a tiny bit but would:

  • allow us to piggyback on call to mark (right now this requires two calls, but we could instead merge calls if side-by-side)
  • reduce the overhead of checking whether to call performance.mark (seems larger than the call, we can do this anyway)
  • marks have timing data we can retrieve later on export (via performance.entriesByType('mark'))

• We may additionally want to consider whether we provide a method to "flush the things that should be measured to the timeline". Right now this greedily calls performance.measure right after we place the second mark.

  • This is something that can be deferred so long as it happens before timeline recording is ended, which means we would have to trust the user to "call flush" before stopping the timeline.
  • May at least want to make this optional for power users who want more granular time data with lower overhead up front

[hjdivad]

we may want to consider simply always marking with performance.mark instead of performance.now when in the browser, and only conditionally check whether to call `performance.measure. This diverges the APIs a tiny bit but would:

Why does this diverge the API? performance.now vs performance.mark seems like an implementation detail; what's the effect on our public API?

[hjdivad]

@runspired @stefanpenner how often do you think this would work as a build time step?

Seems like it might be a 90% solution to be able to only do this against the static portion of a string, but that way we could enable context (nodes) at build-variable cost.

thoughts?

[runspired]

@stefanpenner this is ready for review, I'm not sure what's up with the appveyor build failing though, it's suggesting our babel setup isn't correct. Possibly trolled by semver drift?

EDIT I take back the drift hypothesis given Travis is green.

[stefanpenner]

this seems to be quite abit of code, we should be careful or separate builds for different use-cases (likely future effort).

[stefanpenner]

this is no longer needed, new v8 makes this the default for Object.create(null)

[runspired]

👍