Why does setInterval never run, in my NodeJs code that streams an generator to file?

Question

I have this situation in my NodeJs code, which calculates permutations (code from here), but no matter what I don't get any output from setInterval.

const { Readable } = require('stream');
const { intervalToDuration, formatDuration, format } = require('date-fns');
const { subsetPerm } = require('./permutation');

function formatLogs(counter, permStart) {
    const newLocal = new Date();
    const streamTime = formatDuration(intervalToDuration({
        end: newLocal.getTime(),
        start: permStart.getTime()
    }));
    const formattedLogs = `wrote ${counter.toLocaleString()} patterns, after ${streamTime}`;
    return formattedLogs;
}

const ONE_MINUTES_IN_MS = 1 * 60 * 1000;

let progress = 0;
let timerCallCount = 1;
let start = new Date();
const interval = setInterval(() => {
    console.log(formatLogs(progress, start));
}, ONE_MINUTES_IN_MS);

const iterStream = Readable.from(subsetPerm(Object.keys(Array.from({ length: 200 })), 5));

console.log(`Stream started on: ${format(start, 'PPPPpppp')}`)
iterStream.on('data', () => {
    progress++;
    if (new Date().getTime() - start.getTime() >= (ONE_MINUTES_IN_MS * timerCallCount)) {
        console.log(`manual timer: ${formatLogs(progress, start)}`)
        timerCallCount++;
        if (timerCallCount >= 3) iterStream.destroy();
    }
});

iterStream.on('error', err => {
    console.log(err);
    clearInterval(interval);
});

iterStream.on('close', () => {
    console.log(`closed: ${formatLogs(progress, start)}`);
    clearInterval(interval);
})

console.log('done!');

But what I find is that it prints 'done!' (expected) and then the script seems to end, even though if I put a console.log in my on('data') callback I get data printed to the terminal. But even hours later the console.log in the setInterval never runs, as nothing ends up on file, besides the output from the on('close',...).

The output log looks like:

> node demo.js

Stream started on: Sunday, January 30th, 2022 at 5:40:50 PM GMT+00:00
done!
manual timer: wrote 24,722,912 patterns, after 1 minute
manual timer: wrote 49,503,623 patterns, after 2 minutes
closed: wrote 49,503,624 patterns, after 2 minutes

The timers in node guide has a section called 'leaving timeouts behind' which looked relevant. But where I though using interval.ref(); told the script to not garbage collect the object until .unref() is called on the same timeout object, on second reading that's not quite right, and doesn't make a difference.

I'm running this using npm like so npm run noodle which just points to the file.

@VikasKeskar `setTimeOut` should also block exit. Does it print anything other from `close` event? — ARIF MAHMUD RANA, Jan 30 '22 at 13:29
@ARIFMAHMUDRANA the close event does end up printing something — AncientSwordRage, Jan 30 '22 at 13:31
@AncientSwordRage that means `setInterval` gets `cleared` and don't get a chance to execute? — ARIF MAHMUD RANA, Jan 30 '22 at 13:35
@ARIFMAHMUDRANA but the total time elapsed is much longer than the interval, i.e. it might take 3 hours to run, and the interval is ~10 minutes — AncientSwordRage, Jan 30 '22 at 13:36
@AncientSwordRage can you give something a simple prototype so that everyone can tinker? Otherwise difficult to debug. — ARIF MAHMUD RANA, Jan 30 '22 at 13:44

AncientSwordRage · Answer 1 · 2022-02-04T15:05:36.933

The generator is synchronous and blocks the event loop

Readable.from processes the whole generator in one go, so if the generator is synchronous and long running it blocks the event loop.

Here is the annotated code that it runs:

async function next() {
    for (;;) {
      try {
        const { value, done } = isAsync ?
          await iterator.next() : // our generator is not asynchronous
          iterator.next();

        if (done) {
          readable.push(null); // generator not done
        } else {
          const res = (value &&
            typeof value.then === 'function') ?
            await value :
            value; // not a thenable
          if (res === null) {
            reading = false;
            throw new ERR_STREAM_NULL_VALUES();
          } else if (readable.push(res)) { // readable.push returns false if it's been paused, or some other irrelevant cases.
            continue; // we continue to the next item in the iterator
          } else {
            reading = false;
          }
        }
      } catch (err) {
        readable.destroy(err);
      }
      break;
    }
  }

Here is the api for readable.push, which explains how this keeps the generator running:

Returns: true if additional chunks of data may continue to be pushed; false otherwise.

Nothing has told NodeJs not to continue pushing data, so it carries on.

Between each run of the event loop, Node.js checks if it is waiting for any asynchronous I/O or timers and shuts down cleanly if there are not any.

I raised this as a NodeJs Github Issue and ended up workshopping this solution:

cosnt yieldEvery = 1e5;

function setImmediatePromise() {
    return new Promise(resolve => setImmediate(resolve));
}

const iterStream = Readable.from(async function* () {
    let i = 0
    for await (const item of baseGenerator) {
        yield item;
        i++;
        if (i % yieldEvery === 0) await setImmediatePromise();
    }
}());

This is partly inspired by this snyk.io blog, which goes into more detail on this issue.

Why does setInterval never run, in my NodeJs code that streams an generator to file?

1 Answers1

The generator is synchronous and blocks the event loop

Linked