CPU-bound process blocks worker pool while using Child Process in NestJS HTTP server

Question

Node version: v10.13.0

I'm trying a very simple test on NodeJS request concurrency involving heavy CPU-calculation. I understand NodeJS is not the best tool for CPU-bound processes, and that a child process should not be spawned systematically, but this code is for the sake of testing how the child process works. Also this is written in TypeScript, using NestJS.

src/app.controller.ts

import { Get, Param, Controller } from '@nestjs/common';
import fork = require('child_process');

@Controller()
export class AppController {
  @Get()
  async root(): Promise<string> {
    let promise = new Promise<string>(
        (resolve, reject) => {
          // spawn new child process
          const process = fork.fork('./src/cpu-intensive.ts');
          process.on('message', (message) => {
            // when process finished, resolve
            resolve( message.result);
          });
          process.send({});    
        }
    );    
    return await promise;
  }
}

src/cpu-intensive.ts

process.on('message', async (message) => {
  // simulates a 10s-long process
  let now = new Date().getTime();
  let waittime = 10000; // 10 seconds
  while (new Date().getTime() < now + waittime) { /* do nothing */ };
  // send response to master process
  process.send({ result: 'Process ended' });
});

Such a long process, if executed without spawning new child processes, leads to this timeline of results, with 5 concurrent requests (noted from #1 to #5). Each process blocking the loop-event, each request has to wait for the previous ones to complete to be answered.

Time 0    10   20   30   40   50
#1   +----+
#2   +----+----+
#3   +----+----+----+
#4   +----+----+----+----+
#5   +----+----+----+----+----+

While spawning new child processes, I was expecting each process would be handled concurrently by a different logical core on my CPU (mine has 8 logical cores), leading to this predicted timeline:

Time 0    10   20   30   40   50
#1   +----+
#2   +----+
#3   +----+
#4   +----+
#5   +----+

Though, I observe this strange result on each test:

Time 0    10   20   30   40   50
#1   +----+
#2   +----+----+
#3   +----+----+----+
#4   +----+----+----++
#5   +----+----+----+-+

The first 3 requests act as if the worker pool was starved, though I'd assume that 3 different pools would have been created. The 2 last requests are very confusing, as they act like working concurrently with request #3.

I'm currently looking for an explanation for:

• why the first 3 requests don't act as if running concurrently
• why the last 3 requests act as if running concurrently

---

Please note that if I add another 'fast' method as follows:

  @Get('fast')
  async fast(): Promise<string> {
    return 'Fast process ended.';
  }

this method is not impacted by the CPU-intensive processes run in concurrency, and replies always instantly.

Defensive

Got any updates? – Phenyl

are you getting these results consistently every time? – Paternalism

As far i understand this is because of when we are invoking child process and start performing cpu intensive work so at that time our main thread is performing sync operation, so it is not able to handle the response from child process and when main thread completed its work after that it is able to handle the response from child process. All of the operation are executing parallely but the main thread is not able to handle response because of sync op. going on it. I hope it make sense. For POC you can do some operation in child process n check that operation is done in start time. – Shinbone

For more detail you can read this node issue github.com/nodejs/node/issues/14917 – Shinbone

@mihai: yes, it's consistent – Defensive

@Aabid: I checked the issue you posted, I understand there might be some blocking on the event loop done by spawn(). Yet, I've got a hard time to correlate that with my "3 first requests blocked; 3 last concurrently processed". Maybe I lost you somewhere? – Defensive

@Defensive Check answer i have performed test case in js – Shinbone

Answer 1

I performed test case on my machine and its working fine can you check that on your machine.

Node Version: v8.11.2 OS: macOs High Sierra 10.13.4, 8 Cores

child-process-test.js

const child_process = require('child_process');  
for(let i=0; i<8; i++) {  
    console.log('Start Child Process:',i,(new Date()));
    let worker_process = child_process.fork("cpu-intensive-child.js", [i]);    
    worker_process.on('close', function (code) {  
        console.log('End Child Process:', i , (new Date()), code);  
    });
}

cpu-intensive-child.js

const fs = require('fs');
// simulates a 10s-long process
let now = new Date().getTime();
let waittime = 10000; // 10 seconds
while (new Date().getTime() < now + waittime) { /* do nothing */ };
// send response to master process
// process.send({ result: 'Process ended' });

Output

You can check in output the difference is only 10 sec for all the process, you can perform this test case on you machine and let me know, may be it can help.

Shinbone

It does work indeed. Yet that's not the same use case, because there's no external-event handling here, right? Thanks for your efforts! – Defensive

Yes, there is no external event handling in this. In your use case you have created a http-server else there is no difference. I think both should work same. – Shinbone

They probably should, but they don't, not using NestJS as I did. So there must be something on the http server layer that produces the strange behavior I described? At least you highlighted that it was not the child_process that causes it. I'll try to reduce the use case (not using NestJS seed directly). – Defensive