Binary plugin using libevent stalls node event loop

[martenrichter]

Version

v16.16.0

Platform

Microsoft Windows NT 10.0.19044.0 x64

Subsystem

Main event loop? webstreams?

What steps will reproduce the bug?

Ok, I am not completely sure, if it is really a bug, probably it is related to the event loop. (So may be it should belong to the support category).

I am currently writing a plugin, which uses the quiche library to provide http/3 webtransport support for node., I am currently working to get it to work on windows (https://github.com/fails-components/webtransport/tree/windows).
It runs fine on Linux.
But on windows, after data packets are enqueued to the readable stream (see npm test on the windows branch), they take sometimes seconds (!) to be passed to the await from the reader.
Steps to reproduce, install the windows branch, let the library compile (MSVc build tools including clang-cl required) and run npm test.

For example:
incom ud <Buffer 4d 4e 4f> 1657995037760
incom ud <Buffer 50 51 52> 1657995042771

two datagrams received enqueue almost at the same time (I inspected the time), but emitted after 10 s delay (last number is Date.now())

However, if I include a setInterval( ) function with a short interval I do not see these stalls.
So it seems, that the result from enqueue or maybe the promise is not handled in the event loop cycle and the setInterval just triggers the event loop to break and do the remaining tasks.

How often does it reproduce? Is there a required condition?

Every run with different stalls length, at least one-third of output is stalled.

What is the expected behavior?

No stalls of the event loop, time should only differ by some ms.

What do you see instead?

Delays in of multiples of seconds.

Additional information

The library uses libevent for the http/3 event loop. So I fear, that it interferes with the libuv event loop is this possible? Or what else could cause the behavior?

[martenrichter]

I thought about it again, the enqueue is called from a c++ worker, so under the hood uv_async is scheduling the callback to the enqueue. Is it possible that it ( async callback) is executed in the event loop at a point, where the newly created callbacks inside enqueue do not cause poll to return immediately?

[martenrichter]

Ok, adding inside all callbacks, which are called from the c++ worker (so the libuv async callback effectively) around the function body, a setImmediate, the problem is gone. But of course, the enqueue is then postponed.
A setTimeout(..., 0) also does the trick. Is this the correct behavior? If yes the issue can be closed.

[bnoordhuis]

I can't answer your question without looking at your code in detail (which I'm not going to do because time) but the behavior you describe sounds like a classic case of assuming 1 uv_async_send() call == 1 uv_async_cb call. There's no such relation, libuv can and will coalesce uv_async_send() calls into a single callback call.

I'll convert this to a discussion.

[martenrichter]

Thanks for the pointer. But no this is not the case. It uses AsyncProgressQueueWorker<Http3ProgressReport> template underneath from nan.h. As far as I understand, it takes care of this issue of coalescing calls.
So I still believe, it is caused that some new callbacks are not scheduled.
At least the setImmediate workaround is doing will on Windows and Linux. n mac I do not know yet..., it might stall there because of the setImmediate.

[bnoordhuis]

A simple thing you can try is add your own uv_async_t handle and call uv_async_send() when you push an item onto the progress queue. If your own callback is called much sooner than the progress worker's, that tells you something.

[martenrichter]

I can try this. But the callback from the ProgressWorker is called on time. (Few ms from Date.now() at max.)
Only the callbacks that are generated by the ProgressWorker's callback (inside the ReadableController.enqueue) are not called before the poll stalls.
As if the called js javascript generates callbacks and the event loop does not recognize this.
Should I do the test anyway?

[martenrichter]

May be I should add some pseudo code:
ProgressWorkerQueue --> uses uv_async_send internally -> C++ code calls via V8 a callback on js side this calls on time couple other functions callbacks and at the end calls ReadableControllers.enqueue (WhatWG Stream), until then the time progression is ok.

The reader with await unidiReader.read() exits at every second call after a couple of seconds and not immediately.
It is a unit test, so nothing that can cause an exit of the poll loop is present. (in fact two pakets are arrive via the progressworker shortly one after another and it happens between them).

So the problem occurs between the enqueue and the await. I am not sure, if the stream implementation exit javascript or if it is a problem purely within V8.

[martenrichter]

Ok, here is the test:

TEST 1: start
stream read received <Buffer 41 42 43> 1658296018498
stream read received <Buffer 44 45 46> 1658296018499
asynccallback 1658296018502
stream read received <Buffer 41 42 43> 1658296018502
incoming bidi stream <Buffer 41 42 43> 1658296018503
asynccallback 1658296018506
stream read received <Buffer 44 45 46> 1658296018508
asynccallback 1658296018539
incoming bidi stream <Buffer 44 45 46> 1658296020496
all bidi received, next close writer
All data has been sent.
next close reader
All data has been read.
webtransport sending bidistream success
TEST 1: finish

Here, stream read received is inside a javascript function called from the ProgressQueueWorker for reporting the progress, time comes from Date.now(). Since it is an echo server you see them twice as often as the final receipt in the incoming bidi stream from the stream.
The asynccallback is from an async handle triggered at the same time, something is put into the ProgressWorker queue, time measured using std::chrono::system_clock::now() (of course there are fewer because of the coalescing).
incoming bidi stream is printed after the await reader.read() call with Date.now() .
The delay goes away if I put a setImmediate before the stream read received.

[martenrichter]

Another pointer, all io is coming from the binary plugin. So there is no socket on the libuv loop that will fire, except for the timers, etc.

[martenrichter]

Ok, I have now, converted the whole addon from nan to napi.
It works with napi, without the setImmediate on windows. The structure and mechanism are quite similar to the approach before.
So it is only an issue with the eventloop and nan and not with napi.