IGNITE-29108 Add explicit lock hold time metrics

docs/_docs/distributed-locks.adoc

@@ -57,3 +57,10 @@ In Ignite, locks are supported only for the `TRANSACTIONAL` atomicity mode, whic
 Explicit locks are not transactional and cannot not be used from within transactions (exception will be thrown).
 If you do need explicit locking within transactions, then you should use the `TransactionConcurrency.PESSIMISTIC` concurrency
 control for transactions which will acquire explicit locks for relevant cluster data requests.
+
+== Monitoring
+
+The node that acquired a lock reports how long explicit locks are held: the `MaxExplicitLockHoldTime` metric shows the
+maximum hold time of the locks currently held, and the `ExplicitLockHoldTimeHistogram` metric shows the distribution of
+hold times of released locks, see link:monitoring-metrics/new-metrics#transactions[Transactions] metrics. The locks held at
+the moment are listed in the link:monitoring-metrics/system-views#cache_explicit_locks[CACHE_EXPLICIT_LOCKS] system view.

docs/_docs/monitoring-metrics/new-metrics.adoc

@@ -225,7 +225,9 @@ Register name: `tx`
 |===
 |Name | Type | Description
 |AllOwnerTransactions | Map<String, String> | Map of local node owning transactions.
+|ExplicitLockHoldTimeHistogram | histogram | Explicit locks hold times on node represented as histogram, in milliseconds.
 |LockedKeysNumber | long | The number of keys locked on the node.
+|MaxExplicitLockHoldTime | long | Maximum hold time of explicit locks currently held on the node, in milliseconds.
 |OwnerTransactionsNumber | long | The number of active transactions for which this node is the initiator.
 |TransactionsHoldingLockNumber | long | The number of active transactions holding at least one key lock.
 |commitTime | long | Last commit time.

modules/core/src/main/java/org/apache/ignite/internal/processors/cache/CacheLockImpl.java

