Profiling using --prof inside worker_threads does not work

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.

@nodejs/workers

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.

@bnoordhuis

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

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

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.

@bnoordhuis

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.

@addaleax

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. :-)

@bnoordhuis

@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 :)

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.

worker: set up child Isolate inside Worker thread

test: add `Worker` + `--prof` regression test

@bnoordhuis

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

worker: set up child Isolate inside Worker thread

test: add `Worker` + `--prof` regression test

worker: set up child Isolate inside Worker thread

test: add `Worker` + `--prof` regression test

Navigation Menu

Repository navigation

Profiling using --prof inside worker_threads does not work #24016

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Profiling using --prof inside worker_threads does not work #24016

Description

Activity

Trott commented on Nov 3, 2018

slonka commented on Nov 6, 2018

addaleax commented on Jan 31, 2019

hashseed commented on Feb 2, 2019

bnoordhuis commented on Feb 3, 2019

slonka commented on Feb 3, 2019

bnoordhuis commented on Feb 8, 2019

slonka commented on Feb 8, 2019

addaleax commented on Feb 8, 2019

addaleax commented on Feb 8, 2019

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions