users@grizzly.java.net

Grizzly 2.0 out of the box performance issues?

From: Bo Li <b.li_at_sun.com>
Date: Wed, 13 May 2009 12:42:40 +0200

Hello Grizzly Gurus

After quickly prototyping an OpenDS front-end connection handler to use
Grizzly, I'm encountering some performance issues. All I have is a default
TCPNIOTransport with the TransportFilter and a custom LDAPFilter. The
LDAPFilter uses the readByte and readByteArray methods of StreamReader to
decode the request.

With 16 clients doing IO on persistent connections, I see many Grizzly
worker threads blocked on synchronously allocating read buffers from the
ByteBufferViewManager (the stack traces are at the end of this email.) I was
surprised as our LDAP messages are very small and always fit in one read
buffer. I decreased the read buffer size from the default transport wide 64K
to 4K and saw a performance improvement. However, the DefaultMemoryManager
was still allocating out of the ByteBufferViewManager.

I thought the DefaultMemoryManager should be able to handle 99% of all
allocations out of the thread local pool if I empty out the read buffer(s)
on every handleRead. However, it seems like the TCPNIOStreamReader hangs on
to the empty buffer (TCPNIOStreamReader.current) even after handleRead is
finished. Thus, the next time TCPNIOTranportFilter.handleRead is called
again for the next client request, it calls TCPNIOStreamReader.read0 which
tries to allocate a new read buffer... even though the current one is empty.
When DefaultMemoryManager tries to satisfy the allocation request out of the
thread local pool, there is not enough remaining from the previous read
buffer allocation and falls back to the synchronized ByteBufferViewManager.
In fact the DefaultMemoryManager will always fail this allocation because
the thread local pool is only ever as big as the read buffer size. What's
left after the trim from the previous read is always smaller than the read
buffer size.

I guess I could avoid this by handling the read buffer management myself by
using the readBuffer, getBuffer, and finishBuffer methods in StreamReader...
although it is not ideal. Anyways, Is this behavior by design or just
"features" of a milestone build?

Thanks again
Bo

"Grizzly-WorkerThread(4)" prio=3 tid=0x0000000004c80000 nid=0x52 waiting for
monitor entry [0xfffffd77bf2c3000..0xfffffd77bf2c3b20]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at
org.glassfish.grizzly.memory.ByteBufferViewManager.allocate(ByteBufferViewMa
nager.java:98)
        - waiting to lock <0xfffffd786a796300> (a
org.glassfish.grizzly.memory.DefaultMemoryManager)
        at
org.glassfish.grizzly.memory.DefaultMemoryManager.allocate(DefaultMemoryMana
ger.java:138)
        at
org.glassfish.grizzly.memory.DefaultMemoryManager.allocate(DefaultMemoryMana
ger.java:50)
        at
org.glassfish.grizzly.streams.AbstractStreamReader.newBuffer(AbstractStreamR
eader.java:638)
        at
org.glassfish.grizzly.nio.transport.TCPNIOStreamReader.read0(TCPNIOStreamRea
der.java:171)
        at
org.glassfish.grizzly.nio.transport.TCPNIOTransportFilter.handleRead(TCPNIOT
ransportFilter.java:72)
        at
org.glassfish.grizzly.filterchain.TransportFilter.handleRead(TransportFilter
.java:67)
        at
org.glassfish.grizzly.filterchain.DefaultFilterChain$3.execute(DefaultFilter
Chain.java:88)
        at
org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChain(DefaultFil
terChain.java:238)
        at
org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterCh
ain.java:177)
        at
org.glassfish.grizzly.filterchain.AbstractFilterChain.process(AbstractFilter
Chain.java:148)
        at
org.glassfish.grizzly.ProcessorRunnable.run(ProcessorRunnable.java:232)
        at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
        at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
        at java.util.concurrent.FutureTask.run(FutureTask.java:138)
        at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
va:886)
        at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
08)
        at java.lang.Thread.run(Thread.java:619)

"Grizzly-WorkerThread(3)" prio=3 tid=0x00000000022b0c00 nid=0x51 waiting for
monitor entry [0xfffffd77bf3c4000..0xfffffd77bf3c4aa0]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at
org.glassfish.grizzly.memory.ByteBufferViewManager.allocate(ByteBufferViewMa
nager.java:98)
        - waiting to lock <0xfffffd786a796300> (a
org.glassfish.grizzly.memory.DefaultMemoryManager)
        at
org.glassfish.grizzly.memory.DefaultMemoryManager.allocate(DefaultMemoryMana
ger.java:138)
        at
org.glassfish.grizzly.memory.DefaultMemoryManager.allocate(DefaultMemoryMana
ger.java:50)
        at
org.glassfish.grizzly.streams.AbstractStreamReader.newBuffer(AbstractStreamR
eader.java:638)
        at
org.glassfish.grizzly.nio.transport.TCPNIOStreamReader.read0(TCPNIOStreamRea
der.java:171)
        at
