[
https://issues.apache.org/jira/browse/ARTEMIS-3117?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17285272#comment-17285272
]
Sebastian T commented on ARTEMIS-3117:
--------------------------------------
[~nigrofranz]I followed you advice and used async-profiler. Here are some
results.
{noformat}
$ sudo ./profiler.sh -e cpu -d 30 -o flat 4008
Started [cpu] profiling
--- Execution profile ---
Total samples : 4697
unknown_Java : 66 (1.41%)
not_walkable_Java : 14 (0.30%)
deoptimization : 3 (0.06%)
Frame buffer usage : 4.1374%
ns percent samples top
---------- ------- ------- ---
5454597354 11.51% 545 sha1_implCompress
3762140233 7.94% 370 __lock_text_start_[k]
2332043747 4.92% 233 sun.security.provider.DigestBase.engineReset
1763624534 3.72% 175
/tmp/libnetty_tcnative_linux_x86_6412383274641244971797.so (deleted)
1380825243 2.91% 138 java.util.Arrays.fill
1211143650 2.56% 121 java.util.Arrays.fill
1122056232 2.37% 112 jbyte_disjoint_arraycopy
1060468030 2.24% 106 sun.security.provider.SHA.implDigest
1053677131 2.22% 104
org.apache.activemq.artemis.protocol.amqp.broker.AMQPConnectionCallback.isWritable
974249541 2.06% 96
org.apache.activemq.artemis.utils.collections.LinkedListImpl$Iterator.canAdvance
913508803 1.93% 90 [vdso]
810611908 1.71% 81 sun.security.provider.ByteArrayAccess.b2iBig64
770820693 1.63% 76
org.apache.activemq.artemis.protocol.amqp.broker.AMQPSessionCallback.isWritable
770757093 1.63% 76
org.apache.activemq.artemis.core.server.impl.QueueImpl.deliver
660595358 1.39% 65
org.apache.activemq.artemis.core.server.impl.QueueImpl.handle
570551307 1.20% 57 sun.security.provider.DigestBase.engineUpdate
560396691 1.18% 56
java.security.MessageDigest$Delegate.engineDigest
488147551 1.03% 48 eventfd_write_[k]
480273955 1.01% 48 sun.security.provider.SHA.implCompressCheck
$ sudo ./profiler.sh -e lock -d 30 -o flat 4008
Started [lock] profiling
--- Execution profile ---
Total samples : 7255Frame buffer usage : 0.0869% ns percent
samples top
---------- ------- ------- ---
11699901984 92.19% 303
org.apache.activemq.artemis.core.remoting.impl.netty.NettyAcceptor
899875624 7.09% 5539
java.util.concurrent.locks.ReentrantLock$NonfairSync
90416573 0.71% 1407
org.apache.activemq.artemis.core.server.impl.QueueImpl
190303 0.00% 4 java.lang.Class
95851 0.00% 2 java.lang.Object
$ sudo ./profiler.sh -e cpu -d 30 -o traces 4008
Started [cpu] profiling
--- Execution profile ---
Total samples : 4544
unknown_Java : 76 (1.67%)
not_walkable_Java : 7 (0.15%)
deoptimization : 5 (0.11%)Frame buffer usage : 4.1185%--- 2769920933 ns
(6.04%), 277 samples
[ 0] sha1_implCompress
[ 1] java.security.MessageDigest$Delegate.engineDigest
[ 2] java.security.MessageDigest.digest
[ 3] java.security.MessageDigest.digest
[ 4] com.sun.crypto.provider.PKCS12PBECipherCore.derive
[ 5] com.sun.crypto.provider.PKCS12PBECipherCore.derive
[ 6] com.sun.crypto.provider.HmacPKCS12PBESHA1.engineInit
[ 7] javax.crypto.Mac.chooseProvider
[ 8] javax.crypto.Mac.init
[ 9] sun.security.pkcs12.PKCS12KeyStore.lambda$engineLoad$2
[10] sun.security.pkcs12.PKCS12KeyStore$$Lambda$617.524606891.tryOnce
[11] sun.security.pkcs12.PKCS12KeyStore$RetryWithZero.run
[12] sun.security.pkcs12.PKCS12KeyStore.engineLoad
[13] sun.security.util.KeyStoreDelegator.engineLoad
[14] java.security.KeyStore.load
[15]
org.apache.activemq.artemis.core.remoting.impl.ssl.SSLSupport.loadKeystore
[16]
org.apache.activemq.artemis.core.remoting.impl.ssl.SSLSupport.loadTrustManagerFactory
[17]
org.apache.activemq.artemis.core.remoting.impl.ssl.SSLSupport.createNettyContext
[18]
org.apache.activemq.artemis.core.remoting.impl.netty.NettyAcceptor.loadOpenSslEngine
[19]
org.apache.activemq.artemis.core.remoting.impl.netty.NettyAcceptor.getSslHandler
[20]
org.apache.activemq.artemis.core.remoting.impl.netty.NettyAcceptor$4.initChannel
[21] io.netty.channel.ChannelInitializer.initChannel
[22] io.netty.channel.ChannelInitializer.handlerAdded
[23] io.netty.channel.AbstractChannelHandlerContext.callHandlerAdded
[24] io.netty.channel.DefaultChannelPipeline.callHandlerAdded0
[25] io.netty.channel.DefaultChannelPipeline.access$100
[26] io.netty.channel.DefaultChannelPipeline$PendingHandlerAddedTask.execute
[27] io.netty.channel.DefaultChannelPipeline.callHandlerAddedForAllHandlers
[28] io.netty.channel.DefaultChannelPipeline.invokeHandlerAddedIfNeeded
[29] io.netty.channel.AbstractChannel$AbstractUnsafe.register0
[30] io.netty.channel.AbstractChannel$AbstractUnsafe.access$200
[31] io.netty.channel.AbstractChannel$AbstractUnsafe$1.run
[32] io.netty.util.concurrent.AbstractEventExecutor.safeExecute
[33] io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks
[34] io.netty.channel.epoll.EpollEventLoop.run
[35] io.netty.util.concurrent.SingleThreadEventExecutor$4.run
[36] io.netty.util.internal.ThreadExecutorMap$2.run
[37] org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1.run
--- 2714894418 ns (5.92%), 271 samples
[ 0] sha1_implCompress
[ 1] java.security.MessageDigest$Delegate.engineDigest
[ 2] java.security.MessageDigest.digest
[ 3] java.security.MessageDigest.digest
[ 4] com.sun.crypto.provider.PKCS12PBECipherCore.derive
[ 5] com.sun.crypto.provider.PKCS12PBECipherCore.derive
[ 6] com.sun.crypto.provider.PKCS12PBECipherCore.implInit
[ 7] com.sun.crypto.provider.PKCS12PBECipherCore.implInit
[ 8] com.sun.crypto.provider.PKCS12PBECipherCore.implInit
[ 9]
com.sun.crypto.provider.PKCS12PBECipherCore$PBEWithSHA1AndRC2_40.engineInit
[10] javax.crypto.Cipher.implInit
[11] javax.crypto.Cipher.chooseProvider
[12] javax.crypto.Cipher.init
[13] javax.crypto.Cipher.init
[14] sun.security.pkcs12.PKCS12KeyStore.lambda$engineLoad$1
[15] sun.security.pkcs12.PKCS12KeyStore$$Lambda$613.1316205906.tryOnce
[16] sun.security.pkcs12.PKCS12KeyStore$RetryWithZero.run
[17] sun.security.pkcs12.PKCS12KeyStore.engineLoad
[18] sun.security.util.KeyStoreDelegator.engineLoad
[19] java.security.KeyStore.load
[20]
org.apache.activemq.artemis.core.remoting.impl.ssl.SSLSupport.loadKeystore
[21]
org.apache.activemq.artemis.core.remoting.impl.ssl.SSLSupport.loadTrustManagerFactory
[22]
org.apache.activemq.artemis.core.remoting.impl.ssl.SSLSupport.createNettyContext
[23]
org.apache.activemq.artemis.core.remoting.impl.netty.NettyAcceptor.loadOpenSslEngine
[24]
org.apache.activemq.artemis.core.remoting.impl.netty.NettyAcceptor.getSslHandler
[25]
org.apache.activemq.artemis.core.remoting.impl.netty.NettyAcceptor$4.initChannel
[26] io.netty.channel.ChannelInitializer.initChannel
[27] io.netty.channel.ChannelInitializer.handlerAdded
[28] io.netty.channel.AbstractChannelHandlerContext.callHandlerAdded
[29] io.netty.channel.DefaultChannelPipeline.callHandlerAdded0
[30] io.netty.channel.DefaultChannelPipeline.access$100
[31] io.netty.channel.DefaultChannelPipeline$PendingHandlerAddedTask.execute
[32] io.netty.channel.DefaultChannelPipeline.callHandlerAddedForAllHandlers
[33] io.netty.channel.DefaultChannelPipeline.invokeHandlerAddedIfNeeded
[34] io.netty.channel.AbstractChannel$AbstractUnsafe.register0
[35] io.netty.channel.AbstractChannel$AbstractUnsafe.access$200
[36] io.netty.channel.AbstractChannel$AbstractUnsafe$1.run
[37] io.netty.util.concurrent.AbstractEventExecutor.safeExecute
[38] io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks
[39] io.netty.channel.epoll.EpollEventLoop.run
[40] io.netty.util.concurrent.SingleThreadEventExecutor$4.run
[41] io.netty.util.internal.ThreadExecutorMap$2.run
[42] org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1.run---
1186331756 ns (2.59%), 116 samples
[ 0] __lock_text_start_[k]
[ 1] try_to_wake_up_[k]
[ 2] wake_up_q_[k]
[ 3] futex_wake_[k]
[ 4] do_futex_[k]
[ 5] sys_futex_[k]
[ 6] do_syscall_64_[k]
[ 7] entry_SYSCALL_64_after_hwframe_[k]
[ 8] pthread_cond_signal@@GLIBC_2.3.2
[ 9] jdk.internal.misc.Unsafe.unpark
[10] java.util.concurrent.locks.LockSupport.unpark
[11] java.util.concurrent.locks.AbstractQueuedSynchronizer.unparkSuccessor
[12] java.util.concurrent.locks.AbstractQueuedSynchronizer.release
[13] java.util.concurrent.locks.AbstractQueuedSynchronizer.fullyRelease
[14]
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos
[15] java.util.concurrent.LinkedBlockingQueue.poll
[16]
org.apache.activemq.artemis.utils.ActiveMQThreadPoolExecutor$ThreadPoolQueue.poll
[17]
org.apache.activemq.artemis.utils.ActiveMQThreadPoolExecutor$ThreadPoolQueue.poll
[18] java.util.concurrent.ThreadPoolExecutor.getTask
[19] java.util.concurrent.ThreadPoolExecutor.runWorker
[20] java.util.concurrent.ThreadPoolExecutor$Worker.run
[21] org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1.run{noformat}
> Performance degradation when switching from JDK8 to JDK11
> ---------------------------------------------------------
>
> Key: ARTEMIS-3117
> URL: https://issues.apache.org/jira/browse/ARTEMIS-3117
> Project: ActiveMQ Artemis
> Issue Type: Improvement
> Components: Broker
> Affects Versions: 2.16.0
> Environment: Amazon Linux 2, Amazon Corretto (OpenJDK 11), AMQP over
> TLS via BoringSSL
> Reporter: Sebastian T
> Priority: Major
> Attachments: broker.xml, image-2021-02-12-21-39-32-185.png,
> image-2021-02-12-21-40-21-125.png, image-2021-02-12-21-44-26-271.png,
> image-2021-02-12-21-46-52-006.png, image-2021-02-12-21-47-02-387.png,
> image-2021-02-12-21-47-57-301.png, image-2021-02-12-22-01-07-044.png
>
>
> Since it was announced that probably Artemis 2.18.0 will require Java 11 we
> upgraded the JVM of one of our broker clusters from OpenJDK 8 to OpenJDK 11
> and are seeing a noticable performance degradation which results in higher
> CPU usage and higher latency.
> We are monitoring request/reply round trip duration with a custom distributed
> qpid-jms based healthcheck applications. Here is a graphic that shows the
> effect when we switched the JDK:
> !image-2021-02-12-21-39-32-185.png!
> CPU Usage of the broker process:
> !image-2021-02-12-22-01-07-044.png|width=874,height=262!
>
> The broker itself is also monitored via Dynatrace, there I can see that after
> upgrading to JDK 11 the broker process spend 21% of CPU time locking while in
> JDK it only spent 3.2%.
> *JDK 8:*
> !image-2021-02-12-21-40-21-125.png|width=1247,height=438!
>
> *JDK 11:*
> *!image-2021-02-12-21-44-26-271.png|width=1197,height=420!*
>
> *A method hotspot breakdown reveals this:*
> !image-2021-02-12-21-47-02-387.png|width=1271,height=605!
> !image-2021-02-12-21-47-57-301.png|width=1059,height=627!
> Maybe I am misinterpreting the charts but the root cause seems to be
> somewhere in {{org.apache.activemq.artemis.utils.ActiveMQThreadFactory$1}}
> and/or in
> {{org.apache.activemq.artemis.core.remoting.impl.netty.NettyAcceptor.getSslHandler}}
> I currently cannot pinpoint the exact line number.
>
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
