[
https://issues.apache.org/jira/browse/QPID-8757?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=18111536#comment-18111536
]
Daniil Kirilyuk commented on QPID-8757:
---------------------------------------
Hi Marco,
I'm working on refactoring the WebSocketProvider; this might take a couple of
days, since the scope of the work turned out to be greater than I initially
anticipated. In addition, we need to expand the test coverage for WebSocket
functionality. I hope to be able to provide a draft version of the patch with
the necessary changes by Monday. Overall, we plan to release version 10.1.1 in
September, and I hope to make the changes to the WebSocket plugin early enough
to include them in that release.
Kind regards,
Daniil
> [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-8757.diff,
> 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]
