Profiling using --prof inside worker_threads does not work

[slonka]

• Version: 11.0.0
• Platform: macos
• Subsystem: worker_threads

Generating flame graphs with worker_thread produces isolate files that do not contain useful information.

Using my example repo https://github.com/slonka/nodejs-prof-worker-threads-not-working i generated the following flame graphs for:

Single threaded version:

And worker threads version:

What makes me think that this is a bug inside node and not 0x is that isolate files and processed files (generated by running node --prof-process) contain pretty much the same info that is on the flame graphs. I used flame graphs because they are easier to read for me.

[Trott]

@nodejs/workers

[slonka]

Also, running node --prof --no-logfile-per-isolate --experimental-worker index.js and then trying to do node --prof-process v8.log > processed-single.txt causes an error:

line 2106: unknown code state: 996593

With a different line on every try.

[addaleax]

Maybe @bnoordhuis or somebody else in @nodejs/v8 could know how this would work?

[hashseed]

--no-logfile-per-isolate causes every isolate to log into the same file. That causes confusion for the tick processor script.

[bnoordhuis]

Thanks for the write-up, good bug report! I can reproduce on macos, still need to check other platforms. I used the reduced test case below:

'use strict';
const {Worker, isMainThread, parentPort} = require('worker_threads');
function work() {
  const fib = n => n <= 1 ? 1 : fib(n-1) + fib(n-2);
  for (let i = 0; i < 1e4; i++) {
    process.x = fib(1 + i%24);
    if (parentPort) parentPort.postMessage(process.x);
  }
}
work(); // both threads
if (isMainThread) new Worker(__filename).on('message', console.log);

When run with --prof and then post-processed with --prof-process, the log file of one isolate produces meaningful output while the other produces this:

$ ./out/Release/node --prof-process isolate-0x10304f400-v8.log
Statistical profiling result from isolate-0x10304f400-v8.log, (3 ticks, 0 unaccounted, 0 excluded).

 [Shared libraries]:
   ticks  total  nonlib   name

 [JavaScript]:
   ticks  total  nonlib   name

 [C++]:
   ticks  total  nonlib   name
      1   33.3%   33.3%  t v8::internal::Heap::AllocateRaw(int, v8::internal::AllocationSpace, v8::internal::AllocationAlignment)
      1   33.3%   33.3%  T v8::internal::Deserializer<v8::internal::DefaultDeserializerAllocator>::ReadData(v8::internal::MaybeObject**, v8::internal::MaybeObject**, int, unsigned long)
      1   33.3%   33.3%  T __kernelrpc_mach_vm_map

 [Summary]:
   ticks  total  nonlib   name
      0    0.0%    0.0%  JavaScript
      3  100.0%  100.0%  C++
      0    0.0%    0.0%  GC
      0    0.0%          Shared libraries

 [C++ entry points]:
   ticks    cpp   total   name

 [Bottom up (heavy) profile]:
  Note: percentage shows a share of a particular caller in the total
  amount of its parent calls.
  Callers occupying less than 1.0% are not shown.

   ticks parent  name
      1   33.3%  t v8::internal::Heap::AllocateRaw(int, v8::internal::AllocationSpace, v8::internal::AllocationAlignment)
      1   33.3%  T v8::internal::Deserializer<v8::internal::DefaultDeserializerAllocator>::ReadData(v8::internal::MaybeObject**, v8::internal::MaybeObject**, int, unsigned long)
      1   33.3%  T __kernelrpc_mach_vm_map

I'll investigate this week. The low number of ticks (3) clearly suggests profiling somehow isn't working.

[slonka]

Hi @bnoordhuis - I'm very interested in learning more about the internals of node / v8 so if you would be open to doing some "pair debugging" I'd love to see how you takle a problem like this.

[bnoordhuis]

I did some quick debugging and discovered that new Worker() creates the new isolate on the thread of the current isolate, misleading V8's SIGPROF-based profiler into profiling the wrong thread - the one that's already being profiled.

@addaleax You probably have ideas on how easy it is to move isolate creation to the new thread. I'm guessing 'not that easy'? I suppose an alternative is to petition V8 to untangle isolate creation and starting the profiler; I'm fairly sure the call to Profiler::Engage() could be delayed without ill effect.

@slonka My style of debugging isn't all that advanced, I just read the code and crack open gdb or add some printf statements. :-)

[slonka]

@bnoordhuis - I just want to see how other people work and learn from them. I fully understand if you don't have time / don't want to :)

[addaleax]

I think it might be nice to move Isolate creation to the new thread anyway – in part so that we don’t spend the time for that while on the parent thread – but yes, it’s a bit more comfortable to do it this way.

I’ll look into that as a first option.

[addaleax]

#26011 should resolve this – thanks for the debugging, @bnoordhuis!