org.glassfish.grizzly.nio.transport.TCPNIOTransportFilter.handleRead(TCPNIOT
ransportFilter.java:72)
        at
org.glassfish.grizzly.filterchain.TransportFilter.handleRead(TransportFilter
.java:67)
        at
org.glassfish.grizzly.filterchain.DefaultFilterChain$3.execute(DefaultFilter
Chain.java:88)
        at
org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChain(DefaultFil
terChain.java:238)
        at
org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterCh
ain.java:177)
        at
org.glassfish.grizzly.filterchain.AbstractFilterChain.process(AbstractFilter
Chain.java:148)
        at
org.glassfish.grizzly.ProcessorRunnable.run(ProcessorRunnable.java:232)
        at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
        at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
        at java.util.concurrent.FutureTask.run(FutureTask.java:138)
        at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
va:886)
        at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
08)
        at java.lang.Thread.run(Thread.java:619)

"Grizzly-WorkerThread(1)" prio=3 tid=0x0000000001ca5800 nid=0x4f runnable
[0xfffffd77bf5c6000..0xfffffd77bf5c69a0]
   java.lang.Thread.State: RUNNABLE
        at java.nio.HeapByteBuffer.<init>(HeapByteBuffer.java:39)
        at java.nio.ByteBuffer.allocate(ByteBuffer.java:312)
        at
org.glassfish.grizzly.memory.ByteBufferManager.allocate0(ByteBufferManager.j
ava:81)
        at
org.glassfish.grizzly.memory.ByteBufferViewManager.allocate(ByteBufferViewMa
nager.java:99)
        - locked <0xfffffd786a796300> (a
org.glassfish.grizzly.memory.DefaultMemoryManager)
        at
org.glassfish.grizzly.memory.DefaultMemoryManager.allocate(DefaultMemoryMana
ger.java:138)
        at
org.glassfish.grizzly.memory.DefaultMemoryManager.allocate(DefaultMemoryMana
ger.java:50)
        at
org.glassfish.grizzly.streams.AbstractStreamReader.newBuffer(AbstractStreamR
eader.java:638)
        at
org.glassfish.grizzly.nio.transport.TCPNIOStreamReader.read0(TCPNIOStreamRea
der.java:171)
        at
org.glassfish.grizzly.nio.transport.TCPNIOTransportFilter.handleRead(TCPNIOT
ransportFilter.java:72)
        at
org.glassfish.grizzly.filterchain.TransportFilter.handleRead(TransportFilter
.java:67)
        at
org.glassfish.grizzly.filterchain.DefaultFilterChain$3.execute(DefaultFilter
Chain.java:88)
        at
org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChain(DefaultFil
terChain.java:238)
        at
org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterCh
ain.java:177)
        at
org.glassfish.grizzly.filterchain.AbstractFilterChain.process(AbstractFilter
Chain.java:148)
        at
org.glassfish.grizzly.ProcessorRunnable.run(ProcessorRunnable.java:232)
        at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
        at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
        at java.util.concurrent.FutureTask.run(FutureTask.java:138)
        at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
va:886)
        at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
08)
        at java.lang.Thread.run(Thread.java:619)

"Grizzly-WorkerThread(0)" prio=3 tid=0x0000000001ca4800 nid=0x4e waiting for
monitor entry [0xfffffd77bfbcc000..0xfffffd77bfbcc920]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at
org.glassfish.grizzly.memory.ByteBufferViewManager.allocate(ByteBufferViewMa
nager.java:98)
        - waiting to lock <0xfffffd786a796300> (a
org.glassfish.grizzly.memory.DefaultMemoryManager)
        at
org.glassfish.grizzly.memory.DefaultMemoryManager.allocate(DefaultMemoryMana
ger.java:138)
        at
org.glassfish.grizzly.memory.DefaultMemoryManager.allocate(DefaultMemoryMana
ger.java:50)
        at
org.glassfish.grizzly.streams.AbstractStreamReader.newBuffer(AbstractStreamR
eader.java:638)
        at
org.glassfish.grizzly.nio.transport.TCPNIOStreamReader.read0(TCPNIOStreamRea
der.java:171)
        at
org.glassfish.grizzly.nio.transport.TCPNIOTransportFilter.handleRead(TCPNIOT
ransportFilter.java:72)
        at
org.glassfish.grizzly.filterchain.TransportFilter.handleRead(TransportFilter
.java:67)
        at
org.glassfish.grizzly.filterchain.DefaultFilterChain$3.execute(DefaultFilter
Chain.java:88)
        at
org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChain(DefaultFil
terChain.java:238)
        at
org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterCh
ain.java:177)
        at
org.glassfish.grizzly.filterchain.AbstractFilterChain.process(AbstractFilter
Chain.java:148)
        at
org.glassfish.grizzly.ProcessorRunnable.run(ProcessorRunnable.java:232)
        at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
        at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
        at java.util.concurrent.FutureTask.run(FutureTask.java:138)
        at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
va:886)
        at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
08)
        at java.lang.Thread.run(Thread.java:619)