Marco Geri created QPID-8757:
--------------------------------
Summary: [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
Attachments: QPID-websocket-idle-checker.patch
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]
