GetReport takes very long times after http requests

[Tofandel]

Version

22.10.0

Platform

Linux Tofandel 5.15.146.1-microsoft-standard-WSL2 #1 SMP Thu Jan 11 04:09:03 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux

What steps will reproduce the bug?

console.time("report");
process.report.getReport();
console.timeEnd("report");
await fetch('https://example.com/');
console.time("report");
process.report.getReport();
console.timeEnd("report");
await fetch('https://example.com/');
await fetch('https://example.com/');
console.time("report");
process.report.getReport();
console.timeEnd("report");
console.time("report");
process.report.getReport();
console.timeEnd("report");

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

Always, I can reproduce on windows and on linux

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

The report to not take more than a few milliseconds

What do you see instead?

The report takes 20 additional seconds to generate per fetch request that occured before it (up to 2 fetch, after that it keeps taking 40s)

report: 1.926ms
report: 20.129s
report: 41.714s
report: 40.311s

Additional information

This still happens even with node --report-exclude-network

[avivkeller]

I can't reproduce a increase of that scale. I ran your code, and I got:

report: 2.095ms
report: 14.098ms
report: 25.988ms

When running at a larger scale, everything seems consistent:

Report (after fetching 0 times): 15.347ms
Report (after fetching 1 times): 24.828ms
Report (after fetching 2 times): 29.105ms
Report (after fetching 3 times): 27.147ms
Report (after fetching 4 times): 31.67ms
Report (after fetching 5 times): 29.602ms
Report (after fetching 6 times): 31.013ms
Report (after fetching 7 times): 29.853ms
Report (after fetching 8 times): 31.42ms
Report (after fetching 9 times): 26.445ms
Report (after fetching 10 times): 24.994ms
Report (after fetching 11 times): 27.865ms
Report (after fetching 12 times): 30.993ms
Report (after fetching 13 times): 30.189ms
Report (after fetching 14 times): 30.977ms
Report (after fetching 15 times): 29.551ms
Report (after fetching 16 times): 26.54ms
Report (after fetching 17 times): 25.168ms
Report (after fetching 18 times): 27.516ms
Report (after fetching 19 times): 27.163ms
Report (after fetching 20 times): 29.243ms

[Tofandel]

Which env are you on? Native linux? I'm reproducing it on windows and WSL (it always takes +20seconds for me after each fetch in both envs), this 20 seconds have to come from something env related

[avivkeller]

Which env are you on? Native linux?

Yes. My machine is:

  System:
    OS: Linux 6.10 Kali GNU/Linux Rolling 2024.3
    CPU: (12) x64 AMD Ryzen 5 5600G with Radeon Graphics
    Memory: 18.63 GB / 27.31 GB

[Tofandel]

When running at a larger scale, everything seems consistent:

That's actually in line with me except your time increase is only 15ms

If I run 5 fetch it doesn't take more than 40 seconds, so it seems it's only a factor for the 2 first fetch

[avivkeller]

I am experiencing an increase, just at a much much smaller scale, so maybe something is going on?

[Tofandel]

Yes, I'd like to help debugging If I can but I'm not sure how, I'm not a C++ dev and there doesn't seem to be any output from NODE_DEBUG_NATIVE and compiling from source takes very long (it's been compiling for 2 hours right now)

[avivkeller]

, I'm not a C++ dev and there doesn't seem to be any output from NODE_DEBUG_NATIVE and compiling from source takes very long (it's been compiling for 2 hours right now)

I can do some research, but I'm also not a CPP dev. As for compile times, as a rule-of-thumb, if you aren't already, make use of multithreading (make -j4 where 4 is the number of threads), and configure with ninja (./configure --ninja)

[Tofandel]

I'm using make -j8 but it's still taking forever, I'll increase to -j16 next time

Is there caching between builds and only the first build will take this amount of time or is it going to take this long every time I make a single change?

[avivkeller]

I always build with ninja and ccache, and there's caching between builds for me, IIRC that's due to ccache.

[richardlau]

Does it reproduce if you configure process.report.excludeNetwork? (see #46060 for why that option was added.)

[Tofandel]

Yes it was in the description

This still happens even with node --report-exclude-network

Though it does look like the exact same issue and so it might not be fully solved

[avivkeller]

I'm curious, what does the profiling output look like? (node --prof <file> followed by node --prof-process <log file>)