Node 10 profiler path output regression on Windows

[edmorley]

• Version: v10.1.0
• Platform: Windows 10 x64 (1803)
• Subsystem: v8 profiler

Summary:

With Node 10 on Windows, the v8 log generated via node --prof no longer quotes paths correctly, causing node --prof-process to treat the backslashes in the paths as escape sequences.

This causes a path like:
C:\Users\Ed\src\neutrino-dev\node_modules\webpack\lib\Stats.js

...to be output as:
C:\u0000\rc\u0000erder\node_modulesëck\u0000tats.js

...which doesn't make for the most readable profiles.

In addition, redirecting stdout when using --prof-process without the --preprocess, results in a binary file (whereas if there is no redirection, text is output to the console as expected).

I'm presuming this is a regression between v8 6.2 and 6.6.

STR:

1. node --prof node_modules\webpack\bin\webpack.js --mode production
2. node --prof-process --preprocess isolate-[IDENTIFIER]-v8.log > preprocessed.json
3. node --prof-process isolate-[IDENTIFIER]-v8.log > processed.txt
4. Repeat steps 1-3 using Node 8.11.2 instead, and compare output from each.

Expected:

Node 10.1.0 produces comparable output to Node 8.x, that correctly lists the filesystem paths for items in the profile.

Actual:

# Step 1 produces... (note difference in quoting)

Node 10.1.0:

v8-version,6,6,346,27,-node.6,0
shared-library,C:\Users\Ed\Desktop\node-v10.1.0-win-x64\node.exe,0x7ff64f880000,0x7ff650f0f000,0
shared-library,C:\WINDOWS\SYSTEM32\ntdll.dll,0x7ff9b1df0000,0x7ff9b1fd1000,0
shared-library,C:\WINDOWS\System32\KERNEL32.DLL,0x7ff9b0da0000,0x7ff9b0e52000,0
...

Node 8.11.2:

v8-version,6,2,414,54,0
shared-library,"C:\Users\Ed\Desktop\node-v8.11.2-win-x64\node.exe",0x7ff6f9ec0000,0x7ff6fb490000,0
shared-library,"C:\WINDOWS\SYSTEM32\ntdll.dll",0x7ff9b1df0000,0x7ff9b1fd1000,0
shared-library,"C:\WINDOWS\System32\KERNEL32.DLL",0x7ff9b0da0000,0x7ff9b0e52000,0
...

# Step 2 produces...

Node 10.1.0:

{
  "code": [
  {
    "name": "C:\u0000\rsktop\node-v10.1.0-win-x64\node.exe",
    "type": "SHARED_LIB"
  },
  {
    "name": "C:\u0000WS\u0000M32\ntdll.dll",
    "type": "SHARED_LIB"
  },
...

Node 8.11.2:

{
  "code": [
  {
    "name": "C:\\Users\\Ed\\Desktop\\node-v8.11.2-win-x64\\node.exe",
    "type": "SHARED_LIB"
  },
  {
    "name": "C:\\WINDOWS\\SYSTEM32\\ntdll.dll",
    "type": "SHARED_LIB"
  },
...

# Step 3 produces...

Node 10.1.0 (note: the binary output only occurs when redirecting stdout to a file):

5374 6174 6973 7469 6361 6c20 7072 6f66
696c 696e 6720 7265 7375 6c74 2066 726f
6d20 6973 6f6c 6174 652d 3030 3030 3031
3139 3031 3441 3539 4130 2d76 382e 6c6f
...

Node 8.11.2:

Statistical profiling result from isolate-0000027B49039D30-v8.log, (5485 ticks, 82 unaccounted, 0 excluded).

 [Shared libraries]:
   ticks  total  nonlib   name
   2551   46.5%          C:\WINDOWS\SYSTEM32\ntdll.dll
   1507   27.5%          C:\Users\Ed\Desktop\node-v8.11.2-win-x64\node.exe
...

[tplk]

I temporary use the following solution:

node --prof node_modules/webpack/bin/webpack.js --mode production
sed -r 's/C\:\\[^,]+/"&"/g' isolate-[IDENTIFIER]-v8.log | sed -r '/C\:./ { s/\\/\//g }' > converted
node --prof-process converted > processed.txt

It results in the following output:

...
 [Shared libraries]:
   ticks  total  nonlib   name
     49   80.3%          "C:/Program Files/nodejs/node.exe"
      9   14.8%          "C:/WINDOWS/SYSTEM32/ntdll.dll"
...

[jjyyxx]

I confirm the issue still exists with Node 10.9.0.
@tplk Thanks for your workaround. But when RegExp involved, such lines were still broken.

code-creation,RegExp,4,325150,0x1851d0746e0,1083,^(?=\n[ \t]*(\n|$))

I tried to apply similar fixes like adding "", but in vain anyway.
I'd like to know what's the behavior of regexp in log file in previous v8 versions and is there another workaround for it?

[BridgeAR]

Seems like this is an upstream bug and not directly related to Node.js.

@nodejs/v8 PTAL.

[hashseed]

@psmarshall

[BridgeAR]

Seems like this just got fixed upstream: https://chromium.googlesource.com/v8/v8.git/+/29879461ceb4bc9b84b0ec38e4dd192fbf884dc2. I asked for a backport to 6.8 and I'll get that in if it's accepted.

[ryzokuken]

@BridgeAR closing this since this was fixed upstream and will be landed on canary-master soon if it hasn't already. Feel free to reopen this.

[richardlau]

@ryzokuken Reopening this as for Node.js 10 we'll probably need to float a V8 backport.

[bzoz]

So, this is still an issue with v10.x. Can we at least float the change from https://chromium-review.googlesource.com/c/v8/v8/+/1186625/2/tools/profile.js ?

/cc @nodejs/platform-windows @nodejs/v8

[refack]

Cherry-pick PR - #24555

[BethGriggs]

The fix for this landed in v10.14.2 #24555

[jholladay10]

This still seems to be an issue in v10.16.0
processed.txt

[konpikwastaken]

Confirmed still repro in v10.16 win10