From 09c05672080d9b73440c0dbd9da295bb1554d3d3 Mon Sep 17 00:00:00 2001 From: NSAmelchev Date: Thu, 8 Oct 2026 15:35:51 +0300 Subject: [PATCH] IGNITE-29108 Add explicit lock hold time metrics --- docs/_docs/distributed-locks.adoc | 7 ++ .../_docs/monitoring-metrics/new-metrics.adoc | 2 + .../processors/cache/CacheLockImpl.java | 20 ++-- .../cache/GridCacheExplicitLockSpan.java | 112 +++++++++++++++--- .../cache/GridCacheMvccManager.java | 13 +- .../TransactionMetricsAdapter.java | 46 +++++++ .../internal/TransactionMetricsTest.java | 72 +++++++++++ 7 files changed, 244 insertions(+), 28 deletions(-) diff --git a/docs/_docs/distributed-locks.adoc b/docs/_docs/distributed-locks.adoc index 48c4f4a863d14..ab3fca21eb2ba 100644 --- a/docs/_docs/distributed-locks.adoc +++ b/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. diff --git a/docs/_docs/monitoring-metrics/new-metrics.adoc b/docs/_docs/monitoring-metrics/new-metrics.adoc index f89008c0b611b..ba66d50a68ff8 100644 --- a/docs/_docs/monitoring-metrics/new-metrics.adoc +++ b/docs/_docs/monitoring-metrics/new-metrics.adoc @@ -225,7 +225,9 @@ Register name: `tx` |=== |Name | Type | Description |AllOwnerTransactions | Map | 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. diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/CacheLockImpl.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/CacheLockImpl.java index 040642aed94e7..c8ac3470270c7 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/CacheLockImpl.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/CacheLockImpl.java @@ -53,7 +53,7 @@ class CacheLockImpl 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 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 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); diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheExplicitLockSpan.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheExplicitLockSpan.java index 53c8ad6f5774d..1b454a1e31660 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheExplicitLockSpan.java +++ b/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> cands = new HashMap<>(); + private final Map cands = new HashMap<>(); /** Span lock release future. */ @GridToStringExclude @@ -115,9 +116,11 @@ public boolean removeCandidate(GridCacheMvccCandidate cand) { lock(); try { - Deque deque = cands.get(cand.key()); + KeyCandidates keyCands = cands.get(cand.key()); + + if (keyCands != null) { + Deque 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 deque = cands.get(key); + KeyCandidates keyCands = cands.get(key); GridCacheMvccCandidate cand = null; - if (deque != null) { + if (keyCands != null) { + Deque deque = keyCands.deque; + assert !deque.isEmpty(); GridCacheMvccCandidate first = deque.peekFirst(); @@ -225,7 +230,12 @@ public Collection candidates() { lock(); try { - return new ArrayList<>(F.flatCollections(cands.values())); + Collection 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 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 deque = cands.get(key); + KeyCandidates keyCands = cands.get(key); + + if (keyCands != null) { + Deque deque = keyCands.deque; - if (deque != null) { assert !deque.isEmpty(); return ver == null ? deque.peekFirst() : F.find(deque, null, new P1() { @@ -308,15 +365,15 @@ public IgniteInternalFuture releaseFuture() { * @return Deque. */ private Deque ensureDeque(IgniteTxKey key) { - Deque 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 ensureDeque(IgniteTxKey key) { unlock(); } } + + /** Candidates of one key. */ + private static class KeyCandidates { + /** */ + @GridToStringInclude + private final Deque 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); + } + } } diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheMvccManager.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheMvccManager.java index 9fe3462af0546..98c3b9c00d88a 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheMvccManager.java +++ b/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> pending = new ThreadLocal<>(); /** Pending near local locks and topology version per thread. */ - private ConcurrentMap pendingExplicit; + private final ConcurrentMap pendingExplicit = newMap(); /** Set of removed lock versions. */ private GridBoundedConcurrentLinkedHashSet 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> 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( diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/transactions/TransactionMetricsAdapter.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/transactions/TransactionMetricsAdapter.java index aa004505409e5..00640b20830b1 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/transactions/TransactionMetricsAdapter.java +++ b/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); diff --git a/modules/core/src/test/java/org/apache/ignite/internal/TransactionMetricsTest.java b/modules/core/src/test/java/org/apache/ignite/internal/TransactionMetricsTest.java index 2f281a8162a75..4558270f12fcb 100644 --- a/modules/core/src/test/java/org/apache/ignite/internal/TransactionMetricsTest.java +++ b/modules/core/src/test/java/org/apache/ignite/internal/TransactionMetricsTest.java @@ -17,18 +17,23 @@ package org.apache.ignite.internal; +import java.util.Arrays; import java.util.List; import java.util.Map; import java.util.concurrent.CountDownLatch; +import java.util.concurrent.locks.Lock; +import java.util.stream.LongStream; import org.apache.ignite.Ignite; import org.apache.ignite.IgniteCache; import org.apache.ignite.cache.CacheRebalanceMode; import org.apache.ignite.cache.affinity.rendezvous.RendezvousAffinityFunction; import org.apache.ignite.configuration.CacheConfiguration; import org.apache.ignite.configuration.IgniteConfiguration; +import org.apache.ignite.configuration.NearCacheConfiguration; import org.apache.ignite.internal.processors.metric.impl.ObjectGauge; import org.apache.ignite.metric.MetricRegistry; import org.apache.ignite.mxbean.TransactionMetricsMxBean; +import org.apache.ignite.spi.metric.HistogramMetric; import org.apache.ignite.spi.metric.IntMetric; import org.apache.ignite.spi.metric.LongMetric; import org.apache.ignite.testframework.junits.common.GridCommonAbstractTest; @@ -37,7 +42,10 @@ import static org.apache.ignite.cache.CacheAtomicityMode.TRANSACTIONAL; import static org.apache.ignite.cache.CacheWriteSynchronizationMode.FULL_SYNC; +import static org.apache.ignite.internal.processors.cache.transactions.TransactionMetricsAdapter.METRIC_EXPLICIT_LOCK_HOLD_TIME_HISTOGRAM; +import static org.apache.ignite.internal.processors.cache.transactions.TransactionMetricsAdapter.METRIC_MAX_EXPLICIT_LOCK_HOLD_TIME; import static org.apache.ignite.internal.processors.metric.GridMetricManager.TX_METRICS; +import static org.apache.ignite.testframework.GridTestUtils.waitForCondition; import static org.apache.ignite.transactions.TransactionConcurrency.PESSIMISTIC; import static org.apache.ignite.transactions.TransactionIsolation.REPEATABLE_READ; @@ -218,6 +226,70 @@ public void testNearTxInfo() throws Exception { commitAllower.countDown(); } + /** */ + @Test + public void testExplicitLockMetrics() throws Exception { + IgniteEx srv = startGrid(0); + + IgniteEx client = startClientGrid(1); + + checkExplicitLockMetrics(client, srv, client.cache(DEFAULT_CACHE_NAME)); + checkExplicitLockMetrics(srv, client, srv.cache(DEFAULT_CACHE_NAME)); + } + + /** */ + @Test + public void testExplicitLockMetricsNearCache() throws Exception { + IgniteEx srv = startGrid(0); + + // A near cache can not be created on a node that has already started the cache from its static configuration. + IgniteEx client = startClientGrid(getConfiguration(getTestIgniteInstanceName(1)).setCacheConfiguration()); + + checkExplicitLockMetrics(client, srv, client.createNearCache(DEFAULT_CACHE_NAME, new NearCacheConfiguration<>())); + } + + /** + * @param owner Node acquiring the locks. + * @param other Node that does not acquire them. + * @param cache Cache to lock keys of. + */ + private void checkExplicitLockMetrics(IgniteEx owner, IgniteEx other, IgniteCache cache) + throws Exception { + MetricRegistry mreg = owner.context().metric().registry(TX_METRICS); + + LongMetric maxHoldTime = mreg.findMetric(METRIC_MAX_EXPLICIT_LOCK_HOLD_TIME); + HistogramMetric holdTimeHistogram = mreg.findMetric(METRIC_EXPLICIT_LOCK_HOLD_TIME_HISTOGRAM); + + Lock lock = cache.lock(1); + + lock.lock(); + + try { + assertTrue(waitForCondition(() -> maxHoldTime.value() > 200, getTestTimeout())); + + // Locks are accounted on the owner node only. + assertEquals(0, other.context().metric().registry(TX_METRICS) + .findMetric(METRIC_MAX_EXPLICIT_LOCK_HOLD_TIME).value()); + + assertEquals(0, LongStream.of(holdTimeHistogram.value()).sum()); + } + finally { + lock.unlock(); + } + + assertEquals(0, maxHoldTime.value()); + assertEquals(1, LongStream.of(holdTimeHistogram.value()).sum()); + + Lock multiKeyLock = cache.lockAll(Arrays.asList(2, 3)); + + multiKeyLock.lock(); + multiKeyLock.lock(); + multiKeyLock.unlock(); + multiKeyLock.unlock(); + + assertEquals(2, LongStream.of(holdTimeHistogram.value()).sum()); + } + /** * */