Mailing-List: contact dev-help@activemq.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@activemq.apache.org
Date: Wed, 2 Aug 2017 15:36:38 -0700 (PDT)
From: vdmitriev <allati.g@gmail.com>
To: dev@activemq.apache.org
Message-ID: <1501713398349-4729192.post@n4.nabble.com>
Subject: AMQ 5.11.1, NPE in KahaAddMessageCommand.getMessage() (JIT
 suspected)
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Transfer-Encoding: 7bit
archived-at: Wed, 02 Aug 2017 22:37:14 -0000

Hello!

(I have already posted this question to AMQ Users group and Tim Bain kindly
suggested to ask here too).

We are running AMQ 5.11.1 on AIX 7.1 with IBM J9 7.0 [1] and have
intermittent problem with messages delivery. Everything works fine,
consumers are connected to AMQ, but suddenly server stops delivering
messages and starts to log this stacktrace.

2017-08-01 01:53:12,913 | ERROR |
org.apache.activemq.broker.region.cursors.QueueStorePrefetch@442b1805:xxx,batchResetNeeded=false,size=3,cacheEnabled=false,maxBatchSize:3,hasSpace:true,pendingCachedIds.size:0,lastSyncCachedId:null,lastSyncCachedId-seq:null,lastAsyncCachedId:null,lastAsyncCachedId-seq:null,store=permits:10000,sd=nextSeq:84,lastRet:MessageOrderCursor:[def:81,
low:0, high:0],pending:0 - Failed to fill batch |
org.apache.activemq.broker.region.cursors.AbstractStoreCursor | ActiveMQ
Broker[xxx] Scheduler
java.lang.NullPointerException
        at
org.apache.activemq.store.kahadb.data.KahaAddMessageCommandBase.getMessage(KahaAddMessageCommand.java:397)[activemq-kahadb-store-5.11.1.jar:5.11.1]
        at
org.apache.activemq.store.kahadb.data.KahaAddMessageCommand.getMessage(KahaAddMessageCommand.java:7)[activemq-kahadb-store-5.11.1.jar:5.11.1]
        at
org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:1131)[activemq-kahadb-store-5.11.1.jar:5.11.1]
        at
org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$5.execute(KahaDBStore.java:595)[activemq-kahadb-store-5.11.1.jar:5.11.1]
        at
org.apache.activemq.store.kahadb.disk.page.Transaction.execute(Transaction.java:779)[activemq-kahadb-store-5.11.1.jar:5.11.1]
        at
org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:584)[activemq-kahadb-store-5.11.1.jar:5.11.1]
        at
org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:106)[activemq-broker-5.11.1.jar:5.11.1]
        at
org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:109)[activemq-broker-5.11.1.jar:5.11.1]
        at
org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:381)[activemq-broker-5.11.1.jar:5.11.1]
        at
org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:142)[activemq-broker-5.11.1.jar:5.11.1]
        at
org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:159)[activemq-broker-5.11.1.jar:5.11.1]
        at
org.apache.activemq.broker.region.Queue.doPageInForDispatch(Queue.java:1897)[activemq-broker-5.11.1.jar:5.11.1]
        at
org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:2119)[activemq-broker-5.11.1.jar:5.11.1]
        at
org.apache.activemq.broker.region.Queue.doBrowse(Queue.java:1116)[activemq-broker-5.11.1.jar:5.11.1]
        at
org.apache.activemq.broker.region.Queue.expireMessages(Queue.java:909)[activemq-broker-5.11.1.jar:5.11.1]
        at
org.apache.activemq.broker.region.Queue.access$100(Queue.java:100)[activemq-broker-5.11.1.jar:5.11.1]
        at
org.apache.activemq.broker.region.Queue$2.run(Queue.java:144)[activemq-broker-5.11.1.jar:5.11.1]
        at
org.apache.activemq.thread.SchedulerTimerTask.run(SchedulerTimerTask.java:33)[activemq-client-5.11.1.jar:5.11.1]
        at java.util.TimerThread.mainLoop(Timer.java:566)[:1.7.0]
        at java.util.TimerThread.run(Timer.java:516)[:1.7.0]

I checked the sources (and decompiled binaries from the server just to be
sure) and see no valid reason for JVM to throw NPE at
KahaAddMessageCommand.java:397: "this" mustn't be null and unboxing is not
happening there. I suspect that JIT optimizations are messing the code, but
before following this bumpy trail, I wanted to check with AMQ community.
Maybe I'm missing something and JVM is behaving correctly? Maybe AMQ is
modifying itself somehow at runtime and KahaAddMessageCommand.java:397
starts to point to different sections of code?

[1]
java version "1.7.0"
Java(TM) SE Runtime Environment (build pap6470sr6fp1-20140108_01(SR6 FP1))
IBM J9 VM (build 2.6, JRE 1.7.0 AIX ppc64-64 Compressed References
20140106_181350 (JIT enabled, AOT enabled)
J9VM - R26_Java726_SR6_20140106_1601_B181350
JIT  - r11.b05_20131003_47443.02
GC   - R26_Java726_SR6_20140106_1601_B181350_CMPRSS
J9CL - 20140106_181350)
JCL - 20140103_01 based on Oracle 7u51-b11


~Regards
Vadim 


--
View this message in context: http://activemq.2283324.n4.nabble.com/AMQ-5-11-1-NPE-in-KahaAddMessageCommand-getMessage-JIT-suspected-tp4729192.html
Sent from the ActiveMQ - Dev mailing list archive at Nabble.com.