perf_hooks: emit user timing marks, measures and timerify to trace events #18789

jasnell · 2018-02-14T23:08:06Z

Emit user timing marks/measures and performance.timerify() measures to trace events.

/cc @nodejs/diagnostics @mcollina

Checklist

make -j4 test (UNIX), or vcbuild test (Windows) passes
tests and/or benchmarks are included
documentation is changed or added
commit message follows commit guidelines

Affected core subsystem(s)

perf_hooks, trace_events

AndreasMadsen · 2018-02-15T11:48:49Z

Didn’t review closely but tests are missing.

ofrobots · 2018-02-15T15:47:08Z

src/node_perf.cc

-  // TODO(jasnell): Once Tracing API is fully implemented, this should
-  // record a trace event also.
+  TRACE_EVENT_COPY_MARK_WITH_TIMESTAMP(
+      "node.perf,node.perf.usertiming", *name, now / 1e3);


IIRC, this is doing a floating point divide which is more expensive than an integer divide. 1000 would be an integral constant.

ah yeah, good point :-)

Confirmed. Floating point divide + 2 conversions between integer and floating point.

#include <stdint.h> uint64_t foo(uint64_t nanos) { return nanos / 1e3; } // clang -O3 -mllvm --x86-asm-syntax=intel -S foo.c

movq xmm0, rdi punpckldq xmm0, xmmword ptr [rip + LCPI0_0] ## xmm0 = xmm0[0],mem[0],xmm0[1],mem[1] subpd xmm0, xmmword ptr [rip + LCPI0_1] haddpd xmm0, xmm0 divsd xmm0, qword ptr [rip + LCPI0_2] movsd xmm1, qword ptr [rip + LCPI0_3] ## xmm1 = mem[0],zero movapd xmm2, xmm0 subsd xmm2, xmm1 cvttsd2si rax, xmm2 movabs rcx, -9223372036854775808 xor rcx, rax cvttsd2si rax, xmm0 ucomisd xmm0, xmm1 cmovae rax, rcx pop rbp ret

jasnell · 2018-02-15T19:24:02Z

@ofrobots ... nit fixed!
@AndreasMadsen ... test added.

ofrobots · 2018-02-16T00:20:26Z

src/node_perf.cc

                       env->performance_entry_callback(),
-                       1, &object);
+                       1, &object, {0, 0});


Question: what would the the correct context here? To me it seems that an AsyncResource or async_context be created when the observer is constructed, and that should be used on the callback. Do you agree?

Aside: Do our compilers support async_context{0,0} syntax yet?

Still thinking about that. PerformanceObserver currently is not an AsyncResource and only actually exists on the JS side. Making it an AsyncResource would be a minor divergence from the spec but is certainly not out of the question.

And I don't know about the compilers question.

If you don't want to inherit from AsyncResource, you can attache an async_context to the PerformanceObserver instances for the same effect.

I'm okay if you want to do this in a follow-on, as the issue existed before this PR, and is orthogonal.

Added example to #18810 in case it is useful. If the CI passes there, then that would answer the compiler question :).

jasnell · 2018-02-16T20:14:16Z

@ofrobots ... just went ahead and made PerformanceObserver an AsyncResource.

jasnell · 2018-02-16T20:26:00Z

CI: https://ci.nodejs.org/job/node-test-pull-request/13220/

jasnell · 2018-02-17T00:11:23Z

New CI: https://ci.nodejs.org/job/node-test-pull-request/13230/

jasnell · 2018-02-17T01:48:29Z

CI is looking good with one unrelated failure.

AndreasMadsen · 2018-02-17T13:15:30Z

src/tracing/trace_event.h

-#define INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP(            \
-    phase, category_group, name, id, thread_id, timestamp, flags, ...) \
-  UNIMPLEMENTED()
+#define INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP(                  \


Is a sync with upstream?

In sync with upstream? Nope, not yet. But that reminds me...

@ofrobots ... ^^ To implement this I needed this macro implemented also.

@jasnell created https://chromium-review.googlesource.com/c/v8/v8/+/924507 that adds the same macro upstream.

Note that for the trace-event macros, a sync with upstream is no longer a necessity. Our copy of trace_event.h is derived from upstream, but has a slightly different implementation. It is okay for them to pick up features at a different pace. Please do continue to ping if we add more macros locally. There is no need to block on upstream.

mcollina

LGTM with a nit

mcollina · 2018-02-19T07:43:17Z

doc/api/tracing.md


 The set of categories for which traces are recorded can be specified using the
