32bit address given for 64bit builds using --prof on Windows

[trevnorris]

• Version: 4.5.0
• Platform: Windows
• Subsystem: N/A

Running --prof using the x64 build of node on Windows gives the following output:

v8-version,4,5,103,37,0
shared-library,"C:\Users\Trevor Norris\Downloads\node.exe",0x450d0000,0x45e8d000
shared-library,"C:\Windows\SYSTEM32\ntdll.dll",0xe44c0000,0xe466d000
shared-library,"C:\Windows\system32\KERNEL32.DLL",0xe39c0000,0xe3afe000
shared-library,"C:\Windows\system32\KERNELBASE.dll",0xe1770000,0xe1885000
shared-library,"C:\Windows\system32\WS2_32.dll",0xe3fa0000,0xe3ffa000
shared-library,"C:\Windows\SYSTEM32\WINMM.dll",0xdf880000,0xdf8a2000
shared-library,"C:\Windows\system32\ADVAPI32.dll",0xe3ef0000,0xe3f9a000
shared-library,"C:\Windows\system32\USER32.dll",0xe35b0000,0xe3727000
shared-library,"C:\Windows\SYSTEM32\IPHLPAPI.DLL",0xde250000,0xde27a000
shared-library,"C:\Windows\system32\PSAPI.DLL",0xe3900000,0xe3907000
shared-library,"C:\Windows\SYSTEM32\USERENV.dll",0xe0bc0000,0xe0be1000
shared-library,"C:\Windows\system32\NSI.dll",0xe3b00000,0xe3b09000
shared-library,"C:\Windows\system32\RPCRT4.dll",0xe1b50000,0xe1c90000
shared-library,"C:\Windows\SYSTEM32\WINMMBASE.dll",0xdf6a0000,0xdf6ca000
shared-library,"C:\Windows\system32\msvcrt.dll",0xe3910000,0xe39ba000
shared-library,"C:\Windows\SYSTEM32\sechost.dll",0xe3e00000,0xe3e59000
shared-library,"C:\Windows\system32\GDI32.dll",0xe3b10000,0xe3c5f000
shared-library,"C:\Windows\SYSTEM32\WINNSI.DLL",0xde170000,0xde17a000
shared-library,"C:\Windows\SYSTEM32\profapi.dll",0xe15b0000,0xe15c5000
shared-library,"C:\Windows\system32\SspiCli.dll",0xe1a70000,0xe1a9e000
shared-library,"C:\Windows\SYSTEM32\cfgmgr32.dll",0xe1b00000,0xe1b4f000
shared-library,"C:\Windows\SYSTEM32\DEVOBJ.dll",0xe0430000,0xe0458000
shared-library,"C:\Windows\system32\IMM32.DLL",0xe3280000,0xe32b6000
shared-library,"C:\Windows\system32\MSCTF.dll",0xe3730000,0xe3882000
shared-library,"C:\Windows\system32\mswsock.dll",0xe0e30000,0xe0e89000
shared-library,"C:\Windows\SYSTEM32\CRYPTSP.dll",0xe0e90000,0xe0eb0000
shared-library,"C:\Windows\system32\rsaenh.dll",0xe0ab0000,0xe0ae6000
shared-library,"C:\Windows\SYSTEM32\bcrypt.dll",0xe10e0000,0xe1106000
shared-library,"C:\Windows\SYSTEM32\CRYPTBASE.dll",0xe15d0000,0xe15db000
shared-library,"C:\Windows\SYSTEM32\bcryptPrimitives.dll",0xe13f0000,0xe1453000
shared-library,"C:\Windows\SYSTEM32\dbghelp.dll",0xdc070000,0xdc1f9000
profiler,"begin",1
tick,0x7ff74536a8e0,24787,0,0x0,4

Notice the last line of tick where the address is a 64bit address. But all the addresses given to the shared libraries are only 32 bit. This results in a lot of UNKNOWN results when running --prof-process on the isolate-*.log file.

