[IGNITE-13363] GridDhtCacheEntry::toString locks

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.8.1
• Fix Version/s: 2.10
• Component/s: networking
• Labels: 2.9.1-rc
• Ignite Flags: Docs Required, Release Notes Required
• Assignee: Stepachev Maksim
• Reporter: Stepachev Maksim
• Reviewer: Alexey Scherbakov
• Created: 14/Aug/20 08:45
• Updated: 06/Aug/21 15:25
• Resolved: 21/Aug/20 15:10

Description

`GridDhtCacheEntry::toString` locks the entry which may lead to dead locks and, I assume, even performance issues.
We, naturally, call `toString` on everything all the time and it needs to be the safest and the lightest possible operation.
Example of a hang with locking toString:

 

{{Thread name="grid-timeout-worker-#71%GRIDC1%", id=98, state=WAITING, blockCnt=2, waitCnt=14196
Lock [object=java.util.concurrent.locks.ReentrantLock$NonfairSync@20c96143, ownerName=exchange-worker-#188%GRIDC1%, ownerId=265]
at java.base@11.0.2/jdk.internal.misc.Unsafe.park(Native Method)
at java.base@11.0.2/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
at java.base@11.0.2/java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:885)
at java.base@11.0.2/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:917)
at java.base@11.0.2/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1240)
at java.base@11.0.2/java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:267)
at app//o.a.i.i.processors.cache.GridCacheMapEntry.lockEntry(GridCacheMapEntry.java:5051)
at app//o.a.i.i.processors.cache.distributed.dht.GridDhtCacheEntry.toString(GridDhtCacheEntry.java:819)
at java.base@11.0.2/java.lang.String.valueOf(String.java:2951)
at app//o.a.i.i.util.GridStringBuilder.a(GridStringBuilder.java:101)
at app//o.a.i.i.util.tostring.SBLimitedLength.a(SBLimitedLength.java:88)
at app//o.a.i.i.util.tostring.GridToStringBuilder.toString(GridToStringBuilder.java:939)
at app//o.a.i.i.util.tostring.GridToStringBuilder.toStringImpl(GridToStringBuilder.java:1005)
at app//o.a.i.i.util.tostring.GridToStringBuilder.toString(GridToStringBuilder.java:826)
at app//o.a.i.i.util.tostring.GridToStringBuilder.toString(GridToStringBuilder.java:783)
at app//o.a.i.i.processors.cache.transactions.IgniteTxEntry.toString(IgniteTxEntry.java:1273)
at java.base@11.0.2/java.lang.String.valueOf(String.java:2951)
at java.base@11.0.2/java.lang.StringBuilder.append(StringBuilder.java:168)
at java.base@11.0.2/java.util.AbstractCollection.toString(AbstractCollection.java:473)
at java.base@11.0.2/java.lang.String.valueOf(String.java:2951)
at app//o.a.i.i.util.GridStringBuilder.a(GridStringBuilder.java:101)
at app//o.a.i.i.util.tostring.SBLimitedLength.a(SBLimitedLength.java:88)
at app//o.a.i.i.util.tostring.GridToStringBuilder.toString(GridToStringBuilder.java:939)
at app//o.a.i.i.util.tostring.GridToStringBuilder.toStringImpl(GridToStringBuilder.java:1005)
at app//o.a.i.i.util.tostring.GridToStringBuilder.toString(GridToStringBuilder.java:826)
at app//o.a.i.i.util.tostring.GridToStringBuilder.toString(GridToStringBuilder.java:783)
at app//o.a.i.i.processors.cache.distributed.GridDistributedTxMapping.toString(GridDistributedTxMapping.java:319)
at java.base@11.0.2/java.lang.String.valueOf(String.java:2951)
at app//o.a.i.i.util.GridStringBuilder.a(GridStringBuilder.java:101)
at app//o.a.i.i.util.tostring.SBLimitedLength.a(SBLimitedLength.java:88)
at app//o.a.i.i.util.tostring.GridToStringBuilder.toString(GridToStringBuilder.java:939)
at app//o.a.i.i.util.tostring.GridToStringBuilder.toStringImpl(GridToStringBuilder.java:1005)
at app//o.a.i.i.util.tostring.GridToStringBuilder.toString(GridToStringBuilder.java:864)
at app//o.a.i.i.processors.cache.distributed.near.IgniteTxMappingsSingleImpl.toString(IgniteTxMappingsSingleImpl.java:99)
at java.base@11.0.2/java.lang.String.valueOf(String.java:2951)
at app//o.a.i.i.util.GridStringBuilder.a(GridStringBuilder.java:101)
at app//o.a.i.i.util.tostring.SBLimitedLength.a(SBLimitedLength.java:88)
at app//o.a.i.i.util.tostring.GridToStringBuilder.toString(GridToStringBuilder.java:939)
at app//o.a.i.i.util.tostring.GridToStringBuilder.toStringImpl(GridToStringBuilder.java:1005)
at app//o.a.i.i.util.tostring.GridToStringBuilder.toString(GridToStringBuilder.java:685)
at app//o.a.i.i.util.tostring.GridToStringBuilder.toString(GridToStringBuilder.java:621)
at app//o.a.i.i.processors.cache.distributed.near.GridNearTxLocal.toString(GridNearTxLocal.java:4845)
at java.base@11.0.2/java.lang.String.valueOf(String.java:2951)
at java.base@11.0.2/java.lang.StringBuilder.append(StringBuilder.java:168)
at app//o.a.i.i.processors.cache.GridCachePartitionExchangeManager.dumpLongRunningOperations0(GridCachePartitionExchangeManager.java:1941)
at app//o.a.i.i.processors.cache.GridCachePartitionExchangeManager.dumpLongRunningOperations(GridCachePartitionExchangeManager.java:2002)
at app//o.a.i.i.IgniteKernal$4.run(IgniteKernal.java:1269)
at app//o.a.i.i.processors.timeout.GridTimeoutProcessor$CancelableTask.onTimeout(GridTimeoutProcessor.java:365)

• locked o.a.i.i.processors.timeout.GridTimeoutProcessor$CancelableTask@11035ab0
  at app//o.a.i.i.processors.timeout.GridTimeoutProcessor$TimeoutWorker.body(GridTimeoutProcessor.java:234)
  at app//o.a.i.i.util.worker.GridWorker.run(GridWorker.java:120)
  at java.base@11.0.2/java.lang.Thread.run(Thread.java:834)}}

Here the timeout worker attempted to print long running operations and hanged because the other threads held the locks on the entries (which is what you would expect from a "long running operations" situtation).

Let's remove the locking from this toString (and possibly cleanup more toString implementations) and only print the information we don't need for.
A separate method, like `describeEntry` can be added to obtain a full description under a lock, if it is ever needed somewhere.

 

Issue Links

• links to: GitHub Pull Request #8153