speedscope icon indicating copy to clipboard operation
speedscope copied to clipboard

node12 inspector data doesn't render idle time correctly

Open philz opened this issue 2 years ago • 0 comments

Thanks for speedscope; use it frequently! This issue seems to be fixed in Node16, but I wanted to record the issue in case others are running into it.

The application I work on has historically been using https://github.com/hyj1991/v8-profiler-next. I've tried using v8's inspector API instead, and I've found that the idle time of the application isn't being rendered. To illustrate:

Incorrect: image

Correct: image

To narrow this down a bit, I wrote the following to get some profiles. The intention is that this alternates a busy loop for 100ms with idleness for 100ms, and does so ten times.

const inspector = require('inspector')
const fs = require('fs')
const session = new inspector.Session()
session.connect()
session.post('Profiler.enable', () => {
  session.post('Profiler.start', () => {
    ;(async () => {
      for (let i = 0; i < 10; ++i) {
        const s = Date.now()
        while (Date.now() < s + 100) {}
        await new Promise((resolve, reject) => setTimeout(resolve, 100))
      }
    })().then(() => {
      session.post('Profiler.stop', (err, {profile}) => {
        // Write profile to disk, upload, etc.
        if (!err) {
          fs.writeFileSync('profile.cpuprofile', JSON.stringify(profile))
        }
      })
    })
  })
})

The produces the following profile:

image

In Chrome DevTools or when using node18 (and 16) you get the more expected result.

image

The issue seems to be that node12 doesn't mark things as (idle) and the idle stack frame is (root) <- (program) which gets rendered as the previous stack, perhaps. (I'm trying to read shouldPlaceOnTopOfPreviousStack() and its callers in chrome.ts; I don't know why the diff from #71 decided to put (program) with the previous stack.)

philz avatar May 02 '22 21:05 philz