@@ -53,7 +53,7 @@ class CacheLockImpl<K, V> implements Lock {
     private volatile Thread lockedThread;
 
     /** Lock start time in nanoseconds. */
-    private volatile long startTimeNanos;
+    private long startTimeNanos;
 
     /**
      * @param gate Gate.
@@ -94,7 +94,7 @@ class CacheLockImpl<K, V> implements Lock {
     private void incrementLockCounter() {
         assert (lockedThread == null && cntr == 0) || (lockedThread == Thread.currentThread() && cntr > 0);
 
-        if (cntr == 0 && delegate.context().kernalContext().performanceStatistics().enabled())
+        if (cntr == 0)
             startTimeNanos = System.nanoTime();
 
         cntr++;
@@ -197,15 +197,19 @@ private void incrementLockCounter() {
             if (cntr == 0) {
                 lockedThread = null;
 
-                if (startTimeNanos > 0) {
-                    delegate.context().kernalContext().performanceStatistics().cacheOperation(
+                long holdTimeNanos = System.nanoTime() - startTimeNanos;
+
+                GridCacheContext<K, V> cctx = delegate.context();
+
+                if (cctx.kernalContext().performanceStatistics().enabled()) {
+                    cctx.kernalContext().performanceStatistics().cacheOperation(
                         OperationType.CACHE_LOCK,
-                        delegate.context().cacheId(),
+                        cctx.cacheId(),
                         U.currentTimeMillis(),
-                        System.nanoTime() - startTimeNanos);
-
-                    startTimeNanos = 0;
+                        holdTimeNanos);
                 }
+
+                cctx.shared().txMetrics().onExplicitLockRelease(U.nanosToMillis(holdTimeNanos));
             }
 
             delegate.unlockAll(keys);

modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheExplicitLockSpan.java

@@ -35,6 +35,7 @@
 import org.apache.ignite.internal.util.typedef.F;
 import org.apache.ignite.internal.util.typedef.P1;
 import org.apache.ignite.internal.util.typedef.internal.S;
+import org.apache.ignite.internal.util.typedef.internal.U;
 import org.jetbrains.annotations.Nullable;
 
 /**
@@ -50,7 +51,7 @@ public class GridCacheExplicitLockSpan extends ReentrantLock {
 
     /** Pending candidates. */
     @GridToStringInclude
-    private final Map<IgniteTxKey, Deque<GridCacheMvccCandidate>> cands = new HashMap<>();
+    private final Map<IgniteTxKey, KeyCandidates> cands = new HashMap<>();
 
     /** Span lock release future. */
     @GridToStringExclude
@@ -115,9 +116,11 @@ public boolean removeCandidate(GridCacheMvccCandidate cand) {
         lock();
 
         try {
-            Deque<GridCacheMvccCandidate> deque = cands.get(cand.key());
+            KeyCandidates keyCands = cands.get(cand.key());
+
+            if (keyCands != null) {
+                Deque<GridCacheMvccCandidate> deque = keyCands.deque;
 
-            if (deque != null) {
                 assert !deque.isEmpty();
 
                 if (deque.peekFirst().equals(cand)) {
@@ -151,11 +154,13 @@ public GridCacheMvccCandidate removeCandidate(IgniteTxKey key, @Nullable GridCac
         lock();
 
         try {
-            Deque<GridCacheMvccCandidate> deque = cands.get(key);
+            KeyCandidates keyCands = cands.get(key);
 
             GridCacheMvccCandidate cand = null;
 
-            if (deque != null) {
+            if (keyCands != null) {
+                Deque<GridCacheMvccCandidate> deque = keyCands.deque;
+
                 assert !deque.isEmpty();
 
                 GridCacheMvccCandidate first = deque.peekFirst();
@@ -225,7 +230,12 @@ public Collection<GridCacheMvccCandidate> candidates() {
         lock();
 
         try {
-            return new ArrayList<>(F.flatCollections(cands.values()));
+            Collection<GridCacheMvccCandidate> res = new ArrayList<>();
+
+            for (KeyCandidates keyCands : cands.values())
+                res.addAll(keyCands.deque);
+
+            return res;
         }
         finally {
             unlock();
@@ -241,12 +251,57 @@ public void markOwned(IgniteTxKey key) {
         lock();
 
         try {
-            Deque<GridCacheMvccCandidate> deque = cands.get(key);
+            KeyCandidates keyCands = cands.get(key);
 
-            assert deque != null;
+            assert keyCands != null;
 
-            for (GridCacheMvccCandidate cand : deque)
+            for (GridCacheMvccCandidate cand : keyCands.deque)
                 cand.setOwner();
+
+            keyCands.acquired();
+        }
+        finally {
+            unlock();
+        }
+    }
+
+    /**
+     * Records the time the lock on the key was acquired without touching candidate flags: for near candidates
+     * they are managed by the entry MVCC under the entry lock, so {@link #markOwned(IgniteTxKey)} is not applicable.
+     *
+     * @param key Key.
+     */
+    public void markAcquired(IgniteTxKey key) {
+        lock();
+
+        try {
+            KeyCandidates keyCands = cands.get(key);
+
+            // The key may be already released by a timed out lock future.
+            if (keyCands != null)
+                keyCands.acquired();
+        }
+        finally {
+            unlock();
+        }
+    }
+
+    /**
+     * @param now Current time.
+     * @return Longest time a key of the span has been locked for, in milliseconds, or 0 if no lock is acquired yet.
+     */
+    public long maxHoldTime(long now) {
+        lock();
+
+        try {
+            long max = 0;
+
+            for (KeyCandidates keyCands : cands.values()) {
+                if (keyCands.acquireTime > 0)
+                    max = Math.max(max, now - keyCands.acquireTime);
+            }
+
+            return max;
         }
         finally {
             unlock();
@@ -264,9 +319,11 @@ public void markOwned(IgniteTxKey key) {
         lock();
 
         try {
-            Deque<GridCacheMvccCandidate> deque = cands.get(key);
+            KeyCandidates keyCands = cands.get(key);
+
+            if (keyCands != null) {
+                Deque<GridCacheMvccCandidate> deque = keyCands.deque;
 
-            if (deque != null) {
                 assert !deque.isEmpty();
 
                 return ver == null ? deque.peekFirst() : F.find(deque, null, new P1<GridCacheMvccCandidate>() {
@@ -308,15 +365,15 @@ public IgniteInternalFuture<Object> releaseFuture() {
      * @return Deque.
      */
     private Deque<GridCacheMvccCandidate> ensureDeque(IgniteTxKey key) {
-        Deque<GridCacheMvccCandidate> deque = cands.get(key);
+        KeyCandidates keyCands = cands.get(key);
 
-        if (deque == null) {
-            deque = new LinkedList<>();
+        if (keyCands == null) {
+            keyCands = new KeyCandidates();
 
-            cands.put(key, deque);
+            cands.put(key, keyCands);
         }
 
-        return deque;
+        return keyCands.deque;
     }
 
     /** {@inheritDoc} */
@@ -330,4 +387,27 @@ private Deque<GridCacheMvccCandidate> ensureDeque(IgniteTxKey key) {
             unlock();
         }
     }
+
+    /** Candidates of one key. */
+    private static class KeyCandidates {
+        /** */
+        @GridToStringInclude
+        private final Deque<GridCacheMvccCandidate> deque = new LinkedList<>();
+
+        /** Time the lock on the key was acquired, 0 until then. */
+        @GridToStringExclude
+        private long acquireTime;
+
+        /** Records the first acquisition only, reentries keep the original time. */
+        void acquired() {
+            if (acquireTime == 0)
+                acquireTime = U.currentTimeMillis();
+        }
+
+        /** {@inheritDoc} */
+        @Override public String toString() {
+            return S.toString(KeyCandidates.class, this,
+                "holdTime", acquireTime == 0 ? 0 : U.currentTimeMillis() - acquireTime, false);
+        }
+    }
 }

modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheMvccManager.java

@@ -54,7 +54,6 @@
 import org.apache.ignite.internal.systemview.CacheExplicitLockViewWalker;
 import org.apache.ignite.internal.systemview.CacheLockViewWalker;
 import org.apache.ignite.internal.util.GridBoundedConcurrentLinkedHashSet;
-import org.apache.ignite.internal.util.GridConcurrentFactory;
 import org.apache.ignite.internal.util.GridConcurrentHashSet;
 import org.apache.ignite.internal.util.future.GridCompoundFuture;
 import org.apache.ignite.internal.util.future.GridFinishedFuture;
@@ -116,7 +115,7 @@ public class GridCacheMvccManager extends GridCacheSharedManagerAdapter {
     private final ThreadLocal<Deque<GridCacheMvccCandidate>> pending = new ThreadLocal<>();
 
     /** Pending near local locks and topology version per thread. */
-    private ConcurrentMap<Long, GridCacheExplicitLockSpan> pendingExplicit;
+    private final ConcurrentMap<Long, GridCacheExplicitLockSpan> pendingExplicit = newMap();
 
     /** Set of removed lock versions. */
     private GridBoundedConcurrentLinkedHashSet<GridCacheVersion> rmvLocks =
@@ -226,6 +225,14 @@ private void notifyOwnerChanged(final GridCacheEntryEx entry, final GridCacheMvc
         if (log.isDebugEnabled())
             log.debug("Received owner changed callback [" + entry.key() + ", owner=" + owner + ']');
 
+        // Colocated explicit locks are marked acquired by the lock future, near ones become owners here.
+        if (owner != null && owner.nearLocal() && !owner.tx()) {
+            GridCacheExplicitLockSpan span = pendingExplicit.get(owner.threadId());
+
+            if (span != null)
+                span.markAcquired(entry.txKey());
+        }
+
         if (owner != null && (owner.local() || owner.nearLocal())) {
             Collection<GridCacheVersionedFuture<?>> futCol = verFuts.get(owner.version());
 
@@ -297,8 +304,6 @@ else if (log.isDebugEnabled())
     @Override protected void start0() throws IgniteCheckedException {
         exchLog = cctx.logger(getClass().getName() + ".exchange");
 
-        pendingExplicit = GridConcurrentFactory.newMap();
-
         cctx.gridEvents().addLocalEventListener(discoLsnr, EVT_NODE_FAILED, EVT_NODE_LEFT);
 
         cctx.kernalContext().systemView().registerInnerCollectionView(

modules/core/src/main/java/org/apache/ignite/internal/processors/cache/transactions/TransactionMetricsAdapter.java

@@ -28,6 +28,7 @@
 import java.util.UUID;
 import org.apache.ignite.cluster.ClusterNode;
 import org.apache.ignite.internal.GridKernalContext;
+import org.apache.ignite.internal.processors.cache.GridCacheExplicitLockSpan;
 import org.apache.ignite.internal.processors.cache.GridCacheMvccManager;
 import org.apache.ignite.internal.processors.cache.distributed.near.GridNearTxLocal;
 import org.apache.ignite.internal.processors.metric.MetricRegistryImpl;
@@ -63,6 +64,12 @@ public class TransactionMetricsAdapter implements TransactionMetrics {
     /** Metric name for user time histogram on node. */
     public static final String METRIC_USER_TIME_HISTOGRAM = "nodeUserTimeHistogram";
 
+    /** Metric name for maximum hold time of explicit locks currently held on node. */
+    public static final String METRIC_MAX_EXPLICIT_LOCK_HOLD_TIME = "MaxExplicitLockHoldTime";
+
+    /** Metric name for explicit lock hold time histogram on node. */
+    public static final String METRIC_EXPLICIT_LOCK_HOLD_TIME_HISTOGRAM = "ExplicitLockHoldTimeHistogram";
+
     /** Histogram buckets for metrics of system and user time. */
     public static final long[] METRIC_TIME_BUCKETS =
         new long[] { 1, 2, 4, 8, 16, 25, 50, 75, 100, 250, 500, 750, 1000, 3000, 5000, 10000, 25000, 60000};
@@ -97,6 +104,9 @@ public class TransactionMetricsAdapter implements TransactionMetrics {
     /** Holds the reference to metric for user time histogram on node. */
     private HistogramMetricImpl txUserTimeHistogram;
 
+    /** Holds the reference to metric for explicit lock hold time histogram on node. */
+    private final HistogramMetricImpl explicitLockHoldTimeHistogram;
+
     /**
      * @param ctx Kernal context.
      */
@@ -124,6 +134,12 @@ public TransactionMetricsAdapter(GridKernalContext ctx) {
             METRIC_TIME_BUCKETS,
             "Transactions user times on node represented as histogram, in milliseconds."
         );
+
+        explicitLockHoldTimeHistogram = mreg.histogram(
+            METRIC_EXPLICIT_LOCK_HOLD_TIME_HISTOGRAM,
+            METRIC_TIME_BUCKETS,
+            "Explicit locks hold times on node represented as histogram, in milliseconds."
+        );
     }
 
     /** Callback invoked when {@link IgniteTxManager} started. */
@@ -143,6 +159,10 @@ public void onTxManagerStarted() {
             this::txLockedKeysNum,
             "The number of keys locked on the node.");
 
+        mreg.register(METRIC_MAX_EXPLICIT_LOCK_HOLD_TIME,
+            this::maxExplicitLockHoldTime,
+            "Maximum hold time of explicit locks currently held on the node, in milliseconds.");
+
         mreg.register("OwnerTransactionsNumber",
             this::nearTxNum,
             "The number of active transactions for which this node is the initiator.");
@@ -253,6 +273,15 @@ public void onNearTxComplete(long systemTime, long userTime) {
         }
     }
 
+    /**
+     * Explicit lock release callback.
+     *
+     * @param holdTime Lock hold time in milliseconds.
+     */
+    public void onExplicitLockRelease(long holdTime) {
+        explicitLockHoldTimeHistogram.value(holdTime);
+    }
+
     /**
      * Reset.
      */
@@ -404,6 +433,23 @@ private long txLockedKeysNum() {
         return mvccMgr.lockedKeys().size() + mvccMgr.nearLockedKeys().size();
     }
 
+    /** @return Maximum hold time of explicit locks currently held on the node, in milliseconds. */
+    private long maxExplicitLockHoldTime() {
+        GridCacheMvccManager mvccMgr = gridKernalCtx.cache().context().mvcc();
+
+        if (mvccMgr == null)
+            return 0;
+
+        long now = U.currentTimeMillis();
+
+        long max = 0;
+
+        for (GridCacheExplicitLockSpan span : mvccMgr.activeExplicitLocks())
+            max = Math.max(max, span.maxHoldTime(now));
+
+        return max;
+    }
+
     /** {@inheritDoc} */
     @Override public String toString() {
         return S.toString(TransactionMetricsAdapter.class, this);