[bnoordhuis]

Those shared library addresses don't look wrong to me, seems like they've simply been mapped into the lower 4 GB of the address space.

I took at a quick look at the V8 code that is responsible for logging them (LoadSymbols() in platform-win32.cc) and that doesn't appear to to truncate them, it operates on BYTE* and uintptr_t.

[trevnorris]

@bnoordhuis Hm. It works properly for the 32bit build. On the 64bit build none of the tick addresses occur in the ranges like those listed above. Any idea why that may be?

[bnoordhuis]

@trevnorris Can you upload the log file somewhere?

[trevnorris]

@bnoordhuis Ran the same script on ia32 and x64 builds. Here are the logs: https://cloudup.com/coCYebT6wT1

[bnoordhuis]

I poked around the x64 log and here is what I see:

• all libraries mapped in first 4 GB
• 1945 code creation events (~1920 if you filter out dups, probably code space gc)
• 1649 ticks
• 4390 stack frame samples
• 1398 unknown samples but only 351 unique

All unknown samples fall in the range 0x7ff7bbd3a0f0-0x7ffe0cac466f which is pretty big, about 2^35, but doesn't seem to belong to any shared libraries.

If you have time, can you try adding --log_all?

[trevnorris]

@bnoordhuis Same script generated 1.2GB file. It compressed down to < 50MB. Link is https://cloudup.com/iWYid8uBObd

/cc @ofrobots Just want to loop you in.

[bnoordhuis]

I'll take a look when I'm on a connection where downloading 50 MB doesn't take an hour. :-)

[nrkn]

I can't profile on Windows 10 x64 and it looks like the same thing - I really need to do some profiling at the moment!

v7.10.0

Trivial test case, but this happens every time I do profiling:

const add = ( a, b ) => a + b
const rand = () => Math.floor( Math.random() * 10 )


let sum = 0
for( let i = 0; i < 100000; i++ )
  sum = add( sum, rand() )

console.log( sum )

isolate-0000011DAB289530-v8.log.txt

Statistical profiling result from isolate-0000011DAB289530-v8.log, (10 ticks, 10 unaccounted, 0 excluded).

 [Shared libraries]:
   ticks  total  nonlib   name

 [JavaScript]:
   ticks  total  nonlib   name

 [C++]:
   ticks  total  nonlib   name

 [Summary]:
   ticks  total  nonlib   name
      0    0.0%    0.0%  JavaScript
      0    0.0%    0.0%  C++
      0    0.0%    0.0%  GC
      0    0.0%          Shared libraries
     10  100.0%          Unaccounted

 [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 2.0% are not shown.

   ticks parent  name
     10  100.0%  UNKNOWN
      4   40.0%    C:\Program Files\nodejs\node.exe

[digitalinfinity]

FYI @nodejs/platform-windows

[bzoz]

The original issue does not reproduce with neither v6.x nor with v8.x

The issue @nrkn is having is there though. On Windows, regardless if it is x86 or x64 profiler reports 80-100% as UNKNOWN. This does not happen on Linux. I did some investigation, I did not see anything suspicious in the log generated on Windows.

I did find, that the issue was introduced with v8 update from #8317

/cc @nodejs/v8

[bnoordhuis]

@bzoz I've also noticed that but I don't know what causes it. The log has a lot of tick entries with nullptr samples (i.e., the PC of the sample points to address 0.)

[jaimecbernardo]

The profiler processor is currently showing a lot of UNKNOWNs due to the change in the output format for memory addresses (was changed from 0x%x to %p). The %p format specified is implementation specific and behaves differently on Windows.

The profiler processor expects a format that is recognized by parseInt.

Example line from profiler output on Linux:

code-creation,Builtin,5,0x12e0553593e0,327,"MathMax"

Example line from profiler output on Windows:

code-creation,Builtin,5,000000BABADD9640,304,"MathMax"

I've added a PR that should fix the issue: #14510