-`--trace-event-categories` flag followed by a list of comma separated category names.
+`--trace-event-categories` flag followed by a list of comma separated category


The flag should be named --trace-events-categories for consistency.

This flag already exists and is not introduced by this PR

Adds the `node.perf.usertiming` trace events category for recording usertiming marks and measures (e.g. `perf_hooks.performance.mark()`) in the trace events timeline. Adds the `node.perf.function` trace events category for recording `perf_hooks.performance.timerify()` durations in the trace events timeline.

PR-URL: #18789 Reviewed-By: Ali Ijaz Sheikh <ofrobots@google.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com>

Adds the `node.perf.usertiming` trace events category for recording usertiming marks and measures (e.g. `perf_hooks.performance.mark()`) in the trace events timeline. Adds the `node.perf.function` trace events category for recording `perf_hooks.performance.timerify()` durations in the trace events timeline. PR-URL: #18789 Reviewed-By: Ali Ijaz Sheikh <ofrobots@google.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com>

PR-URL: #18789 Reviewed-By: Ali Ijaz Sheikh <ofrobots@google.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com>

jasnell · 2018-02-26T22:59:24Z

Landed in aca8e76, 9e509b6, and 009e418

MylesBorins · 2018-03-06T21:35:49Z

Should this be backported to v9.x-staging? If yes please follow the guide and raise a backport PR, if not let me know or add the dont-land-on label.

targos · 2018-04-02T12:36:44Z

This depends on #17640 which can't go in v9.x.

PR-URL: nodejs#18789 Reviewed-By: Ali Ijaz Sheikh <ofrobots@google.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com>

Adds the `node.perf.usertiming` trace events category for recording usertiming marks and measures (e.g. `perf_hooks.performance.mark()`) in the trace events timeline. Adds the `node.perf.function` trace events category for recording `perf_hooks.performance.timerify()` durations in the trace events timeline. PR-URL: nodejs#18789 Reviewed-By: Ali Ijaz Sheikh <ofrobots@google.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com>

PR-URL: nodejs#18789 Reviewed-By: Ali Ijaz Sheikh <ofrobots@google.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com>

This reverts commit 009e418. AFAIU the discussion at [1], PerformanceObserver had been made to inherit from AsyncResource more or less as a band-aid in lack of a better async_context candidate to invoke it in. In order to enable access to AsyncLocalStores from PerformanceObservers invoked synchronously through e.g. measure() or mark(), the current async_context, if any, should be retained. Note that this is a breaking change, but - as has been commented at [1], PerformanceObserver being derived from AsyncResource is a "minor divergence from the spec" anyway, - to my knowledge this is an internal implementation detail which has never been documented and - I can't think of a good reason why existing PerformanceObserver implementations would possibly rely on it. OTOH, it's probably worthwhile to not potentially invoke before() and after() async_hooks for each and every PerformanceObserver notification. [1] nodejs#18789 Co-Authored-By: ZauberNerd <zaubernerd@zaubernerd.de> PR-URL: nodejs#36343 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Rich Trott <rtrott@gmail.com>

This reverts commit 009e418. AFAIU the discussion at [1], PerformanceObserver had been made to inherit from AsyncResource more or less as a band-aid in lack of a better async_context candidate to invoke it in. In order to enable access to AsyncLocalStores from PerformanceObservers invoked synchronously through e.g. measure() or mark(), the current async_context, if any, should be retained. Note that this is a breaking change, but - as has been commented at [1], PerformanceObserver being derived from AsyncResource is a "minor divergence from the spec" anyway, - to my knowledge this is an internal implementation detail which has never been documented and - I can't think of a good reason why existing PerformanceObserver implementations would possibly rely on it. OTOH, it's probably worthwhile to not potentially invoke before() and after() async_hooks for each and every PerformanceObserver notification. [1] #18789 Co-Authored-By: ZauberNerd <zaubernerd@zaubernerd.de> PR-URL: #36343 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Rich Trott <rtrott@gmail.com>

jasnell added trace_events Issues and PRs related to V8, Node.js core, and userspace code trace events. perf_hooks Issues and PRs related to the implementation of the Performance Timing API. labels Feb 14, 2018

nodejs-github-bot added the c++ Issues and PRs that require attention from people who are familiar with C++. label Feb 14, 2018

ofrobots reviewed Feb 15, 2018

View reviewed changes

ofrobots reviewed Feb 16, 2018

View reviewed changes

ofrobots approved these changes Feb 16, 2018

View reviewed changes

jasnell force-pushed the perf_trace_event branch from 564a74f to c6ecad5 Compare February 16, 2018 20:13

jasnell force-pushed the perf_trace_event branch from c6ecad5 to 4108481 Compare February 16, 2018 20:23

jasnell force-pushed the perf_trace_event branch from 4108481 to ac17e74 Compare February 17, 2018 00:10

BridgeAR added the author ready PRs that have at least one approval, no pending requests for changes, and a CI started. label Feb 17, 2018

AndreasMadsen reviewed Feb 17, 2018

View reviewed changes

mcollina approved these changes Feb 19, 2018

View reviewed changes

danbev mentioned this pull request Feb 21, 2018

src: fix deprecation warning in node_perf.cc #18877

Closed

2 tasks

perf_hooks: eliminate deprecation warning

47a1898

jasnell force-pushed the perf_trace_event branch from ac17e74 to f67e78d Compare February 26, 2018 19:28

jasnell added 2 commits February 26, 2018 11:29

perf_hooks: make PerformanceObserver an AsyncResource

02adcf7

jasnell force-pushed the perf_trace_event branch from f67e78d to 02adcf7 Compare February 26, 2018 19:29

jasnell added the semver-minor PRs that contain new features and should be released in the next minor version. label Feb 26, 2018

jasnell added a commit that referenced this pull request Feb 26, 2018

perf_hooks: eliminate deprecation warning

aca8e76

PR-URL: #18789 Reviewed-By: Ali Ijaz Sheikh <ofrobots@google.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com>

jasnell added a commit that referenced this pull request Feb 26, 2018

perf_hooks: make PerformanceObserver an AsyncResource

009e418

PR-URL: #18789 Reviewed-By: Ali Ijaz Sheikh <ofrobots@google.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com>

jasnell closed this Feb 26, 2018

MylesBorins added the backport-requested-v9.x label Mar 6, 2018

targos added dont-land-on-v9.x and removed author ready PRs that have at least one approval, no pending requests for changes, and a CI started. backport-requested-v9.x labels Apr 2, 2018

MayaLekova pushed a commit to MayaLekova/node that referenced this pull request May 8, 2018

perf_hooks: eliminate deprecation warning

d09dc7d

PR-URL: nodejs#18789 Reviewed-By: Ali Ijaz Sheikh <ofrobots@google.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com>

MayaLekova pushed a commit to MayaLekova/node that referenced this pull request May 8, 2018

perf_hooks: make PerformanceObserver an AsyncResource

94114e7

PR-URL: nodejs#18789 Reviewed-By: Ali Ijaz Sheikh <ofrobots@google.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com>

MylesBorins added the dont-land-on-v8.x label Aug 7, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

perf_hooks: emit user timing marks, measures and timerify to trace events #18789

perf_hooks: emit user timing marks, measures and timerify to trace events #18789

jasnell commented Feb 14, 2018

AndreasMadsen commented Feb 15, 2018

ofrobots Feb 15, 2018 •

edited

Loading

jasnell Feb 15, 2018

ofrobots Feb 15, 2018

jasnell commented Feb 15, 2018

ofrobots Feb 16, 2018 •

edited

Loading

jasnell Feb 16, 2018

jasnell Feb 16, 2018

ofrobots Feb 16, 2018

ofrobots Feb 16, 2018

jasnell commented Feb 16, 2018

jasnell commented Feb 16, 2018

jasnell commented Feb 17, 2018

jasnell commented Feb 17, 2018

AndreasMadsen Feb 17, 2018

jasnell Feb 17, 2018

ofrobots Feb 18, 2018

mcollina left a comment

mcollina Feb 19, 2018

jasnell Feb 26, 2018

jasnell commented Feb 26, 2018

MylesBorins commented Mar 6, 2018

targos commented Apr 2, 2018

perf_hooks: emit user timing marks, measures and timerify to trace events #18789

perf_hooks: emit user timing marks, measures and timerify to trace events #18789

Conversation

jasnell commented Feb 14, 2018

Checklist

Affected core subsystem(s)

AndreasMadsen commented Feb 15, 2018

ofrobots Feb 15, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jasnell commented Feb 15, 2018

ofrobots Feb 16, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jasnell commented Feb 16, 2018

jasnell commented Feb 16, 2018

jasnell commented Feb 17, 2018

jasnell commented Feb 17, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mcollina left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jasnell commented Feb 26, 2018

MylesBorins commented Mar 6, 2018

targos commented Apr 2, 2018

ofrobots Feb 15, 2018 •

edited

Loading

ofrobots Feb 16, 2018 •

edited

Loading