Есть ли причина, по которой использование setTimeout в событии данных от дочернего процесса вызывает сколь угодно долгие задержки?

Проблема:

Я столкнулся со сценарием с использованием Javascript в NW.js, после чего setTimeout() будет испытывать сколь угодно долгие задержки вместо выполнения обратного вызова после запрошенной продолжительности. Как правило, от нескольких десятков миллисекунд до тысяч миллисекунд неожиданной задержки.

Конечно, setTimeout() не гарантирует, что он выполнит обратный вызов точно по запросу, но обычно это очень и очень близко к этому. Я ожидаю, что так будет всегда, пока основной поток не будет перегружен другими задачами. . Например, если я нажму F12, открою консоль браузера и запущу следующее:

var ts = Date.now();
setTimeout(function () {
  console.log(`This should run immediately! It took ${Date.now() - ts}ms`);
}, 0);

Я бы ожидал вывода, например:

This should run immediately! It took 1ms (возможно, 0-5 мс, в зависимости - но определенно очень мало времени, и повторяется, если вы запускаете его снова и снова)

Однако в вышеупомянутом сценарии задержка может быть значительной; часто на тысячи миллисекунд дольше, чем запрошенная продолжительность.

Сценарий:

Все, что для этого, по-видимому, требуется, это чтобы setTimeout() использовалось после события onData из дочернего процесса. Его можно использовать непосредственно в обратном вызове process.stdout.on('data') или через некоторое время в цепочке выполнения, которая может последовать. В обоих случаях setTimeout() ведет себя неправильно.

Ничто другое не ведет себя плохо; Javascript продолжает выполняться в обычном режиме, Promises разрешаются своевременно и т. д. и т. д. ... до тех пор, пока setTimeout() не задействован. Даже такие ужасные вещи, как использование циклов For для введения задержки вместо setTimeout(), будут работать надежно.

Я подготовил пример, который воспроизводит то, что я наблюдаю в своих системах, в надежде, что другие смогут протестировать его и посмотреть, возможно, я делаю что-то не так!

Я надеюсь, что кто-то обернется и скажет мне, что я что-то упустил из виду!

Пожалуйста, смотрите код ниже. Я пробовал это на нескольких машинах с таким же поведением. Обратите внимание, что приведенный тестовый пример является минимальным примером, который я обнаружил до сих пор, который воспроизводит проблему. Это не отражает того, что я на самом деле пытаюсь сделать на практике; вместо этого он просто пытается воспроизвести неподобающую проблему setTimeout(), с которой я столкнулся в своем проекте (и, насколько я могу судить, он ее воспроизводит).

Рабочий пример:

Для этого сценария требуется:

• NW.js: последний SDK 0.49.2, а также протестирован SDK 0.48.3 (такое же поведение)
• Python: последняя версия 3.9.0, также проверена версия 3.8.5 (такое же поведение)
• Windows: тестировались сборки v2004 (19041.508) и (19041.572) (такое же поведение)

Загрузите и разархивируйте соответствующий NW.js SDK, затем поместите следующие файлы в папку и запустите nw.exe. Вы должны увидеть белое окно; откройте devtools (F12) и выполните тест с помощью td.beginBasicTest():

пакет.json:

{
  "name": "STT",
  "description": "setTimeout Test",
  "main": "test.html",
  "node-remote": "http://127.0.0.1",
  "window": {
    "title": "test",    
    "show": true,
    "toolbar": true,
    "fullscreen": false,
    "width": 500,
    "height": 500,
    "frame": false,
    "position": "center",
    "resizeable": true
  },
  "dependencies": {    
  },
  "devDependencies": {},
  "chromium-args": "--password-store=basic --disable-pinch --disable-background-timer-throttling --disable-raf-throttling"
}

child_process.py:

#!/usr/bin/env python3
import sys
import asyncio
import json

class TestProcess:
    def __init__(self):
        self.alive = True
        self.run = True        
            
    def __hello(self):
        hello_msg = '{"resp": "hello"}'
        print(hello_msg, flush=True)
            
    async def __stdin_msg_handler(self, inp):
        # read the input command and respond accordingly
        if(len(inp) > 0):
            try:
                # convert from JSON to dict
                msg = json.loads(inp[0])
            except:
                # couldn't decode message; ignore it?
                print('{"resp":"badCommand"}', flush=True)
                msg = None
            if(msg):
                if(msg["cmd"] == "hello"):
                    self.__hello()

    async def __listen(self):
        line = await self.loop.run_in_executor(None, sys.stdin.readline)
        if(len(line) > 0):
            msgs = line.split("\r")
            return msgs
        else:            
            return False

    async def __loop(self):
        while self.run == True:
            msgs = await self.__listen()
            if(msgs):
                await self.__stdin_msg_handler(msgs)

    def start(self):
        self.loop = asyncio.get_event_loop()
        self.loop.run_until_complete(self.__loop())


if __name__ == '__main__':
    tproc = TestProcess()
    tproc.start()

тест.html:

<head>

<script>
const spawn = require(`child_process`).spawn; // ability to execute background tasks/commands

class TestDelay {
  constructor (delay = 5) {
    this.childProcessPath = `child_process.py`;
    this._startProcess();
  }

  beginBasicTest (delay = this.defaultDelay) {
    this._pTestProcedureWithComms(delay)
      .then(() => {
        console.log(`Test completed - did it work? Try it a few times, performance seems to vary...`);
      });
  }

  _startProcess () {
    this.childProcess = spawn(`py`, [`-3`, this.childProcessPath], { stdio: `pipe` });
    this.childRunning = true;

    this.childProcess.stdout.on(`data`, (d) => {
      console.log(`stdout: ${d}`);
      var ts = Date.now();
      setTimeout(function () {
        console.log(`This should run immediately! It took ${Date.now() - ts}ms`);
      }, 0);
      setTimeout(function () {
        console.log(`This should run after 5s! It took ${Date.now() - ts}ms`);
      }, 5000);
    });

    this.childProcess.stderr.on(`data`, (d) => {
      console.warn(`stderr: ${d}`);
    });

    this.childProcess.on(`exit`, (code) => {
      this.childRunning = false;
      console.log(`child process exited with code ${code}`);
    });

    this.childProcess.on(`close`, (code) => {
      console.log(`child process IO closed with code ${code}`);
    });
    console.log(`Started child process...`);
  }

  _pTestProcedureWithComms (delay = this.defaultDelay) {
    return new Promise(resolve => {
      this._pSendToProcess({ cmd: `hello` })
        .then(resolve);
    });
  }

  _pSendToProcess (text = ``) {
    return new Promise(resolve => {
      this.childProcess.stdin.write(JSON.stringify(text), `utf-8`);
      this.childProcess.stdin.write(`\n`, `utf-8`);
      resolve();
    });
  }
}

var td = new TestDelay();
</script>
</head>
<body>
Hello!
</body>

Когда я запускаю тесты несколько раз, я часто наблюдаю, что setTimeout ведет себя неправильно. Вот пример вывода, который я получил при выполнении теста несколько раз: