Mailing-List: contact dev-help@activemq.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@activemq.apache.org
MIME-Version: 1.0
In-Reply-To: <1454603365259-4706961.post@n4.nabble.com>
References: <1454603365259-4706961.post@n4.nabble.com>
Date: Thu, 4 Feb 2016 13:23:23 -0500
Message-ID: 
 <CAKF+bsq99LROVONTvZVO4gaWw2oaBF4YZZqOLXna1-4Mz1BHbw@mail.gmail.com>
Subject: Re: Artemis use of PhantomReference impacting GC performance
From: Clebert Suconic <clebert.suconic@gmail.com>
To: "dev@activemq.apache.org" <dev@activemq.apache.org>
Content-Type: text/plain; charset=UTF-8

This discussion is probably a better fit on a Wildfly user's forum.


also I don't think measuring Milliseconds times taken on GC are a good
measure. You need to provide something more concrete such as..
.latency has increased... throughput degrated.. etc.. etc...


Netty Probably uses some PhantonReferences to control reused pools. We
have recently improved that reuse and we are always going beyond the
basics.


also: XNIO is a JBoss Project, so I don't know much about XNIO. (even
if I did this forums wouldn't be a fit place for this discussion).

On Thu, Feb 4, 2016 at 11:29 AM, jim_b_o <james@inaseq.com> wrote:
> I have observed a significant degradation in GC performance after upgrading
> from JBoss 4.2.3.GA to WildFly 10.0.0.Final.  I'm 99% sure the difference is
> due to Artemis ActiveMQ making heavy use of PhantomReference objects
> (directly or indirectly).  I'm raising this discussion to see if anyone else
> can observe the same behaviour and determine whether to raise an issue
> against Artemis or one of its dependencies.
>
> What's changed?
>
>
> I have JBoss 4.2.3.GA (with jboss-messaging-1.4.5.GA) and WildFly
> 10.0.0.Final running on identical hardware with identical JVMs (8u71) and GC
> settings (using G1GC).  The application is only minimally changed as
> required by the API differences between the old and new servers.  The
> application load is identical and results in near identical memory
> allocation rate and young GC frequency.
>
> *The difference is that on JBoss each young GC takes around 10-12ms whereas
> on WildFly they take 16-20ms.*  The additional time is taken in the Object
> Copy and Ref Proc phases.  This indicates that there are more Survivor
> objects on each GC and more References being processed.  I'm pretty sure the
> additional Survivor objects are also the Reference objects.  Running a Java
> Mission Control (JMC) Flight Recording on these two systems under identical
> production load, WildFly is showing around 11,000 PhantomReferences
> processed each GC versus a handful on JBoss.  The number of
> PhantomReferences seems to approximately correspond to the number of JMS
> messages transmitted between GCs.
>
> Some evidence
>
>
> In a separate test environment I have WildFly running under a standard test
> load.  It is emitting JMS messages at a consistent rate (lower than
> production) onto a non-durable Topic.  The following image shows a 2 minute
> JMC recording when there is no subscriber on the Topic.  We can see that
> there are very few PhantomReferences and the GCs take around 4ms.
>
> <http://activemq.2283324.n4.nabble.com/file/n4706961/WithoutConsumer.png>
>
> However once I start up an external JMS client subscribed to the Topic the
> PhantomReferences appear and the GCs slow down as shown in the next image.
> The messaging is non-XA with auto-ack.
>
> <http://activemq.2283324.n4.nabble.com/file/n4706961/WithConsumer.png>
>
> Where do the PhantomReferences come from?
>
>
> I used the debugger to capture where the PhantomReferences are being
> created.  This seems to indicate they are generated by Artemis and/or the
> associated XNIO remoting...
>
> Thread [Thread-1
> (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$2@788d198e-832298282)]
> (Suspended (breakpoint at line 80 in PhantomReference))
>         Cleaner(PhantomReference<T>).<init>(T, ReferenceQueue<? super T>) line: 80
>         Cleaner.<init>(Object, Runnable) line: 115
>         Cleaner.create(Object, Runnable) line: 133
>         DirectByteBuffer.<init>(int) line: 139
>         ByteBuffer.allocateDirect(int) line: 311
>         UnpooledUnsafeDirectByteBuf.allocateDirect(int) line: 108
>         UnpooledUnsafeDirectByteBuf.<init>(ByteBufAllocator, int, int) line: 69
>         UnpooledByteBufAllocator.newDirectBuffer(int, int) line: 50
>         UnpooledByteBufAllocator(AbstractByteBufAllocator).directBuffer(int, int)
> line: 155
>         UnpooledByteBufAllocator(AbstractByteBufAllocator).directBuffer(int) line:
> 146
>         NettyServerConnection.createTransportBuffer(int) line: 38
>
> RemotingConnectionImpl(AbstractRemotingConnection).createTransportBuffer(int)
> line: 162
>         SessionReceiveMessage.encode(RemotingConnection) line: 59
>         ChannelImpl.send(Packet, boolean, boolean) line: 225
>         ChannelImpl.sendBatched(Packet) line: 205
>         CoreSessionCallback.sendMessage(ServerMessage, ServerConsumer, int) line:
> 84
>         ServerConsumerImpl.deliverStandardMessage(MessageReference, ServerMessage)
> line: 883
>         ServerConsumerImpl.proceedDeliver(MessageReference) line: 366
>         QueueImpl.proceedDeliver(Consumer, MessageReference) line: 2358
>         QueueImpl.deliver() line: 1873
>         QueueImpl.access$1400(QueueImpl) line: 97
>         QueueImpl$DeliverRunner.run() line: 2581
>         OrderedExecutorFactory$OrderedExecutor$ExecutorTask.run() line: 100
>         ThreadPoolExecutor.runWorker(ThreadPoolExecutor$Worker) line: 1142
>         ThreadPoolExecutor$Worker.run() line: 617
>         Thread.run() line: 745
> Thread [default I/O-5] (Suspended (breakpoint at line 80 in
> PhantomReference))
>         Cleaner(PhantomReference<T>).<init>(T, ReferenceQueue<? super T>) line: 80
>         Cleaner.<init>(Object, Runnable) line: 115
>         Cleaner.create(Object, Runnable) line: 133
>         DirectByteBuffer.<init>(int) line: 139
>         ByteBuffer.allocateDirect(int) line: 311
>         UnpooledUnsafeDirectByteBuf.allocateDirect(int) line: 108
>         UnpooledUnsafeDirectByteBuf.<init>(ByteBufAllocator, int, int) line: 69
>         UnpooledByteBufAllocator.newDirectBuffer(int, int) line: 50
>         UnpooledByteBufAllocator(AbstractByteBufAllocator).directBuffer(int, int)
> line: 155
>         UnpooledByteBufAllocator(AbstractByteBufAllocator).directBuffer(int) line:
> 146
>         UnpooledByteBufAllocator(AbstractByteBufAllocator).ioBuffer(int) line: 107
>         AdaptiveRecvByteBufAllocator$HandleImpl.allocate(ByteBufAllocator) line:
> 104
>
> AbstractXnioSocketChannel$ReadListener.handleEvent(ConduitStreamSourceChannel)
> line: 426
>         AbstractXnioSocketChannel$ReadListener.handleEvent(Channel) line: 371
>         ChannelListeners.invokeChannelListener(T, ChannelListener<? super T>) line:
> 92
>         ReadReadyHandler$ChannelListenerHandler<C>.readReady() line: 66
>         NioSocketConduit.handleReady(int) line: 88
>         WorkerThread.run() line: 559
> Thread [default I/O-4] (Suspended (breakpoint at line 80 in
> PhantomReference))
>         Cleaner(PhantomReference<T>).<init>(T, ReferenceQueue<? super T>) line: 80
>         Cleaner.<init>(Object, Runnable) line: 115
>         Cleaner.create(Object, Runnable) line: 133
>         DirectByteBuffer.<init>(int) line: 139
>         ByteBuffer.allocateDirect(int) line: 311
>         UnpooledUnsafeDirectByteBuf.allocateDirect(int) line: 108
>         UnpooledUnsafeDirectByteBuf.<init>(ByteBufAllocator, int, int) line: 69
>         UnpooledByteBufAllocator.newDirectBuffer(int, int) line: 50
>         UnpooledByteBufAllocator(AbstractByteBufAllocator).directBuffer(int, int)
> line: 155
>         UnpooledByteBufAllocator(AbstractByteBufAllocator).directBuffer(int) line:
> 146
>         UnpooledByteBufAllocator(AbstractByteBufAllocator).ioBuffer(int) line: 107
>         AdaptiveRecvByteBufAllocator$HandleImpl.allocate(ByteBufAllocator) line:
> 104
>
> AbstractXnioSocketChannel$ReadListener.handleEvent(ConduitStreamSourceChannel)
> line: 426
>         AbstractXnioSocketChannel$ReadListener.handleEvent(Channel) line: 371
>         ChannelListeners.invokeChannelListener(T, ChannelListener<? super T>) line:
> 92
>         ReadReadyHandler$ChannelListenerHandler<C>.readReady() line: 66
>         NioSocketConduit.handleReady(int) line: 88
>         WorkerThread.run() line: 559
> Thread [default I/O-2] (Suspended (breakpoint at line 80 in
> PhantomReference))
>         Cleaner(PhantomReference<T>).<init>(T, ReferenceQueue<? super T>) line: 80
>         Cleaner.<init>(Object, Runnable) line: 115
>         Cleaner.create(Object, Runnable) line: 133
>         DirectByteBuffer.<init>(int) line: 139
>         ByteBuffer.allocateDirect(int) line: 311
>         UnpooledUnsafeDirectByteBuf.allocateDirect(int) line: 108
>         UnpooledUnsafeDirectByteBuf.<init>(ByteBufAllocator, int, int) line: 69
>         UnpooledByteBufAllocator.newDirectBuffer(int, int) line: 50
>         UnpooledByteBufAllocator(AbstractByteBufAllocator).directBuffer(int, int)
> line: 155
>         UnpooledByteBufAllocator(AbstractByteBufAllocator).directBuffer(int) line:
> 146
>         UnpooledByteBufAllocator(AbstractByteBufAllocator).ioBuffer(int) line: 107
>         AdaptiveRecvByteBufAllocator$HandleImpl.allocate(ByteBufAllocator) line:
> 104
>
> AbstractXnioSocketChannel$ReadListener.handleEvent(ConduitStreamSourceChannel)
> line: 426
>         AbstractXnioSocketChannel$ReadListener.handleEvent(Channel) line: 371
>         ChannelListeners.invokeChannelListener(T, ChannelListener<? super T>) line:
> 92
>         ReadReadyHandler$ChannelListenerHandler<C>.readReady() line: 66
>         NioSocketConduit.handleReady(int) line: 88
>         WorkerThread.run() line: 559
>
> What's next?
>
>
> So it's seems pretty certain that this is where the change is coming from.
> The total GC load is still low but we're aiming for consistent low latency
> and this is a backwards step.
>
> I'd be interested in any comments or questions.  I can provide more info if
> required.
>
> Thanks.
>
>
>
> --
> View this message in context: http://activemq.2283324.n4.nabble.com/Artemis-use-of-PhantomReference-impacting-GC-performance-tp4706961.html
> Sent from the ActiveMQ - Dev mailing list archive at Nabble.com.


-- 
Clebert Suconic