Why is request.on data firing with a delay on NodeJS?

Question

There is a simple web server that accepts data. Sample code below.

The idea is to track in real time how much data has entered the server and immediately inform the client about this. If you send a small amount of data, then everything works well, but if you send more than X data in size, then the on.data event on the server is triggered with a huge delay. I can see that data is transfering for 5 seconds already but on.data event is not trigerred. on.data event seems to be triggered only when data is uploaded completely to the server, so that's why it works fine with small data (~2..20Mb), but with big data (50..200Mb) it doesnt work well. Or maybe it is due to some kind of buffering..? Do you have any suggestions why on.data triggered with delay and how to fix it?

const app = express();
const port = 3000;

// PUBLIC API

// upload file 
app.post('/upload', function (request, response) {
    request.on('data', chunk => {
        // message appears with delay
        console.log('upload on data', chunk.length);

        // send message to the client about chunk.length
        
    });

    response.send({
        message: `Got a POST request ${request.headers['content-length']}`
    });
});

app.listen(port, () => {
    console.log(`Example app listening at http://localhost:${port}`);
});

Answer 1

I found a problem. It was in nginx config. Nginx was setup like a reverse proxy. By default proxy request buffering is enabled, so nginx grabs first whole request body and only then forwards it to nodejs, so that's why I saw delay.

https://nginx.org/en/docs/http/ngx_http_proxy_module.html#proxy_request_buffering

Answer 2

TLDR:

The delay that you are experiencing probably is the Queueing from Resource scheduling from the browser.

The Test

I did some tests with express, and then I found that it uses http to handle requests/response, so I used a raw http server listener to test this scenario, which has the same situation.

Backend code

This code, based on sample of Node transaction samples, will create a http server and give log of time on 3 situations:

• When a request was received
• When the first data event fires
• When the end event fires

const http = require('http');

var firstByte = null;
var server = http.createServer((request, response) => {
    const { headers, method, url } = request;
    let body = [];
    request.on('error', (err) => {
    }).on('data', (chunk) => {
        if (!firstByte) {
            firstByte = Date.now();
            console.log('received first byte at: ' + Date.now());
        }
    }).on('end', () => {
        console.log('end receive data at: ' + Date.now());
        // body = Buffer.concat(body).toString();
        // At this point, we have the headers, method, url and body, and can now
        // do whatever we need to in order to respond to this request.

        if (url === '/') {
            response.statusCode = 200;
            response.setHeader('Content-Type', 'text/html');
            response.write('<h1>Hello World</h1>');
        }
        firstByte = null;
        response.end();
    });
    console.log('received a request at: ' + Date.now());
});

server.listen(8083);

Frontend code (snnipet from devtools)

This code will fire a upload to /upload which some array data, I filled the array before with random bytes, but then I removed and see that it did not have any affect on my timing log, so yes.. the upload content for now is just an array of 0's.

console.log('building data');

var view = new Uint32Array(new Array(5 * 1024 * 1024));
console.log('start sending at: ' + Date.now());
fetch("/upload", {
    body: view,
    method: "post"
}).then(async response => {
    const text = await response.text();
    console.log('got response: ' + text);
});

Now running the backend code and then running the frontend code I get some log.

Log capture (screenshots)

The Backend log and frontend log:

The time differences between backend and frontend:

Results

looking at the screenshoots and I get two differences between the logs:

• The first, and most important, is the difference between frontend fetch start and backend request recevied, I got 1613ms which is "close" (1430ms) to Resource Scheduling in network timing tab, I think there are more things happening between the frontend fetch call and the node backend event, so I can't direct compare the times:

log.backendReceivedRequest - log.frontEndStart
1613

• The second is the difference between receving data on backend, which I got 578ms, close to Request sent (585ms) in network timing tab:

log.backendReceivedAllData - log.backendReceivedFirstData
578

I also changed the frontend code to send different sizes of data and the network timing tab still matches the log

The thing that remains unknown for me is... Why does Google Chrome is queueing my fetch since I'm not running any more requests and not using the bandwidth of the server/host? I readed the conditions for Queueing but not found the reason, maybe is allocating the resources on disk, but not sure: https://developer.chrome.com/docs/devtools/network/reference/#timing-explanation

References:

https://nodejs.org/es/docs/guides/anatomy-of-an-http-transaction/ https://developer.chrome.com/docs/devtools/network/reference/#timing-explanation