Rapidly cancelling a Call can overwhelm transport

[carl-mastrangelo]

Doing something like

      ClientCall<Void, Void> call = channel.newCall(foo, CallOptions.DEFAULT);
      call.start(listen, new Metadata());
      call.sendMessage(null);
      call.halfClose();
      call.request(1);
      call.cancel();

rapidly in a loop causes memory to not get reclaimed. Somehow netty is holding on to commands sent to it from the ClientCallImpl.

[carl-mastrangelo]

The class that is not being cleaned up (and thus, the most of) is PooledUnsafeDirectByteBuf

[carl-mastrangelo]

Here is a program that causes the problem:

carl-mastrangelo@bf14bed

Just let it run and it will eventually OOM. It is designed to cause as little extra allocations as possible, which is why it is using a customer marshaller.

[carl-mastrangelo]

Hooray, solved! Well, kinda. The problem is that ChannelOutboundBuffer gets filled up after running for a while, to a point which is never becomes empty again. In my test, it got to be about 60MB before it stopped responding. This is because NioSocketChannel cannot take data out of it fast enough. Two calls are to blame inside NioSocketChannel.doWrite:

ByteBuffer[] nioBuffers = in.nioBuffers();

and

                    for (int i = config().getWriteSpinCount() - 1; i >= 0; i --) {
                        final long localWrittenBytes = ch.write(nioBuffers, 0, nioBufferCnt);
                        if (localWrittenBytes == 0) {
                            setOpWrite = true;
                            break;
                        }
                        expectedWrittenBytes -= localWrittenBytes;
                        writtenBytes += localWrittenBytes;
                        if (expectedWrittenBytes == 0) {
                            done = true;
                            break;
                        }
                    }

When the number of buffers in in (a ChannelOutboundBuffer) is very high, the first call takes a REALLY long time. Like 10s of seconds. The next code chunk does the writing to the wire. By default config().getWriteSpinCount() is 16, which means that if the inner loops doesn't make much progress, it exits too early.

In this case, the number of buffers is ~millions, and the total number of bytes written is about 11K for each round through the loop. (And also strangely, it restarts at the beginning of the array each loop through). The total number of bytes written ends up being around 170K, which means that the ~60M bytes queued up in ChannelOutboundBuffer.

---

There is another problem that causes this to state to begin with: RST packets are not flow controlled. My test program begins a new rpc when a previous one completes, based on the onClosed callback. The callback is fired before the RST packet is written to the wire, causing it to write really fast. This is why adding call.cancel() makes the problem happen more quickly. Because it writes so fast, and because RST packets don't count towards the flow control window, they fill up the outbound buffer

[carl-mastrangelo]

More detail: By default, Java calls into sun/nio/ch/IOUtil.java Which writes ByteBuffers in batches of IOV_MAX, which on my system is 1024. This is why the chunk size is so small, the 13 Byte RST messages and 8 and 14 byte buffers of Settings frames multiplied by 1024 is about 11K, which is the batch size. Decreasing the number of many tiny buffers should alleviate (though not solve) this issue.

[buchgr]

@carl-mastrangelo thanks! you want to take this? Else I ll work on it Wednesday.

[carl-mastrangelo]

I will. I am going to try and make the DefaultHttp2FrameWriter buffer these tiny writes up before sending so that so many tiny buffers aren't created.