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 <binti.sep...@tudor.com> 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.
