Improve the V8 Profiler performance

As previously mentioned on #148 a lot of work was done on CPU Profiler.

The only tool for profiling NodeJS cross-platform is the usage of Profiler.start and Profiler.stop. However, this dynamic instrumentation blocks the event-loop because it needs to iterate over all functions to map. (CpuProfiler::StartProfiling more specifically) and it is harmful to production environments.

This issue is to discuss some ways to improve these usages in the production environment.

Removing from the agenda until we come up with benchmarks for the performance issue.

This issue is stale because it has been open many days with no activity. It will be closed soon unless the stale label is removed or a comment is made.

@Flarna

I've tried to reproduce this behavior but it looks like was fixed on v14 and above.

Code:

const inspector = require('inspector');
const fs = require('fs');

const session = new inspector.Session();
session.connect();

console.time('enable')
session.post('Profiler.enable', () => {
  console.timeEnd('enable')
  let a = [];
  for (let i = 0; i < 1000000; i++) {
    const f = new Function("a", "b", "return a + b");
    f(i, i - 1);
    a.push(f);
  }

  console.time('start')
  session.post('Profiler.start', () => {
    console.timeEnd('start')
    console.time('stop')
    session.post('Profiler.stop', (err, { profile }) => {
      console.timeEnd('stop')
      if (!err) {
        fs.writeFileSync('./profile.cpuprofile', JSON.stringify(profile));
      }
    });
  });
});

v10

$ node bench-profiler.js
enable: 0.293ms
start: 610.000ms
stop: 235.631ms

v12

$ node bench-profiler.js
enable: 0.404ms
start: 640.016ms
stop: 0.473ms

v14

$ node bench-profiler.js
enable: 0.682ms
start: 58.032ms
stop: 0.472ms

v16

$ node bench-profiler.js
enable: 1.621ms
start: 53.174ms
stop: 0.695ms

@Flarna I'm tagging you because I've seen your code example from: #148 (comment)

We discussed and sounds reasonable to close this issue since the results look good for the production environment.

@RafaelGSS

Hi, @RafaelGSS,

can we reopen this issue? I ran the above bench program in node: 16.14.0, latest LTS in v16 as of today, and I got very slow stop() performance:

v16.14.0

$ node test.js
enable: 0.441ms
start: 2.502s
stop: 1.318s

yet on node 14.18.2 and node 17.7.1, it looks like this:

14.18.2
$ node test.js
enable: 0.465ms
start: 72.465ms
stop: 0.92ms

17.7.1
$ node test.js
enable: 1.25ms
start: 50.264ms
stop: 3.763ms

I went backwards on 16 LTS, and it's fast - sometimes - on 16.1.4.0:

Now using node v16.13.0 (npm v8.1.0)
$ node test.js
enable: 1.267ms
start: 119.588ms
stop: 40.193ms
$ node test.js
enable: 0.494ms
start: 2.471s
stop: 1.263s
$ node test.js
enable: 0.475ms
start: 116.059ms
stop: 36.987ms
$ node test.js
enable: 0.522ms
start: 122.772ms
stop: 36.995ms

and it appears always fast, but not as fast as 14 or 17, on 16.10.0

Now using node v16.10.0 (npm v7.24.0)
$ node test.js
enable: 1.144ms
start: 70.108ms
stop: 14.879ms
$ node test.js
enable: 0.491ms
start: 66.77ms
stop: 15.259ms
$ node test.js
enable: 0.426ms
start: 66.567ms
stop: 14.342ms
$ node test.js
enable: 0.441ms
start: 68.913ms
stop: 14.604ms

These were all run on a macbook pro 2020, intel.

Hey! Are you able to send a reproducible code?

Yes, I ran the exact script referenced above that you posted from the original thread.

I did not attempt to repro this on other machines / OS, only on mac (Big Sur). I didn't try on linux, for example.

Oh, ok. I'll check soon

This issue is stale because it has been open many days with no activity. It will be closed soon unless the stale label is removed or a comment is made.

Recently, I had no time to validate it. Does anyone in @nodejs/diagnostics interested in this discovery?

If I got it right, we should understand why the profiler takes too much to stop on Node 16.x and 17.x?

If I got it right, we should understand why the profiler takes too much to stop on Node 16.x and 17.x?

Checking how much time is it taking in all Node.js versions would be a great start.

Checking how much time is it taking in all Node.js versions would be a great start.

Neat! I could give it a try ^^. Feel free to share any resource that could help me.

I remember you posted that: https://github.com/RafaelGSS/nodejs-bench-operations

Could I use a similar approach?

Checking how much time is it taking in all Node.js versions would be a great start.

Neat! I could give it a try ^^. Feel free to share any resource that could help me.

I remember you posted that: https://github.com/RafaelGSS/nodejs-bench-operations

Could I use a similar approach?

I think the snippet I sent above would work as well. #444 (comment)

@RafaelGSS

Hey 👋

Make a simple script and put the results here: https://github.com/tony-go/v8-profiler-performance

What I did:

iterate over node version (from 8 to 18)
change the version with nvm
run the @RafaelGSS snippet 10 times - don't really know if it was relevant or not to run it 10 times, let me know if I should adjust.

I keep the same output but let me know if you prefer a table with average etc...

Sorry if it looks a bit bikeshed, but it's my first time ^^

