perf_hooks/trace_events - nested measurements don't work as expected

[bmacnaughton]

• v12.16.1:
• Linux uxpanapa 4.15.0-88-generic Proposal: return Promises as well as taking callbacks. #88-Ubuntu SMP Tue Feb 11 20:11:34 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux:
• Chrome Version 80.0.3987.132 (Official Build) (64-bit):

'use strict';

const trace_events = require('trace_events');
const {performance: perf} = require('perf_hooks');
const fs = require('fs');

const tracing = trace_events.createTracing({
  categories: ['node.perf.usertiming'],
});

tracing.enable();
fs.readdirSync('.');
perf.mark('A');
fs.readdirSync('.');
perf.mark('B');
fs.readdirSync('.');
perf.mark('C');
perf.measure('B => C', 'B', 'C');
fs.readdirSync('.');
perf.mark('D');
perf.measure('A => D', 'A', 'D');
fs.readdirSync('.');
tracing.disable();

How often does it reproduce? Is there a required condition?

It reproduces every time.

What is the expected behavior?

i expect that A => D be shorter than JavaScriptMainThread and that A => D would be selectable in chrome://tracing. It's possible that it's just an omission from the documentation or that I missed a note that measurements cannot be nested.

What do you see instead?

node_trace.1.log:

{"traceEvents":[{"pid":29578,"tid":29578,"ts":1819702786241,"tts":22090,"ph":"M","cat":"__metadata","name":"process_name","dur":0,"tdur":0,"args":{"name":"node"}},{"pid":29578,"tid":29578,"ts":1819702786243,"tts":22092,"ph":"M","cat":"__metadata","name":"version","dur":0,"tdur":0,"args":{"node":"12.16.1"}},{"pid":29578,"tid":29578,"ts":1819702786245,"tts":22094,"ph":"M","cat":"__metadata","name":"thread_name","dur":0,"tdur":0,"args":{"name":"JavaScriptMainThread"}},{"pid":29578,"tid":29578,"ts":1819702786252,"tts":22101,"ph":"M","cat":"__metadata","name":"node","dur":0,"tdur":0,"args":{"process":{"versions":{"node":"12.16.1","v8":"7.8.279.23-node.31","uv":"1.34.0","zlib":"1.2.11","brotli":"1.0.7","ares":"1.15.0","modules":"72","nghttp2":"1.40.0","napi":"5","llhttp":"2.0.4","http_parser":"2.9.3","openssl":"1.1.1d","cldr":"35.1","icu":"64.2","tz":"2019c","unicode":"12.1"},"arch":"x64","platform":"linux","release":{"name":"node","lts":"Erbium"}}}},{"pid":29578,"tid":29578,"ts":1819702786241,"tts":22090,"ph":"M","cat":"__metadata","name":"process_name","dur":0,"tdur":0,"args":{"name":"node"}},{"pid":29578,"tid":29578,"ts":1819702786243,"tts":22092,"ph":"M","cat":"__metadata","name":"version","dur":0,"tdur":0,"args":{"node":"12.16.1"}},{"pid":29578,"tid":29578,"ts":1819702786245,"tts":22094,"ph":"M","cat":"__metadata","name":"thread_name","dur":0,"tdur":0,"args":{"name":"JavaScriptMainThread"}},{"pid":29578,"tid":29578,"ts":1819702786252,"tts":22101,"ph":"M","cat":"__metadata","name":"node","dur":0,"tdur":0,"args":{"process":{"versions":{"node":"12.16.1","v8":"7.8.279.23-node.31","uv":"1.34.0","zlib":"1.2.11","brotli":"1.0.7","ares":"1.15.0","modules":"72","nghttp2":"1.40.0","napi":"5","llhttp":"2.0.4","http_parser":"2.9.3","openssl":"1.1.1d","cldr":"35.1","icu":"64.2","tz":"2019c","unicode":"12.1"},"arch":"x64","platform":"linux","release":{"name":"node","lts":"Erbium"}}}},{"pid":29578,"tid":29578,"ts":1819702786664,"tts":22261,"ph":"R","cat":"node,node.perf,node.perf.usertiming","name":"A","dur":0,"tdur":0,"args":{}},{"pid":29578,"tid":29578,"ts":1819702786702,"tts":22295,"ph":"R","cat":"node,node.perf,node.perf.usertiming","name":"B","dur":0,"tdur":0,"args":{}},{"pid":29578,"tid":29578,"ts":1819702786720,"tts":22313,"ph":"R","cat":"node,node.perf,node.perf.usertiming","name":"C","dur":0,"tdur":0,"args":{}},{"pid":29578,"tid":29578,"ts":1819702786702,"tts":22350,"ph":"b","cat":"node,node.perf,node.perf.usertiming","name":"B => C","dur":0,"tdur":0,"id":"0x7ffd671fc568","args":{}},{"pid":29578,"tid":29578,"ts":1819702786720,"tts":22352,"ph":"e","cat":"node,node.perf,node.perf.usertiming","name":"B => C","dur":0,"tdur":0,"id":"0x7ffd671fc568","args":{}},{"pid":29578,"tid":29578,"ts":1819702786782,"tts":22375,"ph":"R","cat":"node,node.perf,node.perf.usertiming","name":"D","dur":0,"tdur":0,"args":{}},{"pid":29578,"tid":29578,"ts":1819702786664,"tts":22379,"ph":"b","cat":"node,node.perf,node.perf.usertiming","name":"A => D","dur":0,"tdur":0,"id":"0x7ffd671fc568","args":{}},{"pid":29578,"tid":29578,"ts":1819702786782,"tts":22381,"ph":"e","cat":"node,node.perf,node.perf.usertiming","name":"A => D","dur":0,"tdur":0,"id":"0x7ffd671fc568","args":{}},{"pid":29578,"tid":29578,"ts":1819702786241,"tts":22090,"ph":"M","cat":"__metadata","name":"process_name","dur":0,"tdur":0,"args":{"name":"node"}},{"pid":29578,"tid":29578,"ts":1819702786243,"tts":22092,"ph":"M","cat":"__metadata","name":"version","dur":0,"tdur":0,"args":{"node":"12.16.1"}},{"pid":29578,"tid":29578,"ts":1819702786245,"tts":22094,"ph":"M","cat":"__metadata","name":"thread_name","dur":0,"tdur":0,"args":{"name":"JavaScriptMainThread"}},{"pid":29578,"tid":29578,"ts":1819702786252,"tts":22101,"ph":"M","cat":"__metadata","name":"node","dur":0,"tdur":0,"args":{"process":{"versions":{"node":"12.16.1","v8":"7.8.279.23-node.31","uv":"1.34.0","zlib":"1.2.11","brotli":"1.0.7","ares":"1.15.0","modules":"72","nghttp2":"1.40.0","napi":"5","llhttp":"2.0.4","http_parser":"2.9.3","openssl":"1.1.1d","cldr":"35.1","icu":"64.2","tz":"2019c","unicode":"12.1"},"arch":"x64","platform":"linux","release":{"name":"node","lts":"Erbium"}}}},{"pid":29578,"tid":29578,"ts":1819702786241,"tts":22090,"ph":"M","cat":"__metadata","name":"process_name","dur":0,"tdur":0,"args":{"name":"node"}},{"pid":29578,"tid":29578,"ts":1819702786243,"tts":22092,"ph":"M","cat":"__metadata","name":"version","dur":0,"tdur":0,"args":{"node":"12.16.1"}},{"pid":29578,"tid":29578,"ts":1819702786245,"tts":22094,"ph":"M","cat":"__metadata","name":"thread_name","dur":0,"tdur":0,"args":{"name":"JavaScriptMainThread"}},{"pid":29578,"tid":29578,"ts":1819702786252,"tts":22101,"ph":"M","cat":"__metadata","name":"node","dur":0,"tdur":0,"args":{"process":{"versions":{"node":"12.16.1","v8":"7.8.279.23-node.31","uv":"1.34.0","zlib":"1.2.11","brotli":"1.0.7","ares":"1.15.0","modules":"72","nghttp2":"1.40.0","napi":"5","llhttp":"2.0.4","http_parser":"2.9.3","openssl":"1.1.1d","cldr":"35.1","icu":"64.2","tz":"2019c","unicode":"12.1"},"arch":"x64","platform":"linux","release":{"name":"node","lts":"Erbium"}}}},{"pid":29578,"tid":29578,"ts":1819702786241,"tts":22090,"ph":"M","cat":"__metadata","name":"process_name","dur":0,"tdur":0,"args":{"name":"node"}},{"pid":29578,"tid":29578,"ts":1819702786243,"tts":22092,"ph":"M","cat":"__metadata","name":"version","dur":0,"tdur":0,"args":{"node":"12.16.1"}},{"pid":29578,"tid":29578,"ts":1819702786245,"tts":22094,"ph":"M","cat":"__metadata","name":"thread_name","dur":0,"tdur":0,"args":{"name":"JavaScriptMainThread"}},{"pid":29578,"tid":29578,"ts":1819702786252,"tts":22101,"ph":"M","cat":"__metadata","name":"node","dur":0,"tdur":0,"args":{"process":{"versions":{"node":"12.16.1","v8":"7.8.279.23-node.31","uv":"1.34.0","zlib":"1.2.11","brotli":"1.0.7","ares":"1.15.0","modules":"72","nghttp2":"1.40.0","napi":"5","llhttp":"2.0.4","http_parser":"2.9.3","openssl":"1.1.1d","cldr":"35.1","icu":"64.2","tz":"2019c","unicode":"12.1"},"arch":"x64","platform":"linux","release":{"name":"node","lts":"Erbium"}}}},{"pid":29578,"tid":29578,"ts":1819702786241,"tts":22090,"ph":"M","cat":"__metadata","name":"process_name","dur":0,"tdur":0,"args":{"name":"node"}},{"pid":29578,"tid":29578,"ts":1819702786243,"tts":22092,"ph":"M","cat":"__metadata","name":"version","dur":0,"tdur":0,"args":{"node":"12.16.1"}},{"pid":29578,"tid":29578,"ts":1819702786245,"tts":22094,"ph":"M","cat":"__metadata","name":"thread_name","dur":0,"tdur":0,"args":{"name":"JavaScriptMainThread"}},{"pid":29578,"tid":29578,"ts":1819702786252,"tts":22101,"ph":"M","cat":"__metadata","name":"node","dur":0,"tdur":0,"args":{"process":{"versions":{"node":"12.16.1","v8":"7.8.279.23-node.31","uv":"1.34.0","zlib":"1.2.11","brotli":"1.0.7","ares":"1.15.0","modules":"72","nghttp2":"1.40.0","napi":"5","llhttp":"2.0.4","http_parser":"2.9.3","openssl":"1.1.1d","cldr":"35.1","icu":"64.2","tz":"2019c","unicode":"12.1"},"arch":"x64","platform":"linux","release":{"name":"node","lts":"Erbium"}}}}]}

Additional information

[jeluard]

I can't make this example generate traces for node.perf.usertiming with recent node releases. Is it still supported?