I still don't see any cause of timeout in logs. But there is one suspiciously long pause between two log records:
[INFO ] 2017-02-22 15:45:52.807 [pub-#1%DataGridServer-Production%] OrderHolderSaveRunnable - Begin TXN for orderHolder save, saving 1 orders [ERROR] 2017-02-22 15:46:01.406 [pub-#2%DataGridServer-Production%] OrderHolderSaveRunnable - javax.cache.CacheException: class org.apache.ignite.transactions.TransactionTimeoutException: Cache transaction time d out (was rolled back automatically) It would be great to get thread dumps during this pause. Did you try Apache Ignite 1.8 release? On Thu, Feb 23, 2017 at 5:03 PM, bintisepaha <[email protected]> wrote: > This is the actual error that looks like it is not coming from our code > > 109714 Feb 22, 2017 3:46:17 PM org.apache.ignite.logger.java.JavaLogger > error > 109715 SEVERE: <Position> Failed to acquire lock for request: > GridNearLockRequest [topVer=AffinityTopologyVersion [topVer=3153, > minorTopVer=32], miniId=acdced25a51-c5e64ee6-1079-4b90-bb7b-5ec14032a859, > implicitTx=f alse, implicitSingleTx=false, onePhaseCommit=false, > dhtVers=[null], subjId=f6663b00-24fc-4515-91ac-20c3b47d90ec, taskNameHash=0, > hasTransforms=false, syncCommit=true, accessTtl=-1, retVal=true, > firstClientRe q=false, filter=null, super=GridDistributedLockRequest > [nodeId=f6663b00-24fc-4515-91ac-20c3b47d90ec, nearXidVer=GridCacheVersion > [topVer=98913254, time=1487796367155, order=1487785731866, nodeOrder=7], > threa dId=57, futId=8cdced25a51-c5e64ee6-1079-4b90-bb7b-5ec14032a859, > timeout=9990, isInTx=true, isInvalidate=false, isRead=true, > isolation=REPEATABLE_READ, retVals=[true], txSize=0, flags=0, keysCnt=1, > super=Grid DistributedBaseMessage [ver=GridCacheVersion > [topVer=98913254, time=1487796367155, order=1487785731866, nodeOrder=7], > committedVers=null, rolledbackVers=null, cnt=0, super=GridCacheMessage > [msgId=2688455, de pInfo=null, err=null, skipPrepare=false, > cacheId=812449097, cacheId=812449097]]]] > 109716 class > org.apache.ignite.internal.transactions.IgniteTxTimeoutCheckedException: > Failed to acquire lock within provided timeout for transaction > [timeout=9990, tx=org.apache.ignite.internal.processors.cache.dis > tributed.dht.GridDhtTxLocalAdapter$1@7f2a8c8a] > 109717 at > org.apache.ignite.internal.processors.cache.transactions.IgniteTxLocalAdapter$PostLockClosure1.apply(IgniteTxLocalAdapter.java:3924) > 109718 at > org.apache.ignite.internal.processors.cache.transactions.IgniteTxLocalAdapter$PostLockClosure1.apply(IgniteTxLocalAdapter.java:3874) > 109719 at > org.apache.ignite.internal.util.future.GridEmbeddedFuture$2.applyx(GridEmbeddedFuture.java:91) > 109720 at > org.apache.ignite.internal.util.future.GridEmbeddedFuture$AsyncListener1.apply(GridEmbeddedFuture.java:297) > 109721 at > org.apache.ignite.internal.util.future.GridEmbeddedFuture$AsyncListener1.apply(GridEmbeddedFuture.java:290) > 109722 at > org.apache.ignite.internal.util.future.GridFutureAdapter.notifyListener(GridFutureAdapter.java:263) > 109723 at > org.apache.ignite.internal.util.future.GridFutureAdapter.notifyListeners(GridFutureAdapter.java:251) > 109724 at > org.apache.ignite.internal.util.future.GridFutureAdapter.onDone(GridFutureAdapter.java:381) > 109725 at > org.apache.ignite.internal.util.future.GridFutureAdapter.onDone(GridFutureAdapter.java:347) > 109726 at > org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtLockFuture.onComplete(GridDhtLockFuture.java:752) > 109727 at > org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtLockFuture.access$600(GridDhtLockFuture.java:79) > 109728 at > org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtLockFuture$LockTimeoutObject.onTimeout(GridDhtLockFuture.java:1116) > 109729 at > org.apache.ignite.internal.processors.timeout.GridTimeoutProcessor$TimeoutWorker.body(GridTimeoutProcessor.java:159) > 109730 at > org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110) > 109731 at java.lang.Thread.run(Thread.java:745) > 109732 > 109733 Feb 22, 2017 3:46:17 PM org.apache.ignite.logger.java.JavaLogger > error > 109716 class > org.apache.ignite.internal.transactions.IgniteTxTimeoutCheckedException: > Failed to acquire lock within provided timeout for transaction > [timeout=9990, tx=org.apache.ignite.internal.processors.cache.dis > tributed.dht.GridDhtTxLocalAdapter$1@7f2a8c8a] > 109717 at > org.apache.ignite.internal.processors.cache.transactions.IgniteTxLocalAdapter$PostLockClosure1.apply(IgniteTxLocalAdapter.java:3924) > 109718 at > org.apache.ignite.internal.processors.cache.transactions.IgniteTxLocalAdapter$PostLockClosure1.apply(IgniteTxLocalAdapter.java:3874) > 109719 at > org.apache.ignite.internal.util.future.GridEmbeddedFuture$2.applyx(GridEmbeddedFuture.java:91) > 109720 at > org.apache.ignite.internal.util.future.GridEmbeddedFuture$AsyncListener1.apply(GridEmbeddedFuture.java:297) > 109721 at > org.apache.ignite.internal.util.future.GridEmbeddedFuture$AsyncListener1.apply(GridEmbeddedFuture.java:290) > 109722 at > org.apache.ignite.internal.util.future.GridFutureAdapter.notifyListener(GridFutureAdapter.java:263) > 109723 at > org.apache.ignite.internal.util.future.GridFutureAdapter.notifyListeners(GridFutureAdapter.java:251) > 109724 at > org.apache.ignite.internal.util.future.GridFutureAdapter.onDone(GridFutureAdapter.java:381) > 109725 at > org.apache.ignite.internal.util.future.GridFutureAdapter.onDone(GridFutureAdapter.java:347) > 109726 at > org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtLockFuture.onComplete(GridDhtLockFuture.java:752) > 109727 at > org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtLockFuture.access$600(GridDhtLockFuture.java:79) > 109728 at > org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtLockFuture$LockTimeoutObject.onTimeout(GridDhtLockFuture.java:1116) > 109729 at > org.apache.ignite.internal.processors.timeout.GridTimeoutProcessor$TimeoutWorker.body(GridTimeoutProcessor.java:159) > 109730 at > org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110) > 109731 at java.lang.Thread.run(Thread.java:745) > 109732 > 109733 Feb 22, 2017 3:46:17 PM org.apache.ignite.logger.java.JavaLogger > error > 109734 SEVERE: <Position> Future execution resulted in error: > GridDhtEmbeddedFuture [super=GridEmbeddedFuture [embedded=GridEmbeddedFuture > [embedded=GridDhtLockFuture [nearNodeId=f6663b00-24fc-4515-91ac-20c3b47d90e > c, nearLockVer=GridCacheVersion [topVer=98913254, time=1487796367155, > order=1487785731866, nodeOrder=7], topVer=AffinityTopologyVersion > [topVer=3153, minorTopVer=32], threadId=57, futId=7e221e25a51-8c03dfe0- > 0f6e-4200-aed7-2233c421e0a3, lockVer=GridCacheVersion [topVer=98913254, > time=1487796367159, order=1487785731867, nodeOrder=14], read=true, err=null, > timedOut=true, timeout=9990, tx=GridDhtTxLocal [nearNodeId > =f6663b00-24fc-4515-91ac-20c3b47d90ec, > nearFutId=8cdced25a51-c5e64ee6-1079-4b90-bb7b-5ec14032a859, > nearMiniId=acdced25a51-c5e64ee6-1079-4b90-bb7b-5ec14032a859, > nearFinFutId=null, nearFinMiniId=null, nearXidV er=GridCacheVersion > [topVer=98913254, time=1487796367155, order=1487785731866, nodeOrder=7], > super=GridDhtTxLocalAdapter [nearOnOriginatingNode=false, nearNodes=[], > dhtNodes=[], explicitLock=false, super=Ign iteTxLocalAdapter > [completedBase=null, sndTransformedVals=false, depEnabled=false, > txState=IgniteTxStateImpl [activeCacheIds=GridLongList [idx=1, > arr=[812449097]], txMap={IgniteTxKey [key=KeyCacheObjectImpl > [val=PositionId [fundAbbrev=BVI, clearBrokerId=10032, insIid=681871, > strategy=, traderId=5142, valueDate=19000101], hasValBytes=true], > cacheId=812449097]=IgniteTxEntry [key=KeyCacheObjectImpl [val=PositionId > [fundAbbrev=BVI, clearBrokerId=10032, insIid=681871, strategy=, > traderId=5142, valueDate=19000101], hasValBytes=true], cacheId=812449097, > partId=-1, txKey=IgniteTxKey [key=KeyCacheObjectImpl [val=PositionId > [fundAbbrev=BVI, clearBrokerId=10032, insIid=681871, strategy=, > traderId=5142, valueDate=19000101], hasValBytes=true], cacheId=812449097], > val=[op=NOOP, val=null], prevVal=[op=NOOP, val=null], entryProcesso > rsCol=null, ttl=-1, conflictExpireTime=-1, conflictVer=null, > explicitVer=null, dhtVer=null, filters=[], filtersPassed=false, > filtersSet=false, entry=GridDhtColocatedCacheEntry [super=GridDhtCacheEntry > [rdrs= [], locPart=GridDhtLocalPartition [id=961, > map=o.a.i.i.processors.cache.GridCacheConcurrentMapImpl@4cd4bfee, > rmvQueue=GridCircularBuffer [sizeMask=127, idxGen=0], cntr=1181, > state=OWNING, reservations=0, emp ty=false, createTime=02/18/2017 > 10:01:50], super=GridDistributedCacheEntry [super=GridCacheMapEntry > [key=KeyCacheObjectImpl [val=PositionId [fundAbbrev=BVI, > clearBrokerId=10032, insIid=681871, strategy=, tra derId=5142, > valueDate=19000101], hasValBytes=true], val=CacheObjectImpl [val=Position > [positionId=PositionId [fundAbbrev=BVI, clearBrokerId=10032, insIid=681871, > strategy=, traderId=5142, valueDate=19000101] , quantity=104864.0], > hasValBytes=true], startVer=1487430990114, ver=GridCacheVersion > [topVer=98913252, time=1487796336445, order=1487785730286, nodeOrder=14], > hash=534941633, extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc > [locs=[GridCacheMvccCandidate [nodeId=985b44be-ea4a-4d0b-a2a5-ab2aa441ac62, > ver=GridCacheVersion [topVer=98913253, time=1487796361851, > order=1487785731568, nodeOrder=14], timeout=9990, t s=1487796361850, > threadId=76, id=1817320, topVer=AffinityTopologyVersion [topVer=3152, > minorTopVer=41], reentry=null, > otherNodeId=14cb9e24-0902-48b7-a016-f572db04838f, otherVer=GridCacheVersion > [topVer=98913 253, time=1487796349651, order=1487785731495, > nodeOrder=13], mappedDhtNodes=null, mappedNearNodes=null, ownerVer=null, > serOrder=null, key=KeyCacheObjectImpl [val=PositionId [fundAbbrev=BVI, > clearBrokerId=100 32, insIid=681871, strategy=, traderId=5142, > valueDate=19000101], hasValBytes=true], > masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=1|single_implicit=0|dht_local=1|near_local=0|removed=0, > prevVer=null, ne xtVer=null], GridCacheMvccCandidate > [nodeId=985b44be-ea4a-4d0b-a2a5-ab2aa441ac62, ver=GridCacheVersion > [topVer=98913254, time=1487796367159, order=1487785731867, nodeOrder=14], > timeout=9990, ts=1487796367150 , threadId=57, id=1817427, > topVer=AffinityTopologyVersion [topVer=3153, minorTopVer=32], reentry=null, > otherNodeId=f6663b00-24fc-4515-91ac-20c3b47d90ec, otherVer=GridCacheVersion > [topVer=98913254, time=14877 96367155, order=1487785731866, > nodeOrder=7], mappedDhtNodes=null, mappedNearNodes=null, > ownerVer=GridCacheVersion [topVer=98913253, time=1487796361851, > order=1487785731568, nodeOrder=14], serOrder=null, key= > KeyCacheObjectImpl [val=PositionId [fundAbbrev=BVI, clearBrokerId=10032, > insIid=681871, strategy=, traderId=5142, valueDate=19000101], > hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=1|s > ingle_implicit=0|dht_local=1|near_local=0|removed=0, prevVer=null, > nextVer=null]], rmts=null]], flags=0]]]], prepared=0, locked=false, > nodeId=null, locMapped=false, expiryPlc=null, transferExpiryPlc=false, f > lags=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion > [topVer=98913254, time=1487796367159, order=1487785731867, nodeOrder=14]]}], > super=IgniteTxAdapter [xidVer=GridCacheVersion [topVer=98913254 , > time=1487796367159, order=1487785731867, nodeOrder=14], writeVer=null, > implicit=false, loc=true, threadId=57, startTime=1487796367150, > nodeId=985b44be-ea4a-4d0b-a2a5-ab2aa441ac62, startVer=GridCacheVersion > [topVer=98913254, time=1487796367159, order=1487785731867, nodeOrder=14], > endVer=null, isolation=REPEATABLE_READ, concurrency=PESSIMISTIC, > timeout=9990, sysInvalidate=false, sys=false, plc=2, commitVer=null , > finalizing=NONE, preparing=false, invalidParts=null, state=MARKED_ROLLBACK, > timedOut=false, topVer=AffinityTopologyVersion [topVer=3153, > minorTopVer=32], duration=10008ms, onePhaseCommit=false], size=1]]], > mapped=false, trackable=true, accessTtl=-1, needReturnVal=true, > skipStore=false, keepBinary=false, innerFuts=[], > pendingLocks=[KeyCacheObjectImpl [val=PositionId [fundAbbrev=BVI, > clearBrokerId=10032, insIid =681871, strategy=, traderId=5142, > valueDate=19000101], hasValBytes=true]], super=GridCompoundIdentityFuture > [super=GridCompoundFuture [rdc=Bool reducer: true, initFlag=0, lsnrCalls=0, > done=true, cancelled=f alse, err=null, futs=[]]]]]]] > 109735 class > org.apache.ignite.internal.transactions.IgniteTxTimeoutCheckedException: > Failed to acquire lock within provided timeout for transaction > [timeout=9990, tx=org.apache.ignite.internal.processors.cache.dis > tributed.dht.GridDhtTxLocalAdapter$1@7f2a8c8a] > 109736 at > org.apache.ignite.internal.processors.cache.transactions.IgniteTxLocalAdapter$PostLockClosure1.apply(IgniteTxLocalAdapter.java:3924) > 109737 at > org.apache.ignite.internal.processors.cache.transactions.IgniteTxLocalAdapter$PostLockClosure1.apply(IgniteTxLocalAdapter.java:3874) > 109738 at > org.apache.ignite.internal.util.future.GridEmbeddedFuture$2.applyx(GridEmbeddedFuture.java:91) > 109739 at > org.apache.ignite.internal.util.future.GridEmbeddedFuture$AsyncListener1.apply(GridEmbeddedFuture.java:297) > 109740 at > org.apache.ignite.internal.util.future.GridEmbeddedFuture$AsyncListener1.apply(GridEmbeddedFuture.java:290) > 109741 at > org.apache.ignite.internal.util.future.GridFutureAdapter.notifyListener(GridFutureAdapter.java:263) > 109742 at > org.apache.ignite.internal.util.future.GridFutureAdapter.notifyListeners(GridFutureAdapter.java:251) > 109743 at > org.apache.ignite.internal.util.future.GridFutureAdapter.onDone(GridFutureAdapter.java:381) > 109744 at > org.apache.ignite.internal.util.future.GridFutureAdapter.onDone(GridFutureAdapter.java:347) > 109745 at > org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtLockFuture.onComplete(GridDhtLockFuture.java:752) > 109746 at > org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtLockFuture.access$600(GridDhtLockFuture.java:79) > 109747 at > org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtLockFuture$LockTimeoutObject.onTimeout(GridDhtLockFuture.java:1116) > 109748 at > org.apache.ignite.internal.processors.timeout.GridTimeoutProcessor$TimeoutWorker.body(GridTimeoutProcessor.java:159) > 109749 at > org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110) > 109750 at java.lang.Thread.run(Thread.java:745) > 109751 > 109752 Feb 22, 2017 3:46:17 PM org.apache.ignite.logger.java.JavaLogger > error > 109753 SEVERE: Failed to initialize job > [jobId=73652976a51-2c4ae429-3284-4588-a96e-7e487f6653a1, > ses=GridJobSessionImpl [ses=GridTaskSessionImpl > [taskName=com.tudor.datagridI.server.tradegen.OrderHolderSaveRunn > able, dep=LocalDeployment [super=GridDeployment [ts=1487430097277, > depMode=SHARED, clsLdr=sun.misc.Launcher$AppClassLoader@18b4aac2, > clsLdrId=1051eb15a51-985b44be-ea4a-4d0b-a2a5-ab2aa441ac62, userVer=0, > loc=true, sampleClsName=java.lang.String, pendingUndeploy=false, > undeployed=false, usage=0]], > taskClsName=com.tudor.datagridI.server.tradegen.OrderHolderSaveRunnable, > sesId=63652976a51-2c4ae429-3284-4588 -a96e-7e487f6653a1, > startTime=1487796377472, endTime=9223372036854775807, > taskNodeId=2c4ae429-3284-4588-a96e-7e487f6653a1, > clsLdr=sun.misc.Launcher$AppClassLoader@18b4aac2, closed=false, cpSpi=null, > fail Spi=null, loadSpi=null, usage=1, fullSup=false, > subjId=2c4ae429-3284-4588-a96e-7e487f6653a1, mapFut=IgniteFuture > [orig=GridFutureAdapter [resFlag=0, res=null, startTime=1487796377491, > endTime=0, ignoreIn terrupts=false, state=INIT]]], > jobId=73652976a51-2c4ae429-3284-4588-a96e-7e487f6653a1]] > 109754 class org.apache.ignite.IgniteCheckedException: Failed to deserialize > object with given class loader: sun.misc.Launcher$AppClassLoader@18b4aac2 > 109755 at > org.apache.ignite.marshaller.optimized.OptimizedMarshaller.unmarshal(OptimizedMarshaller.java:250) > 109756 at > org.apache.ignite.internal.processors.job.GridJobWorker.initialize(GridJobWorker.java:409) > 109757 at > org.apache.ignite.internal.processors.job.GridJobProcessor.processJobExecuteRequest(GridJobProcessor.java:1089) > 109758 at > org.apache.ignite.internal.processors.job.GridJobProcessor$JobExecutionListener.onMessage(GridJobProcessor.java:1766) > 109759 at > org.apache.ignite.internal.managers.communication.GridIoManager.invokeListener(GridIoManager.java:1238) > 109760 at > org.apache.ignite.internal.managers.communication.GridIoManager.processRegularMessage0(GridIoManager.java:866) > 109761 at > org.apache.ignite.internal.managers.communication.GridIoManager.access$1700(GridIoManager.java:106) > 109762 at > org.apache.ignite.internal.managers.communication.GridIoManager$5.run(GridIoManager.java:829) > 109763 at > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) > 109764 at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) > 109765 at java.lang.Thread.run(Thread.java:745) > 109766 Caused by: java.io.EOFException: Attempt to read beyond the end of > the stream [pos=2216, more=1, max=2215] > 109767 at > org.apache.ignite.internal.util.io.GridUnsafeDataInput.offset(GridUnsafeDataInput.java:171) > 109768 at > org.apache.ignite.internal.util.io.GridUnsafeDataInput.readByte(GridUnsafeDataInput.java:398) > 109769 at > org.apache.ignite.marshaller.optimized.OptimizedObjectInputStream.readObjectOverride(OptimizedObjectInputStream.java:197) > 109770 at > java.io.ObjectInputStream.readObject(ObjectInputStream.java:367) > 109771 at > org.apache.ignite.marshaller.optimized.OptimizedObjectInputStream.readFields(OptimizedObjectInputStream.java:491) > 109772 at > org.apache.ignite.marshaller.optimized.OptimizedObjectInputStream.readSerializable(OptimizedObjectInputStream.java:579) > 109773 at > org.apache.ignite.marshaller.optimized.OptimizedClassDescriptor.read(OptimizedClassDescriptor.java:841) > 109774 at > org.apache.ignite.marshaller.optimized.OptimizedObjectInputStream.readObjectOverride(OptimizedObjectInputStream.java:324) > 109775 at > java.io.ObjectInputStream.readObject(ObjectInputStream.java:367) > 109776 at > org.apache.ignite.marshaller.optimized.OptimizedObjectInputStream.readFields(OptimizedObjectInputStream.java:491) > 109777 at > org.apache.ignite.marshaller.optimized.OptimizedObjectInputStream.readSerializable(OptimizedObjectInputStream.java:579) > 109778 at > org.apache.ignite.marshaller.optimized.OptimizedClassDescriptor.read(OptimizedClassDescriptor.java:841) > 109779 at > org.apache.ignite.marshaller.optimized.OptimizedObjectInputStream.readObjectOverride(OptimizedObjectInputStream.java:324) > 109780 at > java.io.ObjectInputStream.readObject(ObjectInputStream.java:367) > 109781 at > org.apache.ignite.marshaller.optimized.OptimizedMarshaller.unmarshal(OptimizedMarshaller.java:247) > 109782 ... 10 more > 109783 > > > > > -- > View this message in context: > http://apache-ignite-users.70518.x6.nabble.com/Pessimistic-TXN-did-not-release-lock-on-a-key-all-subsequent-txns-failed-tp10536p10833.html > Sent from the Apache Ignite Users mailing list archive at Nabble.com.
