Bug: Bad execution time for large number of calls on Mutex.runExclusive

[Zomono]

Hi,
I have some trouble with some unit tests taking a lot of time. The problem seems to be related to some methods that are surrounded with runExclusively from a Mutex. I created this test case showing some problems with the performance of runExclusive in combinations with a delayed method.

    const mutex = new Mutex()
    const lockMethod = () => new Promise(resolve => setTimeout(() => resolve(undefined), 0))
    const promises = _.range(0, 1000).map(() => mutex.runExclusive(lockMethod))
    // const promises = _.range(0, 1000).map(() => lockMethod())
    // without lodash use:  [...Array(1000).keys()].map(...)
    await Promise.all(promises)

The test tooks 13seconds on my maschine to complete, while the same test competes in milliseconds if runExclusively is removed from the test. If you increase the number calls it gets even worse.

I am expecting the test to also complete in milliseconds while the Mutex is used.

Im running async-mutex 0.3.2, NodeJS 17.3, Windows 10, jest 27.4.7
If you need more information let me know.
Thanks

[DirtyHairy]

That's not a bug, but a consequence of the mutex is doing its job. What happens is that you are serializing the 1000 setTimeout invocations. setTimeout has a non-negligible granularity, and that is what you are measuring. If you remove the mutex, then all setTimeout calls are scheduled at once, and you will get a much smaller number. As a reference, check out the following test program:

const {Mutex} = require('async-mutex');

const ITERATIONS = 10000;

const case1 = (iter, schedule) => new Promise(resolve => {
    const f = () => iter-- > 0 ? schedule(f) : resolve();
    f();
});

const case2 = (iter, schedule) => {
    const mutex = new Mutex();

    return Promise.all(new Array(iter)
        .fill(0)
        .map(() => mutex.runExclusive(
            () => new Promise(resolve => schedule(resolve)))
        )
    );
}

async function time(fun) {
    timestamp = Date.now();
    await fun();
    return Date.now() - timestamp;
}

async function main() {
    const scheduleSetTimeout = f => setTimeout(f, 0);
    const scheduleMicrotask = f => Promise.resolve().then(f);

    console.log(`setTimeout, plain: ${await time(() => case1(ITERATIONS, scheduleSetTimeout))} msec`);
    console.log(`setTimeout, mutex::runExclusive: ${await time(() => case2(ITERATIONS, scheduleSetTimeout))} msec`);

    console.log(`microtask, plain: ${await time(() => case1(ITERATIONS, scheduleMicrotask))} msec`);
    console.log(`microtask, mutex::runExclusive: ${await time(() => case2(ITERATIONS, scheduleMicrotask))} msec`);
}

main();

It performs the same test as you do, the first time by directly chaining the setTimeout invocations, and the second time using the mutex. It also reruns the same tests with Promise.resolve().then(...) for scheduling. These numbers are much smaller and give you a better feeling for the overhead of the library. This is the result on my laptop:

setTimeout, plain: 13179 msec
setTimeout, mutex::runExclusive: 14020 msec
microtask, plain: 25 msec
microtask, mutex::runExclusive: 70 msec

[Zomono]

Sorry for missing the parralle execution fact In the test scenario provided above. Originally the test cases are intended to be both sequential. However, with your hint I created the following code snippet,

for (let i = 0; i < 1000; i++) {
    await new Promise(resolve => setTimeout(() => resolve(undefined), 0))
}

which has the same poor performance. It shows that the problem is not related to this library.
Thanks for greate library and the quick response.

But I don't know why setTimeout has such a large delay (13-14ms on my maschine)

[DirtyHairy]

That I cannot answer 😏 However, afaik there is no guranteed granularity or accuracy for setTimeout, and the details depend on the execution environment (JS engine, OS, workload).