You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@ignite.apache.org by smurphy <sm...@trustwave.com> on 2017/10/19 21:24:56 UTC
Grid freezing
threaddump.tdump
<http://apache-ignite-users.70518.x6.nabble.com/file/t1317/threaddump.tdump>
I am using Ignite v2.1 and my code using Optimistic/Serializable
transactions and is locking up. When it does, there are a lot of `WARNING:
Found long running transaction` and `WARNING: Found long running cache
future` messages in the logs (see below). Eventually the grid freezes and
there are a lot of "IgniteInterruptedException: Got interrupted while
waiting for future to complete." (see below). Also, see attached thread dump
when the grid is finally stopped.
Using visor, I could see the active threads increase until all are consumed.
I boosted the thread pool count to 100 and saw the active threads rise
steadily until all were consumed. At theat point, the grid freezes up.
Using visor ping multiple times, the servers always ping successfully but
the client fails intermittently.
LONG RUNNING TRANSACTION:
2017-10-19 13:03:06,698 WARN [ ] grid-timeout-worker-#15%null%
{Log4JLogger.java:480} - Found long running transaction
[startTime=12:30:33.985, curTime=13:03:06.682, tx=GridNearTxLocal
[mappings=IgniteTxMappingsSingleImpl [mapping=GridDistributedTxMapping
[entries=[IgniteTxEntry [key=KeyCacheObjectImpl [part=126,
val=GridCacheInternalKeyImpl [name=SCAN_IDX, grpName=default-ds-group],
hasValBytes=true], cacheId=1481046058, txKey=IgniteTxKey
[key=KeyCacheObjectImpl [part=126, val=GridCacheInternalKeyImpl
[name=SCAN_IDX, grpName=default-ds-group], hasValBytes=true],
cacheId=1481046058], val=[op=TRANSFORM, val=null], prevVal=[op=NOOP,
val=null], oldVal=[op=NOOP, val=null], entryProcessorsCol=[IgniteBiTuple
[val1=GetAndIncrementProcessor [], val2=[Ljava.lang.Object;@49d9dc6c]],
ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null,
dhtVer=null, filters=[], filtersPassed=false, filtersSet=true,
entry=GridDhtDetachedCacheEntry [super=GridDistributedCacheEntry
[super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=126,
val=GridCacheInternalKeyImpl [name=SCAN_IDX, grpName=default-ds-group],
hasValBytes=true], val=null, startVer=1508434155232, ver=GridCacheVersion
[topVer=119473256, order=1508434155232, nodeOrder=2243], hash=-375255214,
extras=null, flags=0]]], prepared=0, locked=false,
nodeId=36b4d422-d011-4f77-919a-b8ffb089614b, locMapped=false,
expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0,
serReadVer=null, xidVer=GridCacheVersion [topVer=119473256,
order=1508434155230, nodeOrder=2243]]], explicitLock=false, dhtVer=null,
last=false, nearEntries=0, clientFirst=false,
node=36b4d422-d011-4f77-919a-b8ffb089614b]], nearLocallyMapped=false,
colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false,
thread=<failed to find active thread 109>,
mappings=IgniteTxMappingsSingleImpl [mapping=GridDistributedTxMapping
[entries=[IgniteTxEntry [key=KeyCacheObjectImpl [part=126,
val=GridCacheInternalKeyImpl [name=SCAN_IDX, grpName=default-ds-group],
hasValBytes=true], cacheId=1481046058, txKey=IgniteTxKey
[key=KeyCacheObjectImpl [part=126, val=GridCacheInternalKeyImpl
[name=SCAN_IDX, grpName=default-ds-group], hasValBytes=true],
cacheId=1481046058], val=[op=TRANSFORM, val=null], prevVal=[op=NOOP,
val=null], oldVal=[op=NOOP, val=null], entryProcessorsCol=[IgniteBiTuple
[val1=GetAndIncrementProcessor [], val2=[Ljava.lang.Object;@49d9dc6c]],
ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null,
dhtVer=null, filters=[], filtersPassed=false, filtersSet=true,
entry=GridDhtDetachedCacheEntry [super=GridDistributedCacheEntry
[super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=126,
val=GridCacheInternalKeyImpl [name=SCAN_IDX, grpName=default-ds-group],
hasValBytes=true], val=null, startVer=1508434155232, ver=GridCacheVersion
[topVer=119473256, order=1508434155232, nodeOrder=2243], hash=-375255214,
extras=null, flags=0]]], prepared=0, locked=false,
nodeId=36b4d422-d011-4f77-919a-b8ffb089614b, locMapped=false,
expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0,
serReadVer=null, xidVer=GridCacheVersion [topVer=119473256,
order=1508434155230, nodeOrder=2243]]], explicitLock=false, dhtVer=null,
last=false, nearEntries=0, clientFirst=false,
node=36b4d422-d011-4f77-919a-b8ffb089614b]], super=GridDhtTxLocalAdapter
[nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false,
super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false,
depEnabled=false, txState=IgniteTxImplicitSingleStateImpl [init=true,
recovery=false], super=IgniteTxAdapter [xidVer=GridCacheVersion
[topVer=119473256, order=1508434155230, nodeOrder=2243], writeVer=null,
implicit=true, loc=true, threadId=109, startTime=1508434233985,
nodeId=cb0332bd-1c18-4695-a75f-0d0ed4637b55, startVer=GridCacheVersion
[topVer=119473256, order=1508434155230, nodeOrder=2243], endVer=null,
isolation=READ_COMMITTED, concurrency=OPTIMISTIC, timeout=0,
sysInvalidate=false, sys=true, plc=2, commitVer=GridCacheVersion
[topVer=119473256, order=1508434155230, nodeOrder=2243], finalizing=NONE,
invalidParts=null, state=PREPARING, timedOut=false,
topVer=AffinityTopologyVersion [topVer=2243, minorTopVer=0],
duration=1952707ms, onePhaseCommit=true], size=1]]]]
LONG RUNNING CACHE FUTURE:
2017-10-19 13:03:06,709 WARN [ ] grid-timeout-worker-#15%null%
{Log4JLogger.java:480} - Found long running cache future
[startTime=12:30:33.985, curTime=13:03:06.682, fut=GridNearTxFinishFuture
[futId=d7d7ea53f51-2939d9ae-16bb-41f2-a756-32150fde4ecf, tx=GridNearTxLocal
[mappings=IgniteTxMappingsSingleImpl [mapping=GridDistributedTxMapping
[entries=[IgniteTxEntry [key=KeyCacheObjectImpl [part=126,
val=GridCacheInternalKeyImpl [name=SCAN_IDX, grpName=default-ds-group],
hasValBytes=true], cacheId=1481046058, txKey=IgniteTxKey
[key=KeyCacheObjectImpl [part=126, val=GridCacheInternalKeyImpl
[name=SCAN_IDX, grpName=default-ds-group], hasValBytes=true],
cacheId=1481046058], val=[op=TRANSFORM, val=null], prevVal=[op=NOOP,
val=null], oldVal=[op=NOOP, val=null], entryProcessorsCol=[IgniteBiTuple
[val1=GetAndIncrementProcessor [], val2=[Ljava.lang.Object;@49d9dc6c]],
ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null,
dhtVer=null, filters=[], filtersPassed=false, filtersSet=true,
entry=GridDhtDetachedCacheEntry [super=GridDistributedCacheEntry
[super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=126,
val=GridCacheInternalKeyImpl [name=SCAN_IDX, grpName=default-ds-group],
hasValBytes=true], val=null, startVer=1508434155232, ver=GridCacheVersion
[topVer=119473256, order=1508434155232, nodeOrder=2243], hash=-375255214,
extras=null, flags=0]]], prepared=0, locked=false,
nodeId=36b4d422-d011-4f77-919a-b8ffb089614b, locMapped=false,
expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0,
serReadVer=null, xidVer=GridCacheVersion [topVer=119473256,
order=1508434155230, nodeOrder=2243]]], explicitLock=false, dhtVer=null,
last=false, nearEntries=0, clientFirst=false,
node=36b4d422-d011-4f77-919a-b8ffb089614b]], nearLocallyMapped=false,
colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false,
thread=<failed to find active thread 109>,
mappings=IgniteTxMappingsSingleImpl [mapping=GridDistributedTxMapping
[entries=[IgniteTxEntry [key=KeyCacheObjectImpl [part=126,
val=GridCacheInternalKeyImpl [name=SCAN_IDX, grpName=default-ds-group],
hasValBytes=true], cacheId=1481046058, txKey=IgniteTxKey
[key=KeyCacheObjectImpl [part=126, val=GridCacheInternalKeyImpl
[name=SCAN_IDX, grpName=default-ds-group], hasValBytes=true],
cacheId=1481046058], val=[op=TRANSFORM, val=null], prevVal=[op=NOOP,
val=null], oldVal=[op=NOOP, val=null], entryProcessorsCol=[IgniteBiTuple
[val1=GetAndIncrementProcessor [], val2=[Ljava.lang.Object;@49d9dc6c]],
ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null,
dhtVer=null, filters=[], filtersPassed=false, filtersSet=true,
entry=GridDhtDetachedCacheEntry [super=GridDistributedCacheEntry
[super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=126,
val=GridCacheInternalKeyImpl [name=SCAN_IDX, grpName=default-ds-group],
hasValBytes=true], val=null, startVer=1508434155232, ver=GridCacheVersion
[topVer=119473256, order=1508434155232, nodeOrder=2243], hash=-375255214,
extras=null, flags=0]]], prepared=0, locked=false,
nodeId=36b4d422-d011-4f77-919a-b8ffb089614b, locMapped=false,
expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0,
serReadVer=null, xidVer=GridCacheVersion [topVer=119473256,
order=1508434155230, nodeOrder=2243]]], explicitLock=false, dhtVer=null,
last=false, nearEntries=0, clientFirst=false,
node=36b4d422-d011-4f77-919a-b8ffb089614b]], super=GridDhtTxLocalAdapter
[nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false,
super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false,
depEnabled=false, txState=IgniteTxImplicitSingleStateImpl [init=true,
recovery=false], super=IgniteTxAdapter [xidVer=GridCacheVersion
[topVer=119473256, order=1508434155230, nodeOrder=2243], writeVer=null,
implicit=true, loc=true, threadId=109, startTime=1508434233985,
nodeId=cb0332bd-1c18-4695-a75f-0d0ed4637b55, startVer=GridCacheVersion
[topVer=119473256, order=1508434155230, nodeOrder=2243], endVer=null,
isolation=READ_COMMITTED, concurrency=OPTIMISTIC, timeout=0,
sysInvalidate=false, sys=true, plc=2, commitVer=GridCacheVersion
[topVer=119473256, order=1508434155230, nodeOrder=2243], finalizing=NONE,
invalidParts=null, state=PREPARING, timedOut=false,
topVer=AffinityTopologyVersion [topVer=2243, minorTopVer=0],
duration=1952717ms, onePhaseCommit=true], size=1]]], commit=true,
mappings=IgniteTxMappingsSingleImpl [mapping=GridDistributedTxMapping
[entries=[IgniteTxEntry [key=KeyCacheObjectImpl [part=126,
val=GridCacheInternalKeyImpl [name=SCAN_IDX, grpName=default-ds-group],
hasValBytes=true], cacheId=1481046058, txKey=IgniteTxKey
[key=KeyCacheObjectImpl [part=126, val=GridCacheInternalKeyImpl
[name=SCAN_IDX, grpName=default-ds-group], hasValBytes=true],
cacheId=1481046058], val=[op=TRANSFORM, val=null], prevVal=[op=NOOP,
val=null], oldVal=[op=NOOP, val=null], entryProcessorsCol=[IgniteBiTuple
[val1=GetAndIncrementProcessor [], val2=[Ljava.lang.Object;@49d9dc6c]],
ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null,
dhtVer=null, filters=[], filtersPassed=false, filtersSet=true,
entry=GridDhtDetachedCacheEntry [super=GridDistributedCacheEntry
[super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=126,
val=GridCacheInternalKeyImpl [name=SCAN_IDX, grpName=default-ds-group],
hasValBytes=true], val=null, startVer=1508434155232, ver=GridCacheVersion
[topVer=119473256, order=1508434155232, nodeOrder=2243], hash=-375255214,
extras=null, flags=0]]], prepared=0, locked=false,
nodeId=36b4d422-d011-4f77-919a-b8ffb089614b, locMapped=false,
expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0,
serReadVer=null, xidVer=GridCacheVersion [topVer=119473256,
order=1508434155230, nodeOrder=2243]]], explicitLock=false, dhtVer=null,
last=false, nearEntries=0, clientFirst=false,
node=36b4d422-d011-4f77-919a-b8ffb089614b]], trackable=true,
finishOnePhaseCalled=false, innerFuts=[], super=GridCompoundIdentityFuture
[super=GridCompoundFuture [rdc=AlwaysTrueReducer [], initFlag=0,
lsnrCalls=0, done=false, cancelled=false, err=null, futs=[]]]]]
IGNITECHECKEDEXCEPTION:
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: SEVERE: Failed to execute
job [jobId=ac08ea53f51-cb0332bd-1c18-4695-a75f-0d0ed4637b55,
ses=GridJobSessionImpl [ses=GridTaskSessionImpl
[taskName=com.company.fragment.node.callable.DequeuePortionsCallable,
dep=GridDeployment [ts=1508433959490, depMode=SHARED,
clsLdr=sun.misc.Launcher$AppClassLoader@764c12b6,
clsLdrId=fa68ba53f51-85f1f563-695c-43f9-a263-e9f67e8925b7, userVer=0,
loc=true,
sampleClsName=o.a.i.i.processors.task.GridTaskProcessor$TaskDiscoveryListener$1,
pendingUndeploy=false, undeployed=false, usage=64],
taskClsName=com.company.fragment.node.callable.DequeuePortionsCallable,
sesId=9c08ea53f51-cb0332bd-1c18-4695-a75f-0d0ed4637b55,
startTime=1508434417976, endTime=9223372036854775807,
taskNodeId=cb0332bd-1c18-4695-a75f-0d0ed4637b55,
clsLdr=sun.misc.Launcher$AppClassLoader@764c12b6, closed=false, cpSpi=null,
failSpi=null, loadSpi=null, usage=1, fullSup=false, internal=false,
subjId=cb0332bd-1c18-4695-a75f-0d0ed4637b55, mapFut=IgniteFuture
[orig=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null,
hash=2051666823]], execName=null],
jobId=ac08ea53f51-cb0332bd-1c18-4695-a75f-0d0ed4637b55]]
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: class
org.apache.ignite.IgniteException: class
org.apache.ignite.IgniteInterruptedException: Got interrupted while waiting
for future to complete.
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
org.apache.ignite.internal.processors.closure.GridClosureProcessor$C2.execute(GridClosureProcessor.java:1850)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
org.apache.ignite.internal.processors.job.GridJobWorker$2.call(GridJobWorker.java:566)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
org.apache.ignite.internal.util.IgniteUtils.wrapThreadLoader(IgniteUtils.java:6608)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
org.apache.ignite.internal.processors.job.GridJobWorker.execute0(GridJobWorker.java:560)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
org.apache.ignite.internal.processors.job.GridJobWorker.body(GridJobWorker.java:489)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
org.apache.ignite.internal.processors.job.GridJobProcessor.processJobExecuteRequest(GridJobProcessor.java:1181)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
org.apache.ignite.internal.processors.job.GridJobProcessor$JobExecutionListener.onMessage(GridJobProcessor.java:1908)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
org.apache.ignite.internal.managers.communication.GridIoManager.invokeListener(GridIoManager.java:1556)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
org.apache.ignite.internal.managers.communication.GridIoManager.processRegularMessage0(GridIoManager.java:1184)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
org.apache.ignite.internal.managers.communication.GridIoManager.access$4200(GridIoManager.java:126)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
org.apache.ignite.internal.managers.communication.GridIoManager$9.run(GridIoManager.java:1097)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
java.lang.Thread.run(Unknown Source)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: Caused by:
javax.cache.CacheException: class
org.apache.ignite.IgniteInterruptedException: Got interrupted while waiting
for future to complete.
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
org.apache.ignite.internal.processors.cache.GridCacheUtils.convertToCacheException(GridCacheUtils.java:1312)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
org.apache.ignite.internal.processors.cache.IgniteCacheProxy.cacheException(IgniteCacheProxy.java:2630)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
org.apache.ignite.internal.processors.cache.IgniteCacheProxy.get(IgniteCacheProxy.java:1188)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
com.company.fragment.node.ignite.IgnitePortionDequeuer.dequeuePortionIds(IgnitePortionDequeuer.java:276)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
com.company.fragment.node.ignite.IgnitePortionDequeuer._dequeuePortionIds(IgnitePortionDequeuer.java:196)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
com.company.fragment.node.ignite.IgnitePortionDequeuer.dequeuePortions(IgnitePortionDequeuer.java:146)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
com.company.fragment.node.callable.DequeuePortionsCallable.call(DequeuePortionsCallable.java:44)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
com.company.fragment.node.callable.DequeuePortionsCallable.call(DequeuePortionsCallable.java:35)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
org.apache.ignite.internal.processors.closure.GridClosureProcessor$C2.execute(GridClosureProcessor.java:1847)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: ... 14 more
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: Caused by: class
org.apache.ignite.IgniteInterruptedException: Got interrupted while waiting
for future to complete.
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
org.apache.ignite.internal.util.IgniteUtils$3.apply(IgniteUtils.java:796)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
org.apache.ignite.internal.util.IgniteUtils$3.apply(IgniteUtils.java:794)
Oct 19 13:29:22 prod-srvr apache-ignite[46822]: ... 23 more
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Grid freezing
Posted by smurphy <sm...@trustwave.com>.
I figured this out at long last...
The root cause of the problem was the Scan object's toString method:
@Override
public String toString() {
return ReflectionToStringBuilder.reflectionToString(this);
}
It used the apache common-lang's RefelectionToStringBuilder and this jar was
not in the ignite libs folder.
Once in there, transactions worked with multiple server nodes under heavy
loads.
The problem was easy to reproduce - just remove this jar from the libs
folder.
The error message that results is the same as shown above and does not point
to the real underlying cause, so that is what caused the confusion:
org.apache.ignite.internal.processors.cache.transactions.IgniteTxLocalAdapter.implicitSingleResult(IgniteTxLocalAdapter.java:352)
I am guessing that because this ReflectionToStringBuilder.toString() is only
used in the Scan object's toString() method, it is never needed by Ignite
until at some point an exception is thrown and a logger calls the toString
on the Scan object and a java.lang.NoClassDefFoundError is not
anticipated...
I tried invoking the ReflectionToStringBuilder.toString() more directly from
the dequeuer code itself and I did see the expected error in the logs:
java.lang.NoClassDefFoundError:
org/apache/commons/lang/builder/ReflectionToStringBuilder at...
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Grid freezing
Posted by ezhuravlev <e....@gmail.com>.
Is it possible that in dequeuePortionIds you will have the same keys(at least
one the same key) for scanCache in different threads? If it's possible, I
think it's pretty easy to face a deadlock here with
_getCurrentMax(customerMaxCache, queryScan), while I suppose 2 different
Scans could have the same customer(well, at least it could be deduced from
your comments).
Could you share full reproducer with the community? It's hard to try to find
a deadlock if you don't even have a source code.
Evgenii
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Grid freezing
Posted by smurphy <sm...@trustwave.com>.
The WARNING message above is not consistently showing up in the logs.
Nodes are not going down either.
What I have found is that running 1 server and 2 clients does NOT freeze,
even under heavy loads.
But having 2 ignite servers does freeze up.
Two servers are unsuccessful either on separate boxes or on the same box
using localhost.
Looking at the thread dump of one server, 7 threads are waiting at
TransactionProxyImpl.commit (line 259) (Excerpt 1 & 2 below)
The thread dump of the other server has 8 thread waiting at
IgniteCacheProxy.getAllOutTx (line 1328) (Excerpt 3)
The thread number of one of these waiting threads is also waiting in the
CacheAffinitySharedManager (Excerpt 4)
Even though Excerpt 3 and 4 call getAllOutTx, they are the first place in
the the transaction block where an Ignite cache is called.
*Excerpt 1:*
"pub-#75%dna%" prio=5 tid=96 WAITING
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(<unknown string>)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.get0(GridFutureAdapter.java:176)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.get(GridFutureAdapter.java:139)
at
org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTxPrepareFuture.onDone(GridDhtTxPrepareFuture.java:779)
at
org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTxPrepareFuture.onDone(GridDhtTxPrepareFuture.java:103)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.onDone(GridFutureAdapter.java:461)
at
org.apache.ignite.internal.util.future.GridCompoundFuture.checkComplete(GridCompoundFuture.java:283)
Local Variable: java.lang.NullPointerException#2
at
org.apache.ignite.internal.util.future.GridCompoundFuture.markInitialized(GridCompoundFuture.java:269)
at
org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTxPrepareFuture.prepare0(GridDhtTxPrepareFuture.java:1468)
Local Variable: java.lang.NoClassDefFoundError#1
at
org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTxPrepareFuture.mapIfLocked(GridDhtTxPrepareFuture.java:668)
at
org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTxPrepareFuture.prepare(GridDhtTxPrepareFuture.java:1034)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxLocal.prepareAsyncLocal(GridNearTxLocal.java:3343)
at
org.apache.ignite.internal.processors.cache.transactions.IgniteTxHandler.prepareColocatedTx(IgniteTxHandler.java:221)
Local Variable:
org.apache.ignite.internal.processors.cache.transactions.IgniteTxHandler#1
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearOptimisticSerializableTxPrepareFuture.prepareLocal(GridNearOptimisticSerializableTxPrepareFuture.java:576)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearOptimisticSerializableTxPrepareFuture.prepare(GridNearOptimisticSerializableTxPrepareFuture.java:493)
Local Variable: org.apache.ignite.internal.util.GridLeanMap#24
Local Variable:
org.apache.ignite.spi.discovery.tcp.internal.TcpDiscoveryNode#1
Local Variable:
org.apache.ignite.internal.processors.cache.distributed.GridDistributedTxMapping#4
Local Variable:
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxPrepareRequest#1
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearOptimisticSerializableTxPrepareFuture.prepare(GridNearOptimisticSerializableTxPrepareFuture.java:407)
Local Variable: java.util.AbstractMap$2#1
Local Variable:
org.apache.ignite.internal.processors.cache.distributed.near.GridNearOptimisticSerializableTxPrepareFuture$MiniFuture#2
Local Variable: java.util.AbstractMap$2#2
Local Variable: java.util.ArrayList$Itr#1
Local Variable: java.util.ArrayList#7898
Local Variable: java.util.HashMap#5544
Local Variable:
org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTxMapping#1
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearOptimisticSerializableTxPrepareFuture.prepare0(GridNearOptimisticSerializableTxPrepareFuture.java:314)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearOptimisticTxPrepareFutureAdapter.prepareOnTopology(GridNearOptimisticTxPrepareFutureAdapter.java:137)
Local Variable:
org.apache.ignite.internal.processors.affinity.AffinityTopologyVersion#33
Local Variable:
org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture#11
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearOptimisticTxPrepareFutureAdapter.prepare(GridNearOptimisticTxPrepareFutureAdapter.java:74)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxLocal.prepareNearTxLocal(GridNearTxLocal.java:3110)
Local Variable:
org.apache.ignite.internal.processors.cache.distributed.near.GridNearOptimisticSerializableTxPrepareFuture#1
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxLocal.commitNearTxLocalAsync(GridNearTxLocal.java:3162)
Local Variable:
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxLocal#1
at
org.apache.ignite.internal.processors.cache.GridCacheSharedContext.commitTxAsync(GridCacheSharedContext.java:929)
at
org.apache.ignite.internal.processors.cache.transactions.TransactionProxyImpl.commit(TransactionProxyImpl.java:259)
*Excerpt 2:*
"pub-#112%dna%" prio=5 tid=133 WAITING
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(<unknown string>)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.get0(GridFutureAdapter.java:176)
Local Variable:
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxFinishFuture#4
at
org.apache.ignite.internal.util.future.GridFutureAdapter.get(GridFutureAdapter.java:139)
at
org.apache.ignite.internal.processors.cache.transactions.TransactionProxyImpl.commit(TransactionProxyImpl.java:264)
*Excerpt 3:*
"pub-#35%dna%" prio=5 tid=55 WAITING
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(<unknown string>)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.get0(GridFutureAdapter.java:176)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.get(GridFutureAdapter.java:139)
at
org.apache.ignite.internal.processors.cache.GridCacheGateway.enter(GridCacheGateway.java:166)
at
org.apache.ignite.internal.processors.cache.IgniteCacheProxy.onEnter(IgniteCacheProxy.java:2722)
at
org.apache.ignite.internal.processors.cache.IgniteCacheProxy.getAllOutTx(IgniteCacheProxy.java:1328)
Local Variable: java.util.HashSet#226
at
com.company.dna.scan.fragment.node.ignite.IgniteFragmentDequeuer._createPriorityWeights(IgniteFragmentDequeuer.java:236)
Local Variable:
com.company.dna.scan.fragment.node.domain.PriorityWeights#5
Local Variable: double[]#18
Local Variable:
org.apache.ignite.internal.processors.cache.IgniteCacheProxy#23
at
com.company.dna.scan.fragment.node.ignite.IgniteFragmentDequeuer.*exchange-worker-#30%dna%*(IgniteFragmentDequeuer.java:133)
*Excerpt 4:*
"*exchange-worker-#30%dna%*" prio=5 tid=48 WAITING
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(<unknown string>)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.get0(GridFutureAdapter.java:176)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.get(GridFutureAdapter.java:139)
at
org.apache.ignite.internal.processors.cache.CacheAffinitySharedManager.fetchAffinity(CacheAffinitySharedManager.java:1402)
Local Variable:
org.apache.ignite.internal.processors.affinity.GridAffinityAssignmentCache#4
Local Variable: org.apache.ignite.events.DiscoveryEvent#1
Local Variable:
org.apache.ignite.internal.managers.discovery.DiscoCache#1
at
org.apache.ignite.internal.processors.cache.CacheAffinitySharedManager.fetchAffinityOnJoin(CacheAffinitySharedManager.java:1377)
Local Variable: java.lang.Integer#3104
Local Variable: java.util.ArrayList#1017
Local Variable:
org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtAssignmentFetchFuture#8
at
org.apache.ignite.internal.processors.cache.CacheAffinitySharedManager.onServerJoin(CacheAffinitySharedManager.java:1293)
Local Variable:
org.apache.ignite.internal.processors.cache.CacheAffinitySharedManager#1
at
org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.onServerNodeEvent(GridDhtPartitionsExchangeFuture.java:896)
at
org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionsExchangeFuture.init(GridDhtPartitionsExchangeFuture.java:623)
Local Variable:
org.apache.ignite.internal.processors.affinity.AffinityTopologyVersion#4
at
org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker.body(GridCachePartitionExchangeManager.java:1901)
at
org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110)
Local Variable:
org.apache.ignite.internal.processors.cache.GridCachePartitionExchangeManager$ExchangeWorker#1
at java.lang.Thread.run(<unknown string>)
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Grid freezing
Posted by Eduard Shangareev <ed...@gmail.com>.
Hi, guys.
It looks like https://issues.apache.org/jira/browse/IGNITE-6313.
On Fri, Oct 27, 2017 at 10:28 AM, Evgenii Zhuravlev <
e.zhuravlev.wk@gmail.com> wrote:
> In logs i see messages:
>
> WARNING: Job is being cancelled because master task node left grid (as there is no one waiting for results, job will not be failed over)
>
> Most possible that it's a root cause of problem you've described earlier
>
>
> 2017-10-26 21:27 GMT+03:00 smurphy <sm...@trustwave.com>:
>
>> Here is an additional log message that suggests that rolling back the
>> transaction is not working.
>> I do not know why the isolation level in this log is marked as
>> READ_COMMITTED. All transactions are configured to be Optimistic and
>> Serializable..:
>>
>>
>> 2017-10-26 10:49:12,524 ERROR [dna-scan-engine 172.29.11.197]
>> progress_monitor_1 {Log4JLogger.java:495} - <dna-SCAN_CACHE> Failed to
>> add
>> cause to the end of cause chain (cause is printed here but will not be
>> propagated to callee): class o.a.i.i.transactions.IgniteTx
>> TimeoutCheckedException: Failed to acquire lock within provided timeout
>> for
>> transaction [timeout=10000, tx=GridNearTxLocal
>> [mappings=IgniteTxMappingsSingleImpl [mapping=GridDistributedTxMapping
>> [entries=[IgniteTxEntry [key=KeyCacheObjectImpl [part=311, val=311, hasVal
>> Bytes=true], cacheId=-211228266, txKey=IgniteTxKey [key=KeyCacheObjectImpl
>> [part=311, val=311, hasValBytes=true], cacheId=-211228266],
>> val=[op=DELETE,
>> val=null], prevVal=[op=NOOP, val=null], oldVal=[op=NOOP, val=null],
>> entryProcessorsCol=null, ttl=-1, conflictExpireTi
>> me=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[],
>> filtersPassed=false, filtersSet=true, entry=GridDhtDetachedCacheEntry
>> [super=GridDistributedCacheEntry [super=GridCacheMapEntry
>> [key=KeyCacheObjectImpl [part=311, val=311, hasValBytes=true], val=null,
>> startVer=1509032890673, ver=GridCacheVersion [topVer=120512802,
>> order=1509032890673, nodeOrder=4], hash=311, extras=null, flags=0]]],
>> prepared=0, locked=false, nodeId=790731d7-c002-436f-ae3e-9a3bd7944581,
>> locMapped=false, expiryPlc=null, transferExpiryPlc=false, flag
>> s=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion
>> [topVer=120512802, order=1509032890671, nodeOrder=4]]],
>> explicitLock=false,
>> dhtVer=null, last=false, nearEntries=0, clientFirst=false,
>> node=790731d7-c002-436f-ae3e-9a3bd7944581]], nearLocallyMapped=false,
>> colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false,
>> thread=<failed to find active thread 208>,
>> mappings=IgniteTxMappingsSingleImpl [mapping=GridDistributedTxMapping
>> [entries=[IgniteTxEntry [key=KeyCacheObjectImpl [part=311, val=311,
>> hasValBytes=
>> true], cacheId=-211228266, txKey=IgniteTxKey [key=KeyCacheObjectImpl
>> [part=311, val=311, hasValBytes=true], cacheId=-211228266],
>> val=[op=DELETE,
>> val=null], prevVal=[op=NOOP, val=null], oldVal=[op=NOOP, val=null],
>> entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1,
>> conflictVer=null, explicitVer=null, dhtVer=null, filters=[],
>> filtersPassed=false, filtersSet=true, entry=GridDhtDetachedCacheEntry
>> [super=GridDistributedCacheEntry [super=GridCacheMapEntry
>> [key=KeyCacheObjectImpl [part=311, val=311, hasValBytes=true], val=null,
>> start
>> Ver=1509032890673, ver=GridCacheVersion [topVer=120512802,
>> order=1509032890673, nodeOrder=4], hash=311, extras=null, flags=0]]],
>> prepared=0, locked=false, nodeId=790731d7-c002-436f-ae3e-9a3bd7944581,
>> locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, p
>> artUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion
>> [topVer=120512802,
>> order=1509032890671, nodeOrder=4]]], explicitLock=false, dhtVer=null,
>> last=false, nearEntries=0, clientFirst=false,
>> node=790731d7-c002-436f-ae3e-9a3bd7944581]], super=GridDhtTxLocalAdapter
>> [n
>> earOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false,
>> super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false,
>> depEnabled=false, txState=IgniteTxImplicitSingleStateImpl [init=true,
>> recovery=false], super=IgniteTxAdapter [xidVer=Gr
>> idCacheVersion [topVer=120512802, order=1509032890671, nodeOrder=4],
>> writeVer=null, implicit=true, loc=true, threadId=208,
>> startTime=1509032942451, nodeId=f55eb4f4-57cb-4a6e-b1db-5f91b8a0f34e,
>> startVer=GridCacheVersion [topVer=120512802, order=1509032890671,
>> nodeOrder
>> =4], endVer=null, isolation=READ_COMMITTED, concurrency=OPTIMISTIC,
>> timeout=10000, sysInvalidate=false, sys=false, plc=2,
>> commitVer=GridCacheVersion [topVer=120512802, order=1509032890671,
>> nodeOrder=4], finalizing=NONE, invalidParts=null, state=PREPARING,
>> timedOut=fal
>> se, topVer=AffinityTopologyVersion [topVer=4, minorTopVer=8],
>> duration=10024ms, onePhaseCommit=false], size=1]]]]
>> class org.apache.ignite.IgniteCheckedException: Failed to commit
>> transaction:
>> GridNearTxLocal[id=f219e595f51-00000000-072e-e122-0000-000000000004,
>> concurrency=OPTIMISTIC, isolation=READ_COMMITTED, state=ROLLED_BACK,
>> invalidate=false, rollbackOnly=true, nodeId=f55eb4f4
>> -57cb-4a6e-b1db-5f91b8a0f34e, duration=10037]
>> at
>> org.apache.ignite.internal.processors.cache.distributed.near
>> .GridNearTxFinishFuture.finish(GridNearTxFinishFuture.java:423)
>> at
>> org.apache.ignite.internal.processors.cache.distributed.near
>> .GridNearTxLocal.rollbackNearTxLocalAsync(GridNearTxLocal.java:3255)
>> at
>> org.apache.ignite.internal.processors.cache.distributed.near
>> .GridNearTxLocal$5.applyx(GridNearTxLocal.java:1624)
>> at
>> org.apache.ignite.internal.processors.cache.distributed.near
>> .GridNearTxLocal$5.applyx(GridNearTxLocal.java:1614)
>> at
>> org.apache.ignite.internal.util.lang.IgniteClosureX.apply(
>> IgniteClosureX.java:38)
>> at
>> org.apache.ignite.internal.util.future.GridFutureChainListen
>> er.applyCallback(GridFutureChainListener.java:78)
>> at
>> org.apache.ignite.internal.util.future.GridFutureChainListen
>> er.apply(GridFutureChainListener.java:70)
>> at
>> org.apache.ignite.internal.util.future.GridFutureChainListen
>> er.apply(GridFutureChainListener.java:30)
>> at
>> org.apache.ignite.internal.util.future.GridFutureAdapter.not
>> ifyListener(GridFutureAdapter.java:382)
>> at
>> org.apache.ignite.internal.util.future.GridFutureAdapter.unb
>> lock(GridFutureAdapter.java:346)
>> at
>> org.apache.ignite.internal.util.future.GridFutureAdapter.unb
>> lockAll(GridFutureAdapter.java:334)
>> at
>> org.apache.ignite.internal.util.future.GridFutureAdapter.onD
>> one(GridFutureAdapter.java:494)
>> at
>> org.apache.ignite.internal.processors.cache.GridCacheCompoun
>> dIdentityFuture.onDone(GridCacheCompoundIdentityFuture.java:56)
>> at
>> org.apache.ignite.internal.util.future.GridFutureAdapter.onD
>> one(GridFutureAdapter.java:473)
>> at
>> org.apache.ignite.internal.processors.cache.distributed.near
>> .GridNearTxFinishFuture.onDone(GridNearTxFinishFuture.java:340)
>> at
>> org.apache.ignite.internal.processors.cache.distributed.near
>> .GridNearTxFinishFuture.onDone(GridNearTxFinishFuture.java:69)
>>
>>
>>
>> --
>> Sent from: http://apache-ignite-users.70518.x6.nabble.com/
>>
>
>
Re: Grid freezing
Posted by Evgenii Zhuravlev <e....@gmail.com>.
In logs i see messages:
WARNING: Job is being cancelled because master task node left grid (as
there is no one waiting for results, job will not be failed over)
Most possible that it's a root cause of problem you've described earlier
2017-10-26 21:27 GMT+03:00 smurphy <sm...@trustwave.com>:
> Here is an additional log message that suggests that rolling back the
> transaction is not working.
> I do not know why the isolation level in this log is marked as
> READ_COMMITTED. All transactions are configured to be Optimistic and
> Serializable..:
>
>
> 2017-10-26 10:49:12,524 ERROR [dna-scan-engine 172.29.11.197]
> progress_monitor_1 {Log4JLogger.java:495} - <dna-SCAN_CACHE> Failed to
> add
> cause to the end of cause chain (cause is printed here but will not be
> propagated to callee): class o.a.i.i.transactions.IgniteTx
> TimeoutCheckedException: Failed to acquire lock within provided timeout for
> transaction [timeout=10000, tx=GridNearTxLocal
> [mappings=IgniteTxMappingsSingleImpl [mapping=GridDistributedTxMapping
> [entries=[IgniteTxEntry [key=KeyCacheObjectImpl [part=311, val=311, hasVal
> Bytes=true], cacheId=-211228266, txKey=IgniteTxKey [key=KeyCacheObjectImpl
> [part=311, val=311, hasValBytes=true], cacheId=-211228266], val=[op=DELETE,
> val=null], prevVal=[op=NOOP, val=null], oldVal=[op=NOOP, val=null],
> entryProcessorsCol=null, ttl=-1, conflictExpireTi
> me=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[],
> filtersPassed=false, filtersSet=true, entry=GridDhtDetachedCacheEntry
> [super=GridDistributedCacheEntry [super=GridCacheMapEntry
> [key=KeyCacheObjectImpl [part=311, val=311, hasValBytes=true], val=null,
> startVer=1509032890673, ver=GridCacheVersion [topVer=120512802,
> order=1509032890673, nodeOrder=4], hash=311, extras=null, flags=0]]],
> prepared=0, locked=false, nodeId=790731d7-c002-436f-ae3e-9a3bd7944581,
> locMapped=false, expiryPlc=null, transferExpiryPlc=false, flag
> s=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion
> [topVer=120512802, order=1509032890671, nodeOrder=4]]], explicitLock=false,
> dhtVer=null, last=false, nearEntries=0, clientFirst=false,
> node=790731d7-c002-436f-ae3e-9a3bd7944581]], nearLocallyMapped=false,
> colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false,
> thread=<failed to find active thread 208>,
> mappings=IgniteTxMappingsSingleImpl [mapping=GridDistributedTxMapping
> [entries=[IgniteTxEntry [key=KeyCacheObjectImpl [part=311, val=311,
> hasValBytes=
> true], cacheId=-211228266, txKey=IgniteTxKey [key=KeyCacheObjectImpl
> [part=311, val=311, hasValBytes=true], cacheId=-211228266], val=[op=DELETE,
> val=null], prevVal=[op=NOOP, val=null], oldVal=[op=NOOP, val=null],
> entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1,
> conflictVer=null, explicitVer=null, dhtVer=null, filters=[],
> filtersPassed=false, filtersSet=true, entry=GridDhtDetachedCacheEntry
> [super=GridDistributedCacheEntry [super=GridCacheMapEntry
> [key=KeyCacheObjectImpl [part=311, val=311, hasValBytes=true], val=null,
> start
> Ver=1509032890673, ver=GridCacheVersion [topVer=120512802,
> order=1509032890673, nodeOrder=4], hash=311, extras=null, flags=0]]],
> prepared=0, locked=false, nodeId=790731d7-c002-436f-ae3e-9a3bd7944581,
> locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, p
> artUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion
> [topVer=120512802,
> order=1509032890671, nodeOrder=4]]], explicitLock=false, dhtVer=null,
> last=false, nearEntries=0, clientFirst=false,
> node=790731d7-c002-436f-ae3e-9a3bd7944581]], super=GridDhtTxLocalAdapter
> [n
> earOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false,
> super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false,
> depEnabled=false, txState=IgniteTxImplicitSingleStateImpl [init=true,
> recovery=false], super=IgniteTxAdapter [xidVer=Gr
> idCacheVersion [topVer=120512802, order=1509032890671, nodeOrder=4],
> writeVer=null, implicit=true, loc=true, threadId=208,
> startTime=1509032942451, nodeId=f55eb4f4-57cb-4a6e-b1db-5f91b8a0f34e,
> startVer=GridCacheVersion [topVer=120512802, order=1509032890671, nodeOrder
> =4], endVer=null, isolation=READ_COMMITTED, concurrency=OPTIMISTIC,
> timeout=10000, sysInvalidate=false, sys=false, plc=2,
> commitVer=GridCacheVersion [topVer=120512802, order=1509032890671,
> nodeOrder=4], finalizing=NONE, invalidParts=null, state=PREPARING,
> timedOut=fal
> se, topVer=AffinityTopologyVersion [topVer=4, minorTopVer=8],
> duration=10024ms, onePhaseCommit=false], size=1]]]]
> class org.apache.ignite.IgniteCheckedException: Failed to commit
> transaction:
> GridNearTxLocal[id=f219e595f51-00000000-072e-e122-0000-000000000004,
> concurrency=OPTIMISTIC, isolation=READ_COMMITTED, state=ROLLED_BACK,
> invalidate=false, rollbackOnly=true, nodeId=f55eb4f4
> -57cb-4a6e-b1db-5f91b8a0f34e, duration=10037]
> at
> org.apache.ignite.internal.processors.cache.distributed.
> near.GridNearTxFinishFuture.finish(GridNearTxFinishFuture.java:423)
> at
> org.apache.ignite.internal.processors.cache.distributed.
> near.GridNearTxLocal.rollbackNearTxLocalAsync(GridNearTxLocal.java:3255)
> at
> org.apache.ignite.internal.processors.cache.distributed.
> near.GridNearTxLocal$5.applyx(GridNearTxLocal.java:1624)
> at
> org.apache.ignite.internal.processors.cache.distributed.
> near.GridNearTxLocal$5.applyx(GridNearTxLocal.java:1614)
> at
> org.apache.ignite.internal.util.lang.IgniteClosureX.
> apply(IgniteClosureX.java:38)
> at
> org.apache.ignite.internal.util.future.GridFutureChainListener.
> applyCallback(GridFutureChainListener.java:78)
> at
> org.apache.ignite.internal.util.future.GridFutureChainListener.apply(
> GridFutureChainListener.java:70)
> at
> org.apache.ignite.internal.util.future.GridFutureChainListener.apply(
> GridFutureChainListener.java:30)
> at
> org.apache.ignite.internal.util.future.GridFutureAdapter.notifyListener(
> GridFutureAdapter.java:382)
> at
> org.apache.ignite.internal.util.future.GridFutureAdapter.
> unblock(GridFutureAdapter.java:346)
> at
> org.apache.ignite.internal.util.future.GridFutureAdapter.
> unblockAll(GridFutureAdapter.java:334)
> at
> org.apache.ignite.internal.util.future.GridFutureAdapter.
> onDone(GridFutureAdapter.java:494)
> at
> org.apache.ignite.internal.processors.cache.GridCacheCompoundIdentityFutur
> e.onDone(GridCacheCompoundIdentityFuture.java:56)
> at
> org.apache.ignite.internal.util.future.GridFutureAdapter.
> onDone(GridFutureAdapter.java:473)
> at
> org.apache.ignite.internal.processors.cache.distributed.
> near.GridNearTxFinishFuture.onDone(GridNearTxFinishFuture.java:340)
> at
> org.apache.ignite.internal.processors.cache.distributed.
> near.GridNearTxFinishFuture.onDone(GridNearTxFinishFuture.java:69)
>
>
>
> --
> Sent from: http://apache-ignite-users.70518.x6.nabble.com/
>
Re: Grid freezing
Posted by smurphy <sm...@trustwave.com>.
Here is an additional log message that suggests that rolling back the
transaction is not working.
I do not know why the isolation level in this log is marked as
READ_COMMITTED. All transactions are configured to be Optimistic and
Serializable..:
2017-10-26 10:49:12,524 ERROR [dna-scan-engine 172.29.11.197]
progress_monitor_1 {Log4JLogger.java:495} - <dna-SCAN_CACHE> Failed to add
cause to the end of cause chain (cause is printed here but will not be
propagated to callee): class o.a.i.i.transactions.IgniteTx
TimeoutCheckedException: Failed to acquire lock within provided timeout for
transaction [timeout=10000, tx=GridNearTxLocal
[mappings=IgniteTxMappingsSingleImpl [mapping=GridDistributedTxMapping
[entries=[IgniteTxEntry [key=KeyCacheObjectImpl [part=311, val=311, hasVal
Bytes=true], cacheId=-211228266, txKey=IgniteTxKey [key=KeyCacheObjectImpl
[part=311, val=311, hasValBytes=true], cacheId=-211228266], val=[op=DELETE,
val=null], prevVal=[op=NOOP, val=null], oldVal=[op=NOOP, val=null],
entryProcessorsCol=null, ttl=-1, conflictExpireTi
me=-1, conflictVer=null, explicitVer=null, dhtVer=null, filters=[],
filtersPassed=false, filtersSet=true, entry=GridDhtDetachedCacheEntry
[super=GridDistributedCacheEntry [super=GridCacheMapEntry
[key=KeyCacheObjectImpl [part=311, val=311, hasValBytes=true], val=null,
startVer=1509032890673, ver=GridCacheVersion [topVer=120512802,
order=1509032890673, nodeOrder=4], hash=311, extras=null, flags=0]]],
prepared=0, locked=false, nodeId=790731d7-c002-436f-ae3e-9a3bd7944581,
locMapped=false, expiryPlc=null, transferExpiryPlc=false, flag
s=0, partUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion
[topVer=120512802, order=1509032890671, nodeOrder=4]]], explicitLock=false,
dhtVer=null, last=false, nearEntries=0, clientFirst=false,
node=790731d7-c002-436f-ae3e-9a3bd7944581]], nearLocallyMapped=false,
colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false,
thread=<failed to find active thread 208>,
mappings=IgniteTxMappingsSingleImpl [mapping=GridDistributedTxMapping
[entries=[IgniteTxEntry [key=KeyCacheObjectImpl [part=311, val=311,
hasValBytes=
true], cacheId=-211228266, txKey=IgniteTxKey [key=KeyCacheObjectImpl
[part=311, val=311, hasValBytes=true], cacheId=-211228266], val=[op=DELETE,
val=null], prevVal=[op=NOOP, val=null], oldVal=[op=NOOP, val=null],
entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1,
conflictVer=null, explicitVer=null, dhtVer=null, filters=[],
filtersPassed=false, filtersSet=true, entry=GridDhtDetachedCacheEntry
[super=GridDistributedCacheEntry [super=GridCacheMapEntry
[key=KeyCacheObjectImpl [part=311, val=311, hasValBytes=true], val=null,
start
Ver=1509032890673, ver=GridCacheVersion [topVer=120512802,
order=1509032890673, nodeOrder=4], hash=311, extras=null, flags=0]]],
prepared=0, locked=false, nodeId=790731d7-c002-436f-ae3e-9a3bd7944581,
locMapped=false, expiryPlc=null, transferExpiryPlc=false, flags=0, p
artUpdateCntr=0, serReadVer=null, xidVer=GridCacheVersion [topVer=120512802,
order=1509032890671, nodeOrder=4]]], explicitLock=false, dhtVer=null,
last=false, nearEntries=0, clientFirst=false,
node=790731d7-c002-436f-ae3e-9a3bd7944581]], super=GridDhtTxLocalAdapter [n
earOnOriginatingNode=false, nearNodes=[], dhtNodes=[], explicitLock=false,
super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false,
depEnabled=false, txState=IgniteTxImplicitSingleStateImpl [init=true,
recovery=false], super=IgniteTxAdapter [xidVer=Gr
idCacheVersion [topVer=120512802, order=1509032890671, nodeOrder=4],
writeVer=null, implicit=true, loc=true, threadId=208,
startTime=1509032942451, nodeId=f55eb4f4-57cb-4a6e-b1db-5f91b8a0f34e,
startVer=GridCacheVersion [topVer=120512802, order=1509032890671, nodeOrder
=4], endVer=null, isolation=READ_COMMITTED, concurrency=OPTIMISTIC,
timeout=10000, sysInvalidate=false, sys=false, plc=2,
commitVer=GridCacheVersion [topVer=120512802, order=1509032890671,
nodeOrder=4], finalizing=NONE, invalidParts=null, state=PREPARING,
timedOut=fal
se, topVer=AffinityTopologyVersion [topVer=4, minorTopVer=8],
duration=10024ms, onePhaseCommit=false], size=1]]]]
class org.apache.ignite.IgniteCheckedException: Failed to commit
transaction:
GridNearTxLocal[id=f219e595f51-00000000-072e-e122-0000-000000000004,
concurrency=OPTIMISTIC, isolation=READ_COMMITTED, state=ROLLED_BACK,
invalidate=false, rollbackOnly=true, nodeId=f55eb4f4
-57cb-4a6e-b1db-5f91b8a0f34e, duration=10037]
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxFinishFuture.finish(GridNearTxFinishFuture.java:423)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxLocal.rollbackNearTxLocalAsync(GridNearTxLocal.java:3255)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxLocal$5.applyx(GridNearTxLocal.java:1624)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxLocal$5.applyx(GridNearTxLocal.java:1614)
at
org.apache.ignite.internal.util.lang.IgniteClosureX.apply(IgniteClosureX.java:38)
at
org.apache.ignite.internal.util.future.GridFutureChainListener.applyCallback(GridFutureChainListener.java:78)
at
org.apache.ignite.internal.util.future.GridFutureChainListener.apply(GridFutureChainListener.java:70)
at
org.apache.ignite.internal.util.future.GridFutureChainListener.apply(GridFutureChainListener.java:30)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.notifyListener(GridFutureAdapter.java:382)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.unblock(GridFutureAdapter.java:346)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.unblockAll(GridFutureAdapter.java:334)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.onDone(GridFutureAdapter.java:494)
at
org.apache.ignite.internal.processors.cache.GridCacheCompoundIdentityFuture.onDone(GridCacheCompoundIdentityFuture.java:56)
at
org.apache.ignite.internal.util.future.GridFutureAdapter.onDone(GridFutureAdapter.java:473)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxFinishFuture.onDone(GridNearTxFinishFuture.java:340)
at
org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxFinishFuture.onDone(GridNearTxFinishFuture.java:69)
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Grid freezing
Posted by smurphy <sm...@trustwave.com>.
One thing that I see in the logs looks to me like a NullPointerException on
attempting to commit an optimistic/serializable transaction.
My reading of this excpetion is that an optimistic lock conflict is
correctly detected in prepare0 but that eventually the code incorrectly
attempts to return this.ret which is null rather than an
IgniteTxOptimisticCheckedException...:
Oct 25 19:25:46 srvr.company apache-ignite[45092]: [19:25:46] (err) Failed
to execute compound future reducer: GridDhtTxPrepareFuture
[futId=2a3ec065f51-75e18206-0fee-4926-99be-bb6fee7b5828, err=null,
replied=1, mapped=1, reads=[], writes=[IgniteTxEntry [key=KeyCacheObjectImpl
[part=115, val=115, hasValBytes=true], cacheId=-211228266, txKey=IgniteTxKey
[key=KeyCacheObjectImpl [part=115, val=115, hasValBytes=true],
cacheId=-211228266], val=[op=UPDATE,
val=com.company.dna.scan.fragment.node.domain.Scan [idHash=1148364470,
hash=525731140, _fragmentIds=HashSet {}, _scannerGroupId=16,
_visibility=EXTERNAL, _scanUUID=d1a7a992-6ff2-4eb0-8398-06e45b15d08b,
_customerId=6779780, _customerMaxReached=false, _priority=1,
_scanStartedMsgSent=false, _empty=true, _idx=115, _canceled=true,
_scanId=45534, _version=2]], prevVal=[op=NOOP, val=null], oldVal=[op=NOOP,
val=null], entryProcessorsCol=null, ttl=-1, conflictExpireTime=-1,
conflictVer=null, explicitVer=null, dhtVer=null, filters=[],
filtersPassed=false, filtersSet=false, entry=GridDhtCacheEntry [rdrs=[],
part=115, super=GridDistributedCacheEntry [super=GridCacheMapEntry
[key=KeyCacheObjectImpl [part=115, val=115, hasValBytes=true],
val=com.company.dna.scan.fragment.node.domain.Scan [idHash=582900940,
hash=-1150571357, _fragmentIds=HashSet {}, _scannerGroupId=16,
_visibility=EXTERNAL, _scanUUID=d1a7a992-6ff2-4eb0-8398-06e45b15d08b,
_customerId=6779780, _customerMaxReached=false, _priority=1,
_scanStartedMsgSent=true, _empty=true, _idx=115, _canceled=false,
_scanId=45534, _version=3], startVer=1508977480914, ver=GridCacheVersion
[topVer=120361566, order=1508977480909, nodeOrder=33], hash=115,
extras=GridCacheMvccEntryExtras [mvcc=GridCacheMvcc
[locs=[GridCacheMvccCandidate [nodeId=47680ca3-827f-4788-af9e-d73dd7b030e0,
ver=GridCacheVersion [topVer=120361566, order=1508977480913, nodeOrder=33],
threadId=111, id=396, topVer=AffinityTopologyVersion [topVer=39,
minorTopVer=0], reentry=null,
otherNodeId=7a2804c4-5fae-4258-b6e2-96e75a219ea7, otherVer=GridCacheVersion
[topVer=120361566, order=1508977480890, nodeOrder=39], mappedD
Oct 25 19:25:46 srvr.company apache-ignite[45092]: htNodes=null,
mappedNearNodes=null, ownerVer=null, serOrder=GridCacheVersion
[topVer=120361566, order=1508977480890, nodeOrder=39],
key=KeyCacheObjectImpl [part=115, val=115, 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|read=0,
prevVer=null, nextVer=null]], rmts=null]], flags=2]]], prepared=1,
locked=false, nodeId=null, locMapped=false, expiryPlc=null,
transferExpiryPlc=false, flags=0, partUpdateCntr=0,
serReadVer=GridCacheVersion [topVer=120361566, order=1508977480161,
nodeOrder=33], xidVer=null]], trackable=true, nearMiniId=2, last=true,
retVal=false, ret=null, lockKeys=[], forceKeysFut=null, locksReady=true,
invoke=false, timeoutObj=PrepareTimeoutObject [timeout=9976],
xid=GridCacheVersion [topVer=120361566, order=1508977480913, nodeOrder=33],
innerFuts=[], super=GridCompoundFuture
[rdc=o.a.i.i.processors.cache.distributed.dht.GridDhtTxPrepareFuture$1@38648d98,
initFlag=1, lsnrCalls=0, done=false, cancelled=false, err=null,
futs=[]]]java.lang.NullPointerException
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.processors.cache.transactions.IgniteTxLocalAdapter.implicitSingleResult(IgniteTxLocalAdapter.java:352)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTxPrepareFuture.createPrepareResponse(GridDhtTxPrepareFuture.java:875)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTxPrepareFuture.onDone(GridDhtTxPrepareFuture.java:763)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTxPrepareFuture.onDone(GridDhtTxPrepareFuture.java:103)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.util.future.GridFutureAdapter.onDone(GridFutureAdapter.java:450)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.util.future.GridCompoundFuture.checkComplete(GridCompoundFuture.java:278)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.util.future.GridCompoundFuture.markInitialized(GridCompoundFuture.java:269)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTxPrepareFuture.prepare0(GridDhtTxPrepareFuture.java:1468)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTxPrepareFuture.mapIfLocked(GridDhtTxPrepareFuture.java:668)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTxPrepareFuture.prepare(GridDhtTxPrepareFuture.java:1034)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtTxLocal.prepareAsync(GridDhtTxLocal.java:410)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.processors.cache.transactions.IgniteTxHandler.prepareNearTx(IgniteTxHandler.java:459)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.processors.cache.transactions.IgniteTxHandler.processNearTxPrepareRequest(IgniteTxHandler.java:121)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.processors.cache.transactions.IgniteTxHandler.access$000(IgniteTxHandler.java:95)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.processors.cache.transactions.IgniteTxHandler$1.apply(IgniteTxHandler.java:141)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.processors.cache.transactions.IgniteTxHandler$1.apply(IgniteTxHandler.java:139)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.processMessage(GridCacheIoManager.java:1042)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.onMessage0(GridCacheIoManager.java:561)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.handleMessage(GridCacheIoManager.java:378)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.handleMessage(GridCacheIoManager.java:304)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.processors.cache.GridCacheIoManager.access$100(GridCacheIoManager.java:99)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.processors.cache.GridCacheIoManager$1.onMessage(GridCacheIoManager.java:293)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.managers.communication.GridIoManager.invokeListener(GridIoManager.java:1556)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.managers.communication.GridIoManager.processRegularMessage0(GridIoManager.java:1184)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.managers.communication.GridIoManager.access$4200(GridIoManager.java:126)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.managers.communication.GridIoManager$9.run(GridIoManager.java:1097)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
org.apache.ignite.internal.util.StripedExecutor$Stripe.run(StripedExecutor.java:483)
Oct 25 19:25:46 srvr.company apache-ignite[45092]: at
java.lang.Thread.run(Unknown Source)
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Grid freezing
Posted by smurphy <sm...@trustwave.com>.
log_1.txt
<http://apache-ignite-users.70518.x6.nabble.com/file/t1317/log_1.txt>
log_2.txt
<http://apache-ignite-users.70518.x6.nabble.com/file/t1317/log_2.txt>
log_3.txt
<http://apache-ignite-users.70518.x6.nabble.com/file/t1317/log_3.txt>
I don't see any nodes shutting down until 9 minutes after this particular
log..
But please see the attached are server logs for fuller details..
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Grid freezing
Posted by Evgenii Zhuravlev <e....@gmail.com>.
Looks like job was canceled. Are you sure that you didn't cancel this job
directly or node on which this job running was not stopped?
2017-10-26 17:18 GMT+03:00 smurphy <sm...@trustwave.com>:
> No - this is what the invocation looks like:
>
> DequeuePortionsCallable job = new
> DequeuePortionsCallable(ignitePortionDequeuer);
> DequeuedPortionResponse response = _ignite.compute().call(job);
>
>
>
>
> --
> Sent from: http://apache-ignite-users.70518.x6.nabble.com/
>
Re: Grid freezing
Posted by smurphy <sm...@trustwave.com>.
No - this is what the invocation looks like:
DequeuePortionsCallable job = new
DequeuePortionsCallable(ignitePortionDequeuer);
DequeuedPortionResponse response = _ignite.compute().call(job);
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Grid freezing
Posted by Evgenii Zhuravlev <e....@gmail.com>.
Is it possible that you run DequeuePortionsCallable with timeout?
Evgenii
2017-10-26 6:40 GMT+03:00 smurphy <sm...@trustwave.com>:
> I added a transaction timeout of 10000 millis and a transation size of 100
> (transaction is Optimistic and Serializable)...
>
> I see no TransactionTimeoutExceptions, just the following:
> CacheException: class org.apache.ignite.IgniteInterruptedException: Got
> interrupted while waiting for future to complete..
>
>
>
> --
> Sent from: http://apache-ignite-users.70518.x6.nabble.com/
>
Re: Grid freezing
Posted by smurphy <sm...@trustwave.com>.
I added a transaction timeout of 10000 millis and a transation size of 100
(transaction is Optimistic and Serializable)...
I see no TransactionTimeoutExceptions, just the following:
CacheException: class org.apache.ignite.IgniteInterruptedException: Got
interrupted while waiting for future to complete..
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Grid freezing
Posted by smurphy <sm...@trustwave.com>.
Thanks Evgenii,
I'll add that catch block and see if it sheds any light on the issue.
The client's transaction configuration is set to Optimistic and Serializable
and the transaction within the try with resources block is explicitly set to
Optimistic and Serializable, which should preclude deadlock...but there does
seem to be deadlock..
The servers do not have any transaction configuration set explicitly..
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Grid freezing
Posted by Evgenii Zhuravlev <e....@gmail.com>.
Looks like possible deadlock. Please add timeout for transactions and check
it with deadlock detection, as described here:
https://apacheignite.readme.io/docs/transactions#section-deadlock-detection
Evgenii
2017-10-23 21:16 GMT+03:00 smurphy <sm...@trustwave.com>:
> IgnitePortionDequeuer.java
> <http://apache-ignite-users.70518.x6.nabble.com/file/
> t1317/IgnitePortionDequeuer.java>
>
> top.visor
> <http://apache-ignite-users.70518.x6.nabble.com/file/t1317/top.visor>
>
> Hi Evgenii,
>
> See the attached top command and java file..
>
>
>
> --
> Sent from: http://apache-ignite-users.70518.x6.nabble.com/
>
Re: Grid freezing
Posted by smurphy <sm...@trustwave.com>.
IgnitePortionDequeuer.java
<http://apache-ignite-users.70518.x6.nabble.com/file/t1317/IgnitePortionDequeuer.java>
top.visor
<http://apache-ignite-users.70518.x6.nabble.com/file/t1317/top.visor>
Hi Evgenii,
See the attached top command and java file..
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Grid freezing
Posted by Evgenii Zhuravlev <e....@gmail.com>.
Hi!
How many nodes do you have? How many CPUs? Could you provide a code of
com.company.node.ignite.IgnitePortionDequeuer
or at least a dequeuePortions method?
Evgenii
2017-10-20 0:24 GMT+03:00 smurphy <sm...@trustwave.com>:
> threaddump.tdump
> <http://apache-ignite-users.70518.x6.nabble.com/file/
> t1317/threaddump.tdump>
>
> I am using Ignite v2.1 and my code using Optimistic/Serializable
> transactions and is locking up. When it does, there are a lot of `WARNING:
> Found long running transaction` and `WARNING: Found long running cache
> future` messages in the logs (see below). Eventually the grid freezes and
> there are a lot of "IgniteInterruptedException: Got interrupted while
> waiting for future to complete." (see below). Also, see attached thread
> dump
> when the grid is finally stopped.
>
> Using visor, I could see the active threads increase until all are
> consumed.
> I boosted the thread pool count to 100 and saw the active threads rise
> steadily until all were consumed. At theat point, the grid freezes up.
>
> Using visor ping multiple times, the servers always ping successfully but
> the client fails intermittently.
>
> LONG RUNNING TRANSACTION:
>
> 2017-10-19 13:03:06,698 WARN [ ] grid-timeout-worker-#15%null%
> {Log4JLogger.java:480} - Found long running transaction
> [startTime=12:30:33.985, curTime=13:03:06.682, tx=GridNearTxLocal
> [mappings=IgniteTxMappingsSingleImpl [mapping=GridDistributedTxMapping
> [entries=[IgniteTxEntry [key=KeyCacheObjectImpl [part=126,
> val=GridCacheInternalKeyImpl [name=SCAN_IDX, grpName=default-ds-group],
> hasValBytes=true], cacheId=1481046058, txKey=IgniteTxKey
> [key=KeyCacheObjectImpl [part=126, val=GridCacheInternalKeyImpl
> [name=SCAN_IDX, grpName=default-ds-group], hasValBytes=true],
> cacheId=1481046058], val=[op=TRANSFORM, val=null], prevVal=[op=NOOP,
> val=null], oldVal=[op=NOOP, val=null], entryProcessorsCol=[IgniteBiTuple
> [val1=GetAndIncrementProcessor [], val2=[Ljava.lang.Object;@49d9dc6c]],
> ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null,
> dhtVer=null, filters=[], filtersPassed=false, filtersSet=true,
> entry=GridDhtDetachedCacheEntry [super=GridDistributedCacheEntry
> [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=126,
> val=GridCacheInternalKeyImpl [name=SCAN_IDX, grpName=default-ds-group],
> hasValBytes=true], val=null, startVer=1508434155232, ver=GridCacheVersion
> [topVer=119473256, order=1508434155232, nodeOrder=2243], hash=-375255214,
> extras=null, flags=0]]], prepared=0, locked=false,
> nodeId=36b4d422-d011-4f77-919a-b8ffb089614b, locMapped=false,
> expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0,
> serReadVer=null, xidVer=GridCacheVersion [topVer=119473256,
> order=1508434155230, nodeOrder=2243]]], explicitLock=false, dhtVer=null,
> last=false, nearEntries=0, clientFirst=false,
> node=36b4d422-d011-4f77-919a-b8ffb089614b]], nearLocallyMapped=false,
> colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false,
> thread=<failed to find active thread 109>,
> mappings=IgniteTxMappingsSingleImpl [mapping=GridDistributedTxMapping
> [entries=[IgniteTxEntry [key=KeyCacheObjectImpl [part=126,
> val=GridCacheInternalKeyImpl [name=SCAN_IDX, grpName=default-ds-group],
> hasValBytes=true], cacheId=1481046058, txKey=IgniteTxKey
> [key=KeyCacheObjectImpl [part=126, val=GridCacheInternalKeyImpl
> [name=SCAN_IDX, grpName=default-ds-group], hasValBytes=true],
> cacheId=1481046058], val=[op=TRANSFORM, val=null], prevVal=[op=NOOP,
> val=null], oldVal=[op=NOOP, val=null], entryProcessorsCol=[IgniteBiTuple
> [val1=GetAndIncrementProcessor [], val2=[Ljava.lang.Object;@49d9dc6c]],
> ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null,
> dhtVer=null, filters=[], filtersPassed=false, filtersSet=true,
> entry=GridDhtDetachedCacheEntry [super=GridDistributedCacheEntry
> [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=126,
> val=GridCacheInternalKeyImpl [name=SCAN_IDX, grpName=default-ds-group],
> hasValBytes=true], val=null, startVer=1508434155232, ver=GridCacheVersion
> [topVer=119473256, order=1508434155232, nodeOrder=2243], hash=-375255214,
> extras=null, flags=0]]], prepared=0, locked=false,
> nodeId=36b4d422-d011-4f77-919a-b8ffb089614b, locMapped=false,
> expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0,
> serReadVer=null, xidVer=GridCacheVersion [topVer=119473256,
> order=1508434155230, nodeOrder=2243]]], explicitLock=false, dhtVer=null,
> last=false, nearEntries=0, clientFirst=false,
> node=36b4d422-d011-4f77-919a-b8ffb089614b]], super=GridDhtTxLocalAdapter
> [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[],
> explicitLock=false,
> super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false,
> depEnabled=false, txState=IgniteTxImplicitSingleStateImpl [init=true,
> recovery=false], super=IgniteTxAdapter [xidVer=GridCacheVersion
> [topVer=119473256, order=1508434155230, nodeOrder=2243], writeVer=null,
> implicit=true, loc=true, threadId=109, startTime=1508434233985,
> nodeId=cb0332bd-1c18-4695-a75f-0d0ed4637b55, startVer=GridCacheVersion
> [topVer=119473256, order=1508434155230, nodeOrder=2243], endVer=null,
> isolation=READ_COMMITTED, concurrency=OPTIMISTIC, timeout=0,
> sysInvalidate=false, sys=true, plc=2, commitVer=GridCacheVersion
> [topVer=119473256, order=1508434155230, nodeOrder=2243], finalizing=NONE,
> invalidParts=null, state=PREPARING, timedOut=false,
> topVer=AffinityTopologyVersion [topVer=2243, minorTopVer=0],
> duration=1952707ms, onePhaseCommit=true], size=1]]]]
>
> LONG RUNNING CACHE FUTURE:
> 2017-10-19 13:03:06,709 WARN [ ] grid-timeout-worker-#15%null%
> {Log4JLogger.java:480} - Found long running cache future
> [startTime=12:30:33.985, curTime=13:03:06.682, fut=GridNearTxFinishFuture
> [futId=d7d7ea53f51-2939d9ae-16bb-41f2-a756-32150fde4ecf,
> tx=GridNearTxLocal
> [mappings=IgniteTxMappingsSingleImpl [mapping=GridDistributedTxMapping
> [entries=[IgniteTxEntry [key=KeyCacheObjectImpl [part=126,
> val=GridCacheInternalKeyImpl [name=SCAN_IDX, grpName=default-ds-group],
> hasValBytes=true], cacheId=1481046058, txKey=IgniteTxKey
> [key=KeyCacheObjectImpl [part=126, val=GridCacheInternalKeyImpl
> [name=SCAN_IDX, grpName=default-ds-group], hasValBytes=true],
> cacheId=1481046058], val=[op=TRANSFORM, val=null], prevVal=[op=NOOP,
> val=null], oldVal=[op=NOOP, val=null], entryProcessorsCol=[IgniteBiTuple
> [val1=GetAndIncrementProcessor [], val2=[Ljava.lang.Object;@49d9dc6c]],
> ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null,
> dhtVer=null, filters=[], filtersPassed=false, filtersSet=true,
> entry=GridDhtDetachedCacheEntry [super=GridDistributedCacheEntry
> [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=126,
> val=GridCacheInternalKeyImpl [name=SCAN_IDX, grpName=default-ds-group],
> hasValBytes=true], val=null, startVer=1508434155232, ver=GridCacheVersion
> [topVer=119473256, order=1508434155232, nodeOrder=2243], hash=-375255214,
> extras=null, flags=0]]], prepared=0, locked=false,
> nodeId=36b4d422-d011-4f77-919a-b8ffb089614b, locMapped=false,
> expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0,
> serReadVer=null, xidVer=GridCacheVersion [topVer=119473256,
> order=1508434155230, nodeOrder=2243]]], explicitLock=false, dhtVer=null,
> last=false, nearEntries=0, clientFirst=false,
> node=36b4d422-d011-4f77-919a-b8ffb089614b]], nearLocallyMapped=false,
> colocatedLocallyMapped=false, needCheckBackup=null, hasRemoteLocks=false,
> thread=<failed to find active thread 109>,
> mappings=IgniteTxMappingsSingleImpl [mapping=GridDistributedTxMapping
> [entries=[IgniteTxEntry [key=KeyCacheObjectImpl [part=126,
> val=GridCacheInternalKeyImpl [name=SCAN_IDX, grpName=default-ds-group],
> hasValBytes=true], cacheId=1481046058, txKey=IgniteTxKey
> [key=KeyCacheObjectImpl [part=126, val=GridCacheInternalKeyImpl
> [name=SCAN_IDX, grpName=default-ds-group], hasValBytes=true],
> cacheId=1481046058], val=[op=TRANSFORM, val=null], prevVal=[op=NOOP,
> val=null], oldVal=[op=NOOP, val=null], entryProcessorsCol=[IgniteBiTuple
> [val1=GetAndIncrementProcessor [], val2=[Ljava.lang.Object;@49d9dc6c]],
> ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null,
> dhtVer=null, filters=[], filtersPassed=false, filtersSet=true,
> entry=GridDhtDetachedCacheEntry [super=GridDistributedCacheEntry
> [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=126,
> val=GridCacheInternalKeyImpl [name=SCAN_IDX, grpName=default-ds-group],
> hasValBytes=true], val=null, startVer=1508434155232, ver=GridCacheVersion
> [topVer=119473256, order=1508434155232, nodeOrder=2243], hash=-375255214,
> extras=null, flags=0]]], prepared=0, locked=false,
> nodeId=36b4d422-d011-4f77-919a-b8ffb089614b, locMapped=false,
> expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0,
> serReadVer=null, xidVer=GridCacheVersion [topVer=119473256,
> order=1508434155230, nodeOrder=2243]]], explicitLock=false, dhtVer=null,
> last=false, nearEntries=0, clientFirst=false,
> node=36b4d422-d011-4f77-919a-b8ffb089614b]], super=GridDhtTxLocalAdapter
> [nearOnOriginatingNode=false, nearNodes=[], dhtNodes=[],
> explicitLock=false,
> super=IgniteTxLocalAdapter [completedBase=null, sndTransformedVals=false,
> depEnabled=false, txState=IgniteTxImplicitSingleStateImpl [init=true,
> recovery=false], super=IgniteTxAdapter [xidVer=GridCacheVersion
> [topVer=119473256, order=1508434155230, nodeOrder=2243], writeVer=null,
> implicit=true, loc=true, threadId=109, startTime=1508434233985,
> nodeId=cb0332bd-1c18-4695-a75f-0d0ed4637b55, startVer=GridCacheVersion
> [topVer=119473256, order=1508434155230, nodeOrder=2243], endVer=null,
> isolation=READ_COMMITTED, concurrency=OPTIMISTIC, timeout=0,
> sysInvalidate=false, sys=true, plc=2, commitVer=GridCacheVersion
> [topVer=119473256, order=1508434155230, nodeOrder=2243], finalizing=NONE,
> invalidParts=null, state=PREPARING, timedOut=false,
> topVer=AffinityTopologyVersion [topVer=2243, minorTopVer=0],
> duration=1952717ms, onePhaseCommit=true], size=1]]], commit=true,
> mappings=IgniteTxMappingsSingleImpl [mapping=GridDistributedTxMapping
> [entries=[IgniteTxEntry [key=KeyCacheObjectImpl [part=126,
> val=GridCacheInternalKeyImpl [name=SCAN_IDX, grpName=default-ds-group],
> hasValBytes=true], cacheId=1481046058, txKey=IgniteTxKey
> [key=KeyCacheObjectImpl [part=126, val=GridCacheInternalKeyImpl
> [name=SCAN_IDX, grpName=default-ds-group], hasValBytes=true],
> cacheId=1481046058], val=[op=TRANSFORM, val=null], prevVal=[op=NOOP,
> val=null], oldVal=[op=NOOP, val=null], entryProcessorsCol=[IgniteBiTuple
> [val1=GetAndIncrementProcessor [], val2=[Ljava.lang.Object;@49d9dc6c]],
> ttl=-1, conflictExpireTime=-1, conflictVer=null, explicitVer=null,
> dhtVer=null, filters=[], filtersPassed=false, filtersSet=true,
> entry=GridDhtDetachedCacheEntry [super=GridDistributedCacheEntry
> [super=GridCacheMapEntry [key=KeyCacheObjectImpl [part=126,
> val=GridCacheInternalKeyImpl [name=SCAN_IDX, grpName=default-ds-group],
> hasValBytes=true], val=null, startVer=1508434155232, ver=GridCacheVersion
> [topVer=119473256, order=1508434155232, nodeOrder=2243], hash=-375255214,
> extras=null, flags=0]]], prepared=0, locked=false,
> nodeId=36b4d422-d011-4f77-919a-b8ffb089614b, locMapped=false,
> expiryPlc=null, transferExpiryPlc=false, flags=0, partUpdateCntr=0,
> serReadVer=null, xidVer=GridCacheVersion [topVer=119473256,
> order=1508434155230, nodeOrder=2243]]], explicitLock=false, dhtVer=null,
> last=false, nearEntries=0, clientFirst=false,
> node=36b4d422-d011-4f77-919a-b8ffb089614b]], trackable=true,
> finishOnePhaseCalled=false, innerFuts=[], super=GridCompoundIdentityFuture
> [super=GridCompoundFuture [rdc=AlwaysTrueReducer [], initFlag=0,
> lsnrCalls=0, done=false, cancelled=false, err=null, futs=[]]]]]
>
> IGNITECHECKEDEXCEPTION:
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: SEVERE: Failed to execute
> job [jobId=ac08ea53f51-cb0332bd-1c18-4695-a75f-0d0ed4637b55,
> ses=GridJobSessionImpl [ses=GridTaskSessionImpl
> [taskName=com.company.fragment.node.callable.DequeuePortionsCallable,
> dep=GridDeployment [ts=1508433959490, depMode=SHARED,
> clsLdr=sun.misc.Launcher$AppClassLoader@764c12b6,
> clsLdrId=fa68ba53f51-85f1f563-695c-43f9-a263-e9f67e8925b7, userVer=0,
> loc=true,
> sampleClsName=o.a.i.i.processors.task.GridTaskProcessor$
> TaskDiscoveryListener$1,
> pendingUndeploy=false, undeployed=false, usage=64],
> taskClsName=com.company.fragment.node.callable.DequeuePortionsCallable,
> sesId=9c08ea53f51-cb0332bd-1c18-4695-a75f-0d0ed4637b55,
> startTime=1508434417976, endTime=9223372036854775807,
> taskNodeId=cb0332bd-1c18-4695-a75f-0d0ed4637b55,
> clsLdr=sun.misc.Launcher$AppClassLoader@764c12b6, closed=false,
> cpSpi=null,
> failSpi=null, loadSpi=null, usage=1, fullSup=false, internal=false,
> subjId=cb0332bd-1c18-4695-a75f-0d0ed4637b55, mapFut=IgniteFuture
> [orig=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null,
> hash=2051666823]], execName=null],
> jobId=ac08ea53f51-cb0332bd-1c18-4695-a75f-0d0ed4637b55]]
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: class
> org.apache.ignite.IgniteException: class
> org.apache.ignite.IgniteInterruptedException: Got interrupted while
> waiting
> for future to complete.
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> org.apache.ignite.internal.processors.closure.GridClosureProcessor$C2.
> execute(GridClosureProcessor.java:1850)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> org.apache.ignite.internal.processors.job.GridJobWorker$
> 2.call(GridJobWorker.java:566)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> org.apache.ignite.internal.util.IgniteUtils.wrapThreadLoader(IgniteUtils.
> java:6608)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> org.apache.ignite.internal.processors.job.GridJobWorker.
> execute0(GridJobWorker.java:560)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> org.apache.ignite.internal.processors.job.GridJobWorker.
> body(GridJobWorker.java:489)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> org.apache.ignite.internal.processors.job.GridJobProcessor.
> processJobExecuteRequest(GridJobProcessor.java:1181)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> org.apache.ignite.internal.processors.job.GridJobProcessor$
> JobExecutionListener.onMessage(GridJobProcessor.java:1908)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> org.apache.ignite.internal.managers.communication.
> GridIoManager.invokeListener(GridIoManager.java:1556)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> org.apache.ignite.internal.managers.communication.GridIoManager.
> processRegularMessage0(GridIoManager.java:1184)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> org.apache.ignite.internal.managers.communication.
> GridIoManager.access$4200(GridIoManager.java:126)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> org.apache.ignite.internal.managers.communication.GridIoManager$9.run(
> GridIoManager.java:1097)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> java.lang.Thread.run(Unknown Source)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: Caused by:
> javax.cache.CacheException: class
> org.apache.ignite.IgniteInterruptedException: Got interrupted while
> waiting
> for future to complete.
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> org.apache.ignite.internal.processors.cache.GridCacheUtils.
> convertToCacheException(GridCacheUtils.java:1312)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> org.apache.ignite.internal.processors.cache.IgniteCacheProxy.
> cacheException(IgniteCacheProxy.java:2630)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> org.apache.ignite.internal.processors.cache.IgniteCacheProxy.get(
> IgniteCacheProxy.java:1188)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> com.company.fragment.node.ignite.IgnitePortionDequeuer.dequeuePortionIds(
> IgnitePortionDequeuer.java:276)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> com.company.fragment.node.ignite.IgnitePortionDequeuer._dequeuePortionIds(
> IgnitePortionDequeuer.java:196)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> com.company.fragment.node.ignite.IgnitePortionDequeuer.dequeuePortions(
> IgnitePortionDequeuer.java:146)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> com.company.fragment.node.callable.DequeuePortionsCallable.call(
> DequeuePortionsCallable.java:44)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> com.company.fragment.node.callable.DequeuePortionsCallable.call(
> DequeuePortionsCallable.java:35)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> org.apache.ignite.internal.processors.closure.GridClosureProcessor$C2.
> execute(GridClosureProcessor.java:1847)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: ... 14 more
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: Caused by: class
> org.apache.ignite.IgniteInterruptedException: Got interrupted while
> waiting
> for future to complete.
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> org.apache.ignite.internal.util.IgniteUtils$3.apply(IgniteUtils.java:796)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: at
> org.apache.ignite.internal.util.IgniteUtils$3.apply(IgniteUtils.java:794)
> Oct 19 13:29:22 prod-srvr apache-ignite[46822]: ... 23 more
>
>
>
>
>
> --
> Sent from: http://apache-ignite-users.70518.x6.nabble.com/
>