nodejs / node

Node.js JavaScript runtime ✨🐢🚀✨
https://nodejs.org
Other
105.53k stars 28.63k forks source link

console.timeStamp(...) and performance.mark/measure are missing from the --inspect Performance Timings timeline #47813

Open brian-mann opened 1 year ago

brian-mann commented 1 year ago

Version

20

Platform

No response

Subsystem

No response

What steps will reproduce the bug?

console.profile()

console.timeStamp('Start Rendering')
performance.mark("Start rendering")

function createArr() {
  return new Array(10000).join('x')
}

for (var i=0; i< 1000;i++) {
  createArr()
}

performance.mark("Finish rendering")
performance.measure("Rendering", "Start rendering", "Finish rendering")

console.timeStamp('Finish Rendering')
console.profileEnd()

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

No response

What is the expected behavior? Why is that the expected behavior?

  1. Per the node docs on console.timeStamp(...) with the --inspect flag enabled, I should be able to see the timestamp indicated on the performance tab.

  2. The User Timings API, performance.mark, and performance.measure show up as "Timings" in the browser's Chrome Dev Tools, but does not show up in node.

What do you see instead?

I don't see any User Timings API calls on the performance timeline.

image

When using the same performance.* methods in the browser I see them show up in the Performance Timeline.

image

Additional information

No response

KleaTech commented 10 months ago

While we are waiting on this, does anybody know any alternative ways to easily measure and visualize performance locally?

joyeecheung commented 1 month ago

Looked into this a bit and it seems Node.js is sending the Runtime.consoleAPICalled message correctly. I am guessing this is more of a bug in the DevTools frontend dedicated to Node.js not displaying it properly in the performance panel.

Example script

let i = 0;
setInterval(() => {
  const label = `timer${i++}`;
  console.time(label);
  setTimeout(() => {
    console.timeEnd(label);
  }, 1000);
}, 2000);

In Chrome the messages sent to the frontend are:

{
    "type": "timeEnd",
    "args": [
        {
            "type": "string",
            "value": "timer5: 1001.677001953125 ms"
        }
    ],
    "executionContextId": 3,
    "timestamp": 1718723093102.851,
    "stackTrace": {
        "callFrames": [
            {
                "functionName": "",
                "scriptId": "8",
                "url": "file:///Users/joyee/projects/node/log.js",
                "lineNumber": 5,
                "columnNumber": 12
            }
        ],
        "parentId": {
            "id": "43"
        }
    }
}

In Node.js the messages sent to the frontend are like this:

{
    "type": "timeEnd",
    "args": [
        {
            "type": "string",
            "value": "timer3: 1002.194091796875 ms"
        }
    ],
    "executionContextId": 1,
    "timestamp": 1718723204688.715,
    "stackTrace": {
        "callFrames": [
            {
                "functionName": "",
                "scriptId": "72",
                "url": "file:///Users/joyee/projects/node/log.js",
                "lineNumber": 5,
                "columnNumber": 12
            },
            {
                "functionName": "listOnTimeout",
                "scriptId": "10",
                "url": "node:internal/timers",
                "lineNumber": 572,
                "columnNumber": 16
            },
            {
                "functionName": "processTimers",
                "scriptId": "10",
                "url": "node:internal/timers",
                "lineNumber": 513,
                "columnNumber": 6
            }
        ]
    }
}
legendecas commented 1 month ago

Devtools has no support for Tracing domain when targetting Node.js yet, which is necessary to render user timing entries on the devtools performance tab. It's actually a CPU Profile.

joyeecheung commented 1 month ago

Right there are actually two different issues: console messages not showing up and performance timings not showing up. The console messages are more of a Devtools problem because the protocol messages sent by Node.js are not too different than the ones sent by browsers, but the frontend of DevTools for Node.js could only show the profile part and missed all the other parts.