Simple server stops responding after 16000+ requests for multiple seconds

[matus-vacula]

Version

v18.16.0

Platform

Darwin *** 22.3.0 Darwin Kernel Version 22.3.0: Mon Jan 30 20:38:43 PST 2023; root:xnu-8792.81.3~2/RELEASE_ARM64_T8112 arm64

Subsystem

net

What steps will reproduce the bug?

When running a simple server, after 16300+ requests program stops responding for multiple seconds with what seems like a large GC pause.

var net = require('node:net');
var server = net.createServer(function (socket) {
    socket.on('data', function (data) {
        var request = data.toString();
        console.log(new Date().toISOString() + ' request');
        if (request.startsWith('GET /endpoint')) {
            var response = 'HTTP/1.1 200 OK\r\n\r\n';
            socket.write(response);
            socket.end();
        }
    });
    socket.on('end', function () {
        console.log('Connection ended');
    });
});
var port = 5500;
server.listen(port, '0.0.0.0', function () {
    console.log("NET Server is running at http://localhost:".concat(port));
});

node --trace_gc app.js

ab -m GET -n 100000 -c 1 http://127.0.0.1:5500/endpoint

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

It happens every time I run ab with more than 16300+ requests on Apple M2 Macbook. I couldn't reproduce this on a laptop with ubuntu installed.

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

The program should continue serving the requests.

What do you see instead?

When running a simple server, after 16000+ requests program stops responding for multiple seconds with what seems like a large GC pause.

$ node --trace_gc app.js

...
...
...

Connection ended
2023-05-15T07:55:36.967Z request
Connection ended
2023-05-15T07:55:36.967Z request
Connection ended
2023-05-15T07:55:43.677Z request
Connection ended
[92609:0x128078000]    14098 ms: Mark-sweep (reduce) 7.8 (44.1) -> 4.7 (7.3) MB, 2.8 / 0.0 ms  (+ 3.3 ms in 22 steps since start of marking, biggest step 0.4 ms, walltime since start of marking 7 ms) (average mu = 0.999, current mu = 0.999) finalize incremental marking via task; GC in old space requested
[92609:0x128078000]    14705 ms: Mark-sweep (reduce) 4.7 (7.3) -> 4.6 (6.8) MB, 2.3 / 0.0 ms  (+ 3.0 ms in 20 steps since start of marking, biggest step 0.3 ms, walltime since start of marking 6 ms) (average mu = 0.998, current mu = 0.991) finalize incremental marking via task; GC in old space requested

$ ab -m GET -n 100000 -c 1 http://127.0.0.1:5500/endpoint
This is ApacheBench, Version 2.3 <$Revision: 1901567 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking 127.0.0.1 (be patient)
Completed 10000 requests
apr_socket_recv: Operation timed out (60)
Total of 16328 requests completed

Additional information

It seems to be happening on multiple versions of Node (tried 16 and 18). Also happening on M1 Macbook Pro with 16,18,20

[bnoordhuis]

I don't see a large GC pause. The last two take only ~3 ms.

You're probably looking at the first number (14705 ms) but that's time since program start.

[matus-vacula]

It's possible that the GC pause might be a red herring. The thing is that the program stops responding to requests for some time and there is a higher probability that GC message appears here (since there are no more request logs present at the time).

[bnoordhuis]

GC is a more or less continuous activity so that's not surprising.

You're probably running out of ephemeral ports; 16,000 is around the usual range on most systems. ab is also an infamously terrible benchmarking tool; try e.g. wrk instead.

Last but not least, benchmarking on macOS is like trying to drive a Ferrari on a dirt road. Try tarmac^WLinux instead.

I see no reason to suspect a node bug so far so I'll go ahead and convert this to a discussion.