@tony-go

Thank you @tony-go.

I've run it locally and the max spike I got was 1.5sec

======= iteration number 1 for node v14.19.3 ========
enable: 0.246ms
start: 57.586ms
stop: 0.447ms
======= iteration number 2 for node v14.19.3 ========
enable: 0.25ms
start: 56.623ms
stop: 0.435ms
======= iteration number 3 for node v14.19.3 ========
enable: 0.238ms
start: 58.386ms
stop: 0.445ms
======= iteration number 4 for node v14.19.3 ========
enable: 0.246ms
start: 57.457ms
stop: 0.456ms
======= iteration number 5 for node v14.19.3 ========
enable: 0.267ms
start: 59.748ms
stop: 0.597ms
======= iteration number 6 for node v14.19.3 ========
enable: 0.249ms
start: 56.702ms
stop: 0.444ms
======= iteration number 7 for node v14.19.3 ========
enable: 0.236ms
start: 58.028ms
stop: 0.477ms
======= iteration number 8 for node v14.19.3 ========
enable: 0.245ms
start: 57.485ms
stop: 0.434ms
======= iteration number 9 for node v14.19.3 ========
enable: 0.245ms
start: 57.501ms
stop: 0.455ms
======= iteration number 10 for node v14.19.3 ========
enable: 0.247ms
start: 59.6ms
stop: 0.437ms

======= iteration number 1 for node v16.15.1 ========
enable: 0.235ms
start: 1.483s
stop: 900.975ms
======= iteration number 2 for node v16.15.1 ========
enable: 0.238ms
start: 1.449s
stop: 911.747ms
======= iteration number 3 for node v16.15.1 ========
enable: 0.255ms
start: 421.201ms
stop: 240.386ms
======= iteration number 4 for node v16.15.1 ========
enable: 0.235ms
start: 1.474s
stop: 908.485ms
======= iteration number 5 for node v16.15.1 ========
enable: 0.237ms
start: 99.483ms
stop: 25.386ms
======= iteration number 6 for node v16.15.1 ========
enable: 11.825ms
start: 41.66ms
stop: 0.748ms
======= iteration number 7 for node v16.15.1 ========
enable: 0.251ms
start: 101.609ms
stop: 28.143ms
======= iteration number 8 for node v16.15.1 ========
enable: 0.233ms
start: 1.455s
stop: 899.074ms
======= iteration number 9 for node v16.15.1 ========
enable: 0.241ms
start: 103.015ms
stop: 27.097ms
======= iteration number 10 for node v16.15.1 ========
enable: 0.249ms
start: 101.046ms
stop: 24.36ms

======= iteration number 1 for node v18.4.0 ========
enable: 0.246ms
start: 354.838ms
stop: 207.19ms
======= iteration number 2 for node v18.4.0 ========
enable: 0.234ms
start: 101.858ms
stop: 21.897ms
======= iteration number 3 for node v18.4.0 ========
enable: 0.271ms
start: 1.442s
stop: 873.228ms
======= iteration number 4 for node v18.4.0 ========
enable: 0.237ms
start: 98.99ms
stop: 24.871ms
======= iteration number 5 for node v18.4.0 ========
enable: 0.235ms
start: 360.61ms
stop: 207.911ms
======= iteration number 6 for node v18.4.0 ========
enable: 0.249ms
start: 101.585ms
stop: 29.675ms
======= iteration number 7 for node v18.4.0 ========
enable: 0.239ms
start: 352.201ms
stop: 204.73ms
======= iteration number 8 for node v18.4.0 ========
enable: 0.233ms
start: 1.404s
stop: 865.165ms
======= iteration number 9 for node v18.4.0 ========
enable: 0.255ms
start: 362.245ms
stop: 200.001ms
======= iteration number 10 for node v18.4.0 ========
enable: 0.234ms
start: 102.054ms
stop: 26.845ms

There are several variables that might affect this benchmark such as page faults and so on. Nevertheless, I think the results in the latest version are acceptable

@lastquestion

@lastquestion I'll close it. In case you think this need to be fixed, please provide a bit more information of your use case. Thank you!

Good :)

There are several variables that might affect this benchmark such as page faults and so on. Nevertheless, I think the results in the latest version are acceptable

For my personal culture: if you could share more information regarding stuff I should avoid when I write a benchmark it should be great :)

Navigation Menu

Repository navigation

Improve the V8 Profiler performance #444

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Improve the V8 Profiler performance #444

Description

Activity

mmarchini commented on Nov 25, 2020

github-actions commented on Feb 24, 2021

RafaelGSS commented on Jun 27, 2021

RafaelGSS commented on Jun 30, 2021

lastquestion commented on Mar 16, 2022

RafaelGSS commented on Mar 16, 2022

lastquestion commented on Mar 16, 2022

RafaelGSS commented on Mar 16, 2022

github-actions commented on Jun 15, 2022

RafaelGSS commented on Jun 15, 2022

tony-go commented on Jun 15, 2022

RafaelGSS commented on Jun 15, 2022

tony-go commented on Jun 16, 2022

RafaelGSS commented on Jun 17, 2022

tony-go commented on Jun 22, 2022

RafaelGSS commented on Jul 1, 2022

RafaelGSS commented on Jul 1, 2022

tony-go commented on Jul 1, 2022

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions