René's URL Explorer Experiment

{"@context":"https://schema.org","@type":"DiscussionForumPosting","headline":"Performance issue when sending large responses for concurrent requests","articleBody":"\u003c!--\r\nThank you for reporting an issue.\r\n\r\nThis issue tracker is for bugs and issues found within Node.js core.\r\nIf you require more general support please file an issue on our help\r\nrepo. https://github.com/nodejs/help\r\n\r\n\r\nPlease fill in as much of the template below as you're able.\r\n\r\nVersion: output of `node -v`\r\nPlatform: output of `uname -a` (UNIX), or output of `\"$([Environment]::OSVersion | ForEach-Object VersionString) $(if ([Environment]::Is64BitOperatingSystem) { \"x64\" } else { \"x86\" })\"` in PowerShell console (Windows)\r\nSubsystem: if known, please specify affected core module name\r\n--\u003e\r\n\r\n* **Version**: 12.20.1\r\n* **Platform**: Linux xxx 5.4.0-1038-aws #40~18.04.1-Ubuntu SMP Sat Feb 6 01:56:56 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux, or Darwin xxx 19.6.0 Darwin Kernel Version 19.6.0: Tue Jan 12 22:13:05 PST 2021; root:xnu-6153.141.16~1/RELEASE_X86_64 x86_64\r\n* **Subsystem**:\r\n\r\n### What steps will reproduce the bug?\r\n\r\n\u003c!--\r\nEnter details about your bug, preferably a simple code snippet that can be\r\nrun using `node` directly without installing third-party dependencies.\r\n--\u003e\r\n\r\n```\r\nconst express = require(\"express\");\r\n\r\nfunction makeBigObject(leaves, depth) {\r\n  if (depth === 0) {\r\n    return \"howdy\";\r\n  } else {\r\n    const ret = {};\r\n    for (let i = 0; i \u003c leaves; ++i) {\r\n      ret[i] = makeBigObject(leaves, depth - 1);\r\n    }\r\n    return ret;\r\n  }\r\n}\r\n\r\nfunction getTimeMs() {\r\n  return Date.now() - firstRequestStartTime;\r\n}\r\n\r\nconst app = express();\r\n\r\nconst bigObject = makeBigObject(2000, 2);\r\nlet requestCount = 0;\r\nlet firstRequestStartTime;\r\n\r\nasync function requestHandler({ requestIndex, req, res }) {\r\n  if (requestIndex === 1) {\r\n    firstRequestStartTime = Date.now();\r\n  }\r\n\r\n  console.log(\r\n    `[${getTimeMs()}] Serializing response for request ${requestIndex}...`\r\n  );\r\n  const serializedBigObject = JSON.stringify(bigObject);\r\n\r\n  const flushStartTimeMs = Date.now();\r\n  res.on(\"finish\", () =\u003e {\r\n    const flushDurationMs = Date.now() - flushStartTimeMs;\r\n    console.log(\r\n      `[${getTimeMs()}] -- Took ${flushDurationMs}ms to flush response for request ${requestIndex} --`\r\n    );\r\n  });\r\n\r\n  console.log(\r\n    `[${getTimeMs()}] Sending ${Math.round(\r\n      serializedBigObject.length / 1024 / 1024\r\n    )}MB response for request ${requestIndex}...`\r\n  );\r\n  res.send(serializedBigObject);\r\n  // res.send(\"ok\");\r\n\r\n  console.log(`[${getTimeMs()}] - Handler done for request ${requestIndex} -`);\r\n}\r\n\r\napp.get(\"/\", async (req, res) =\u003e {\r\n  const requestIndex = ++requestCount;\r\n  requestHandler({ requestIndex, req, res });\r\n});\r\n\r\napp.listen(\"/tmp/sock\", () =\u003e\r\n  console.log(`Example app listening on Unix domain socket /tmp/sock!`)\r\n);\r\n```\r\n\r\n### How often does it reproduce? Is there a required condition?\r\n\r\nSend multiple concurrent requests to the app. For example,\r\n\r\n(for x in $(seq 5); do time curl --unix-socket /tmp/sock http://localhost/ \u003e /dev/null \u0026 done)\r\n\r\n### What is the expected behavior?\r\n\r\n\u003c!--\r\nIf possible please provide textual output instead of screenshots.\r\n--\u003e\r\n\r\nI expect that responses are flushed fairly fast and early requests don't \"wait\" for later requests to flush together\r\n\r\n[0] Processing request 1...\r\n[23] Serializing response for request 1...\r\n[390] Sending 55MB response for request 1...\r\n[536] - Handler done for request 1 -\r\n[537] Processing request 2...\r\n[547] -- Took 158ms to flush response for request 1 --\r\n[558] Serializing response for request 2...\r\n[925] Sending 55MB response for request 2...\r\n[1065] - Handler done for request 2 -\r\n[1065] Processing request 3...\r\n[1077] -- Took 152ms to flush response for request 2 --\r\n[1086] Serializing response for request 3...\r\n[1444] Sending 55MB response for request 3...\r\n[1568] - Handler done for request 3 -\r\n[1568] Processing request 4...\r\n[1579] -- Took 135ms to flush response for request 3 --\r\n[1589] Serializing response for request 4...\r\n[1948] Sending 55MB response for request 4...\r\n[2075] - Handler done for request 4 -\r\n[2075] Processing request 5...\r\n[2087] -- Took 139ms to flush response for request 4 --\r\n[2096] Serializing response for request 5...\r\n[2455] Sending 55MB response for request 5...\r\n[2581] - Handler done for request 5 -\r\n[2591] -- Took 136ms to flush response for request 5 --\r\n\r\n\r\n### What do you see instead?\r\n\r\n\u003c!--\r\nIf possible please provide textual output instead of screenshots.\r\n--\u003e\r\n\r\nEarlier requests were blocked and not making progress until the later requests finished processing/serializing. The more concurrent requests, the longer the delay and the worse the problem is.\r\n\r\n[0] Serializing response for request 1...\r\n[334] Sending 55MB response for request 1...\r\n[491] - Handler done for request 1 -\r\n[492] Serializing response for request 2...\r\n[820] Sending 55MB response for request 2...\r\n[957] - Handler done for request 2 -\r\n[958] Serializing response for request 3...\r\n[1292] Sending 55MB response for request 3...\r\n[1430] - Handler done for request 3 -\r\n[1432] Serializing response for request 4...\r\n[1763] Sending 55MB response for request 4...\r\n[1902] - Handler done for request 4 -\r\n[1910] Serializing response for request 5...\r\n[2229] Sending 55MB response for request 5...\r\n[2371] - Handler done for request 5 -\r\n[2536] -- Took 773ms to flush response for request 4 --\r\n[2538] -- Took 309ms to flush response for request 5 --\r\n[2539] -- Took 1719ms to flush response for request 2 --\r\n[2540] -- Took 2206ms to flush response for request 1 --\r\n[2540] -- Took 1248ms to flush response for request 3 --\r\n\r\n### Additional information\r\n\r\n\u003c!--\r\nTell us anything else you think we should know.\r\n--\u003e\r\n\r\nif replacing res.send(serializedBigObject) with res.send(\"ok\"), then you get expected behavior. So response size matters.\r\n\r\n[0] Serializing response for request 1...\r\n[341] Sending 55MB response for request 1...\r\n[345] - Handler done for request 1 -\r\n[346] -- Took 5ms to flush response for request 1 --\r\n[348] Serializing response for request 2...\r\n[660] Sending 55MB response for request 2...\r\n[661] - Handler done for request 2 -\r\n[661] -- Took 1ms to flush response for request 2 --\r\n[661] Serializing response for request 3...\r\n[976] Sending 55MB response for request 3...\r\n[977] - Handler done for request 3 -\r\n[977] -- Took 1ms to flush response for request 3 --\r\n[977] Serializing response for request 4...\r\n[1296] Sending 55MB response for request 4...\r\n[1297] - Handler done for request 4 -\r\n[1297] -- Took 1ms to flush response for request 4 --\r\n[1297] Serializing response for request 5...\r\n[1633] Sending 55MB response for request 5...\r\n[1633] - Handler done for request 5 -\r\n[1634] -- Took 1ms to flush response for request 5 --\r\n","author":{"url":"https://github.com/xue-cai","@type":"Person","name":"xue-cai"},"datePublished":"2021-03-09T20:28:37.000Z","interactionStatistic":{"@type":"InteractionCounter","interactionType":"https://schema.org/CommentAction","userInteractionCount":9},"url":"https://github.com/37680/node/issues/37680"}