`process.report.getReport();` is potentially very slow

[adesso-os]

Version

v18.12.1

Platform

Linux DE-ADN-2GPTTQ3 5.15.79.1-microsoft-standard-WSL2 #1 SMP Wed Nov 23 01:01:46 UTC 2022 x86_64 GNU/Linux

Subsystem

report

What steps will reproduce the bug?

Calling process.report.getReport(); is all it takes. The call will not return for longer than 1 minute, if the failure conditions are met.

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

The issue is 100% reproducible within scenarios I can only construct with our private code bases so far.

I am seeing this as part of the package installation process of yarn, which call process.report.getReport(); internally. This usually takes less than a second, but in certain scenarios, it takes more than a minute.

What is the expected behavior?

The call should return reliably within a timely fashion, not consuming more than 2-3 seconds.

What do you see instead?

Node hangs for more than a minute and is completely unresponsive.

Additional information

While looking into this issue, I found this comment in the source code of yarn:

    // Doing these calls early is important: it seems calling it after we've started the resolution incurs very high
    // performance penalty on WSL, with the Gatsby benchmark jumping from ~28s to ~130s. It's possible this is due to
    // the number of async tasks being listed in the report, although it's strange this doesn't occur on other systems.

These comments are above the code path that leats to the report being generated. This suggests that the behavior is a WSL-specific issue. Assuming that's the case, I'd still like to get better insights into the root cause.

[adesso-os]

From what I can tell so far with my limited understanding of Node internals, the report is delayed by the generation of the libuv section.

To generate this section, all open handles will be inspected and information about them is attached to the report. The handles that cause the majority of the delay are the ones relating to sockets. There seem to be at least 20+ open sockets at the time the report is generated.

node/src/node_report_utils.cc

Line 12 in a03529d

static void ReportEndpoint(uv_handle_t* h,

reads like this might try to retrieve the hostname for the IP address on that socket, but I might be misreading that source.

I must assume the DNS queries take especially long in my environment for this to be this problematic, but I also feel like it might not be ideal to run DNS lookups in a fully synchronous code path. I got the impression that generating the report should be fairly quick. So any chance to introduce minute-long delays should likely be avoided.

[oliversalzburg]

This code reproduces the issue reliably on one of my systems:

const https = require("node:https");

const SOCKET_COUNT = 10;
const sockets = [];
let allResolved = false;

const keepAliveAgent = new https.Agent({ keepAlive: true });

const performRequest = () => {
  const socketPromise = new Promise((resolve) => {
    https
      .get(
        {
          agent: keepAliveAgent,
          hostname: "registry.npmjs.org",
        },
        () => {
          process.stdout.write(".");
          resolve();
        }
      )
      .on("error", (error) => {
        console.error(error);
        resolve();
      });
  });
  sockets.push(socketPromise);
};

process.stdout.write(`${new Date().toISOString()} opening ${SOCKET_COUNT} sockets`);
for (let loops = 0; loops < SOCKET_COUNT; ++loops) {
  performRequest();
}

Promise.all(sockets).then(() => {
  allResolved = true;
  console.log(
    `\n${new Date().toISOString()} all sockets created. requesting report...`
  );
  process.report.getReport();

  console.log(`${new Date().toISOString()} destroying client`);
  keepAliveAgent.destroy();

  console.log(`${new Date().toISOString()} end`);
});

const check = () => {
  if (!allResolved) {
    setTimeout(check, 200);
    return;
  }
};

check();

On this system, it takes about 20s to generate the report.

[cjihrig]

FWIW, on my machine (M1 MBP), the report is generated in much less than one second.

[oliversalzburg]

FWIW, on my machine (M1 MBP), the report is generated in much less than one second.

Interesting. It was suggested in the yarn source that this is somehow WSL-specific. So far, I'm having a hard time understanding what aspect of WSL would introduce this, but I also haven't compared with non-WSL Linuxes yet.

[oliversalzburg]

After playing around a bit at https://github.com/oliversalzburg/report-repro/, I can see that RDNS is being performed on the addresses of all open sockets. With a large enough number of sockets, I could also push the report generation over the multi-second mark in GitHub Actions on ubuntu-latest.

I still feel like this is problematic, but the behavior is certainly amplified in WSL. The default behavior of which is to register an internal DNS resolver into /etc/resolv.conf, which seems to perform poorly. I assume the idea here is to allow resolution of names on the local network.

When I inspect the answers from this resolver, the problem also becomes clearer:

$ dig -x 1.1.1.1 @172.22.176.1 +noall +answer
1.1.1.1.in-addr.arpa.   0       IN      PTR     one.one.one.one.

$ dig -x 1.1.1.1 @8.8.8.8 +noall +answer
1.1.1.1.in-addr.arpa.   1006    IN      PTR     one.one.one.one.

The WSL resolver will set the TTL of all answers to 0, which prevents any DNS caching and the resolution will have to be done over and over for all open sockets.

A workaround is to configure a different DNS server for the WSL environment. https://learn.microsoft.com/en-us/windows/wsl/wsl-config#network-settings

[adesso-os]

I also reported this for WSL: microsoft/WSL#9423

[bnoordhuis]

@cjihrig I can reproduce (on Linux) when I blackhole outgoing DNS traffic.

It's the uv_getnameinfo() calls that are problematic - every socket adds a 30s delay - but I can see why you'd want the report to have that info. Tough call.

[joyeecheung]

Perhaps we can add an option to process.report.getReport() to not do DNS queries (or any other operations that rely on stable network configurations)? Or an environment variable that is effective for all the other report triggers?

[arcanis]

Some users have reported 6.5 minutes of install time when running yarn install due to getReport:

[lpic10]

I was facing similar issue when using yarn v2 on a Ubuntu VM with hyper-v, instead of wsl.

Thanks to the code by @oliversalzburg to reproduce the issue I found that the systemd-resolved was the culprit and this thread helped me to find a workaround: systemd/systemd#28166

Maybe this can help someone with similar setup as mine:

• disable multicast DNS and LLMNR by editing /etc/systemd/resolved.conf as below

MulticastDNS=no
LLMNR=no

• restart systemd-resolved

systemctl restart systemd-resolved