Why is execution time of this function increasing?

Question

I have following code:

fetchAsync().then()

async function fetchAsync() {
    return await Promise.all([...Array(1000).keys()].map((i) => wait(i)))
}

async function wait(i) {
    const startTime = Date.now();
    await new Promise(resolve => {
        setTimeout(() => resolve(), 100)
    });
    const timePassed = Date.now() - startTime;

    console.log(`Call ${i}: ${timePassed}ms`)
}

Console output is

Call 0: 102ms
Call 1: 108ms 
Call 2: 109ms 
Call 3: 109ms 
Call 4: 109ms 
Call 5: 110ms
...
Call 995: 190ms
Call 996: 190ms
Call 997: 190ms
Call 998: 190ms
Call 999: 190ms

As you can see, the execution time of wait is increasing every time its being executed. Does anyone know why this is happening?

Have a read https://stackoverflow.com/questions/34691428/javascript-event-queue-and-settimeout — Suraj Rao, Apr 18 '23 at 12:05
Does it happen if you use real code, rather than one that mostly produces an increased load on the garbage collector? — VLAZ, Apr 18 '23 at 12:08
@VLAZ What exactly do you mean with "real code"? The code above has no real purpose for me, i just wanted to try something and realized this sideeffect. — Jan, Apr 18 '23 at 12:12
Real code - code that is used in a real application solving a real problem. The code above is not that. It demonstrates a behaviour but, IMO, mostly demonstrates GC. It generates a lot of objects that will need to be garbage collected. So, the slowdown might just be down to GC runs. Which probably won't happen if you have code that doesn't just churn out objects and immediately orphan them. — VLAZ, Apr 18 '23 at 12:15
Alright. I'm aware that this is no productive example. You may be right that this could be a problem with the GC rsp. because the fact from @SurajRao answer. Thanks anyways for the explanation! — Jan, Apr 18 '23 at 12:25
@VLAZ I don't think the code places considerable load on the GC. It creates only a few 1000 objects, mostly promises and closures. — Bergi, Apr 18 '23 at 12:53
`console.log` can be quite expensive. I'd think most of the time of the extra 90ms is spent flushing a 1000 lines of output to the terminal or debugger. — Bergi, Apr 18 '23 at 12:57
@Bergi My point is that it mostly generates things that will be GC'd. Rather than doing anything actually realistic. — VLAZ, Apr 18 '23 at 13:02
@Bergi I don't think console.log is the problem here. The execution time increases relatively linear. Assuming console.log takes ~90ms, wouldn't the frist request also be aproximately 190ms? — Jan, Apr 18 '23 at 13:09
@VLAZ My understanding of GC is that as soon as a reference to an object is released, it gets "collected". What I not really understand is why this should have an impact on the executed code from my question. — Jan, Apr 18 '23 at 13:11
@Jan I mean that 1000 `console.log` calls together take 90ms, not that each call takes 90ms. The `map` loop is creating a 1000 `startTime` dates, a 1000 promises, and makes a 1000 calls to `setTimeout`. This happens more or less at once. Then all the timeouts are waiting 100ms (concurrently). Then for each timeout, it calls `resolve`, resumes the async function, takes the `timePassed` and `console.log`s it. These steps are executed a 1000 times, one after the other. The time each `console.log` takes (around 0.1ms?) accumulates. — Bergi, Apr 18 '23 at 13:11
@Bergi That would confirm the answer from SurajRao wouldn't it? — Jan, Apr 18 '23 at 13:13
"*as soon as a reference to an object is released, it gets "collected".*" no, when an object has no more references to it it is ***eligible** for collection*. It doesn't get garbage collected immediately. GC runs whenever it is needed. Increasing the amount of objects being created does often lead to more frequent and more expensive GC runs. With that said, I don't really think it's worth dwelling on this code. Again - it's not real. Insights need not apply to any real use case. — VLAZ, Apr 18 '23 at 13:14
@Jan Not sure how the question linked by SurajRao relates to your code. I mean, yes, it shows that the `setTimeout` callback waits for other code to finish, but in your case it's not a busy-waiting loop but rather 999 other callbacks. — Bergi, Apr 18 '23 at 13:17
@Bergi It explains setTimeout. Until now, i thought node would create a new thread for every setTimeout. Obviously it does not. Instead, as you and the linked question explains, it will execute its callbacks one after each other — Jan, Apr 18 '23 at 13:21
@Bergi I just tried to evaluate this theory by copy pasting the code rather than using `Promise.all`. Now the execution time is straight 100ms. This would speak against setTimeout to be the reason. I read your explanation again and I think I missunderstood your point. Do I understand it now right that all callbacks of `setTimeout` are executed "simultaneously" rsp. after each other because no multithreading is happening? — Jan, Apr 18 '23 at 13:40
Yes, there is no multithreading, everything is executed one after the other. Not sure what you mean by "copy-pasting the code" — Bergi, Apr 18 '23 at 13:44

score 0 · Accepted Answer · answered Apr 18 '23 at 17:25

It's because you are calling console.log inside wait. IO is a costly operation and items deeper in your array have to wait for IO for all items occurring before. Use a single console.log to see that each items actually takes the same amount of time -

fetchAsync().then(console.log) // single console.log

function fetchAsync() {
  return Promise.all(Array.from(Array(1000), (_,i) => wait(i)))
}

async function wait(i) {
  const startTime = Date.now();
  await new Promise(r => setTimeout(r, 100))
  return `Call ${i}: ${Date.now() - startTime}ms`; // return
}

.as-console-wrapper { min-height: 100%; top: 0; }

Why is execution time of this function increasing?

1 Answers1