[
https://issues.apache.org/jira/browse/QPID-8757?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=18110601#comment-18110601
]
Marco Geri edited comment on QPID-8757 at 9/2/26 11:26 AM:
-----------------------------------------------------------
Hi Daniil,
Thanks for picking this up so quickly.
I ran JMH on it while waiting and attached the benchmark I used along with its
output, in case they're any use. You'll have a much better view than I do on
whether the trade is acceptable, so I'll just lay out what I measured.
The way I've been thinking about it, the two changes are separate. The
AtomicBoolean is what fixes the OutOfMemoryError, and I couldn't measure it at
all next to a thread pool submission. The 1ms floor is only there so the loop
doesn't spin once submission is suppressed, and it means fewer passes than
today, not more.
The scan is where the cost is, and it seemed to me more a functional change
than a performance one, since one connection in trouble currently holds up
everyone else's timeouts. But it does cost:
||connections||one due, shipped||one due, patched||nothing due,
shipped||nothing due, patched||
|1|22ns|27ns|24ns|24ns|
|10|19ns|48ns|44ns|45ns|
|100|22ns|300ns|276ns|290ns|
|1000|21ns|4.0us|3.4us|3.9us|
|10000|22ns|122us|110us|123us|
The first two columns are the regression: same case before and after, and the
early exit is worth a lot when it applies. The last two are the part that made
me think it might be tolerable, since the loop already walks the whole list
whenever nothing is due, and there the two are equal within error.
Off my laptop, an i7-11800H on JDK 21.0.12, so ratios rather than absolutes,
and the ten thousand row is noisy.
Two things about the benchmark. It assumes the patch applied, since it calls
`findDueConnections` and builds a ConnectionWrapper, and I compiled it with
javac against the module's target/classes rather than adding JMH to the build.
Also, don't mock MultiVersionProtocolEngine as I did at first:
`getAggregateTicker()` is a field read, but on a mock it costs microseconds,
and the scan disappears under the mocking overhead.
I should say the first version of this benchmark was wrong. The control walked
an ArrayList of engines with one dereference where the real scan walks a
CopyOnWriteArrayList of connections with two, and the nothing-due case came out
up to 20% apart in both directions depending on size, which is the harness
rather than the algorithm. Matching them is what made the numbers above line up.
And apologies in advance if I've misread any of this. I've only been in this
file for a few days, so there may well be a reason for the early exit that I
haven't seen. Hope some of it is useful rather than just adding to your pile.
Marco
was (Author: JIRAUSER295325):
Hi Daniil,
Thanks for picking this up so quickly.
I ran JMH on it while waiting and attached the benchmark I used along with its
output, in case they're any use. You'll have a much better view than I do on
whether the trade is acceptable, so I'll just lay out what I measured.
The way I've been thinking about it, the two changes are separate. The
AtomicBoolean is what fixes the OutOfMemoryError, and I couldn't measure it at
all next to a thread pool submission. The 1ms floor is only there so the loop
doesn't spin once submission is suppressed, and it means fewer passes than
today, not more.
The scan is where the cost is, and it seemed to me more a functional change
than a performance one, since one connection in trouble currently holds up
everyone else's timeouts. But it does cost:
||connections||one due, shipped||one due, patched||nothing due,
shipped||nothing due, patched||
|1|22ns|27ns|24ns|24ns|
|10|19ns|48ns|44ns|45ns|
|100|22ns|300ns|276ns|290ns|
|1000|21ns|4.0us|3.4us|3.9us|
|10000|22ns|122us|110us|123us|
The first two columns are the regression: same case before and after, and the
early exit is worth a lot when it applies. The last two are the part that made
me think it might be tolerable, since the loop already walks the whole list
whenever nothing is due, and there the two are equal within error.
Off my laptop, an i7-11800H on JDK 21.0.12, so ratios rather than absolutes,
and the ten thousand row is noisy.
Two things about the benchmark. It assumes the patch applied, since it calls
`findDueConnections` and builds a ConnectionWrapper, and I compiled it with
javac against the module's target/classes rather than adding JMH to the build.
Also, don't mock MultiVersionProtocolEngine as I did at first:
`getAggregateTicker()` is a field read, but on a mock it costs microseconds,
and the scan disappears under the mocking overhead.
I should say the first version of this benchmark was wrong. The control walked
an ArrayList of engines with one dereference where the real scan walks a
CopyOnWriteArrayList of connections with two, and the nothing-due case came out
up to 20% apart in both directions depending on size, which is the harness
rather than the algorithm. Matching them is what made the numbers above line up.
And apologies in advance if I've misread any of this. I've only been in this
file for a few days, so there may well be a reason for the early exit that I
haven't seen. Hope some of it is useful rather than just adding to your pile.
Marco
> [Broker-J] WebSocket idle checker queues unbounded tick jobs while a
> connection is writing, exhausting the broker heap
> ----------------------------------------------------------------------------------------------------------------------
>
> Key: QPID-8757
> URL: https://issues.apache.org/jira/browse/QPID-8757
> Project: Qpid
> Issue Type: Bug
> Components: Broker-J
> Reporter: Marco Geri
> Assignee: Daniil Kirilyuk
> Priority: Major
> Attachments: IdleCheckerBenchmark.java,
> QPID-websocket-idle-checker.patch, jmh-results.txt
>
>
> We hit this on a 10.x broker while moving a client onto AMQP over WebSocket
> with {{{}permessage-deflate{}}}, to help a user on a slow link. The broker
> died partway through a bulk read:
> {noformat}
> Unhandled Exception java.lang.OutOfMemoryError: Java heap space in Thread
> WebSocket Idle Checker: null
> Exiting
> java.lang.OutOfMemoryError: Java heap space
> at
> org.eclipse.jetty.util.BlockingArrayQueue.lockedGrow(BlockingArrayQueue.java:803)
> at
> org.eclipse.jetty.util.BlockingArrayQueue.offer(BlockingArrayQueue.java:429)
> at
> org.eclipse.jetty.util.thread.QueuedThreadPool.execute(QueuedThreadPool.java:820)
> at
> org.apache.qpid.server.transport.websocket.WebSocketProvider$ConnectionWrapper.tick(WebSocketProvider.java:701)
> at
> org.apache.qpid.server.transport.websocket.WebSocketProvider$WebSocketIdleTimeoutChecker.run(WebSocketProvider.java:756)
> {noformat}
> What caught our attention is where the memory went. The allocation that
> failed is the thread pool's own task queue growing, not a message or a
> connection, so something was queueing work faster than the pool could run it,
> and for long enough to fill the heap. We went looking for the producer.
> h2. What we think is happening
> The idle checker reads a connection's ticker without holding that
> connection's monitor, but the only thing that advances the ticker holds it.
> That is {{{}_tickJob{}}}, around line 512:
> {code:java}
> _tickJob = () ->
> {
> synchronized (ConnectionWrapper.this)
> {
> protocolEngine.getAggregateTicker().tick(System.currentTimeMillis());
> doWrite();
> }
> };
> {code}
> {{tick()}} at line 699 hands that job to the pool, and there is nothing to
> stop it handing over the same job again while the first is still waiting to
> run.
> {{_tickJob}} is one shared instance, so queueing it a thousand times runs it
> a thousand times:
> {code:java}
> public void tick()
> {
> _threadPool.execute(_tickJob);
> }
> {code}
> And in {{WebSocketIdleTimeoutChecker.run()}} at line 707, a due tick means
> the loop does not wait at all before coming back round:
> {code:java}
> long tick = ticker.getTimeToNextTick(currentTime);
> if(tick <= 0)
> {
> connectionToTick = connection;
> nextTick = -1;
> break;
> }
> ...
> if(nextTick > 0) // nextTick is -1 here, so no wait happens
> {
> wait(nextTick);
> }
> ...
> if(connectionToTick != null)
> {
> connectionToTick.tick();
> }
> {code}
> Put together: while the monitor is held, the ticker stays overdue, so the
> checker spins and queues one more job on every pass. Nothing bounds that
> except how long the monitor stays held.
> It does not take anything unusual to hold it. {{doWrite()}} at line 642 and
> {{doWork()}} at line 675 are both {{synchronized}} on the connection, and
> {{doWrite()}} allocates an array the size of everything pending, copies it
> all in, and calls {{Session.sendBinary}} without letting go.
> With {{permessage-deflate}} negotiated, Jetty deflates inside that
> {{sendBinary }}call, so a connection draining a deep queue holds the monitor
> for long stretches at a time. We suspect that is why we only met this after
> turning compression on, though compression is clearly not required: any slow
> write should do it, including a client that has simply topped reading.
> h2. A second thing, in the same loop
> The {{break}} above stops the scan at the first overdue connection, so one
> connection that stays overdue keeps every other connection's timeouts from
> being looked at.
> We have not bundled that in out of tidiness. Fixing it on its own would make
> the first problem worse, because the checker would then queue a job for every
> overdue connection on each pass instead of one. The two seemed safer to
> change together.
> h2. What the patch does
> Three things, all in {{{}WebSocketProvider{}}}:
> * an {{AtomicBoolean}} per {{{}ConnectionWrapper{}}}, set when a tick job is
> queued and cleared inside the monitor before the ticker is advanced, so at
> most one job is ever outstanding;
> * the scan pulled out into a package-private {{findDueConnections}} that
> returns every due connection instead of the first, with the checker ticking
> all of them;
> * a minimum wait of 1 ms in the loop, so that a connection whose job is
> already queued cannot spin the checker thread.
> The module had no test sources, so the patch adds them along with the two
> test dependencies the sibling plugin modules already declare. Getting at
> {{tick()}} from a test meant making {{ConnectionWrapper}} package-private,
> which is the one change we made purely for testability, and we would happily
> take a better suggestion.
> Against unpatched code the two new tests fail like this:
> {noformat}
> [ERROR] WebSocketProviderTest.tickDoesNotQueueASecondJobWhileOneIsPending
> queued 99996 tick jobs from 100000 calls to tick();
> at most one should be pending
> [ERROR] WebSocketProviderTest.everyDueConnectionIsReturnedNotJustTheFirst
> both overdue connections should be returned ==> expected: <2> but was: <1>
> {noformat}
> The first holds the connection monitor from another thread, the way
> {{doWrite()}} would, and then calls {{tick()}} as the checker does while the
> ticker is overdue. The second hands the provider two overdue connections and
> asks which ones are due. {{mvn -pl broker-plugins/websocket test}} is green
> with the patch applied.
> h2. Versions, and where we might be wrong
> Two caveats worth stating. We have not identified what left the ticker
> overdue in our own crash, only the code path that turns an overdue ticker
> into an unbounded queue, so the trigger may deserve a look of its own. And if
> the unbounded submission is deliberate, load shedding of some sort we have
> not understood, we would rather be told than have the patch quietly declined.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
