Return-Path: X-Original-To: archive-asf-public-internal@cust-asf2.ponee.io Delivered-To: archive-asf-public-internal@cust-asf2.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by cust-asf2.ponee.io (Postfix) with ESMTP id 1572A200B43 for ; Tue, 19 Jul 2016 08:54:34 +0200 (CEST) Received: by cust-asf.ponee.io (Postfix) id 13FD3160A8F; Tue, 19 Jul 2016 06:54:34 +0000 (UTC) Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by cust-asf.ponee.io (Postfix) with SMTP id B09F2160A8B for ; Tue, 19 Jul 2016 08:54:31 +0200 (CEST) Received: (qmail 21686 invoked by uid 500); 19 Jul 2016 06:54:30 -0000 Mailing-List: contact commits-help@ignite.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@ignite.apache.org Delivered-To: mailing list commits@ignite.apache.org Received: (qmail 21666 invoked by uid 99); 19 Jul 2016 06:54:30 -0000 Received: from git1-us-west.apache.org (HELO git1-us-west.apache.org) (140.211.11.23) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 19 Jul 2016 06:54:30 +0000 Received: by git1-us-west.apache.org (ASF Mail Server at git1-us-west.apache.org, from userid 33) id 81EF4E058E; Tue, 19 Jul 2016 06:54:30 +0000 (UTC) Content-Type: text/plain; charset="us-ascii" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit From: vozerov@apache.org To: commits@ignite.apache.org Date: Tue, 19 Jul 2016 06:54:31 -0000 Message-Id: <21d1904d151f47d8a7537003ea8f2599@git.apache.org> In-Reply-To: References: X-Mailer: ASF-Git Admin Mailer Subject: [03/28] ignite git commit: ignite-3336 Added properties IGNITE_THREAD_DUMP_ON_EXCHANGE_TIMEOUT, IGNITE_LONG_OPERATIONS_DUMP_TIMEOUT. Refactored cache message logging. archived-at: Tue, 19 Jul 2016 06:54:34 -0000 ignite-3336 Added properties IGNITE_THREAD_DUMP_ON_EXCHANGE_TIMEOUT, IGNITE_LONG_OPERATIONS_DUMP_TIMEOUT. Refactored cache message logging. Project: http://git-wip-us.apache.org/repos/asf/ignite/repo Commit: http://git-wip-us.apache.org/repos/asf/ignite/commit/8ed13e84 Tree: http://git-wip-us.apache.org/repos/asf/ignite/tree/8ed13e84 Diff: http://git-wip-us.apache.org/repos/asf/ignite/diff/8ed13e84 Branch: refs/heads/ignite-3414 Commit: 8ed13e84499a2006baf8df22d897509e2d4e3f7e Parents: 89d722c Author: sboikov Authored: Wed Jul 6 10:18:26 2016 +0300 Committer: sboikov Committed: Wed Jul 6 10:18:26 2016 +0300 ---------------------------------------------------------------------- .../apache/ignite/IgniteSystemProperties.java | 8 +- .../apache/ignite/internal/IgniteKernal.java | 21 ++ .../processors/cache/GridCacheAdapter.java | 4 + .../processors/cache/GridCacheIoManager.java | 150 +++++++++- .../processors/cache/GridCacheMessage.java | 9 + .../GridCachePartitionExchangeManager.java | 147 +++++++++- .../cache/GridCacheSharedContext.java | 68 +++++ .../processors/cache/GridCacheUtils.java | 21 ++ .../distributed/GridCacheTxRecoveryFuture.java | 70 ++++- .../distributed/GridCacheTxRecoveryRequest.java | 8 + .../GridCacheTxRecoveryResponse.java | 8 + .../distributed/GridDistributedLockRequest.java | 6 + .../GridDistributedLockResponse.java | 6 + .../GridDistributedTxFinishRequest.java | 7 +- .../GridDistributedTxFinishResponse.java | 8 + .../GridDistributedTxPrepareRequest.java | 6 + .../GridDistributedTxPrepareResponse.java | 9 +- .../GridDistributedUnlockRequest.java | 6 + .../distributed/dht/GridDhtLockFuture.java | 52 ++-- .../dht/GridDhtTransactionalCacheAdapter.java | 77 ++++- .../distributed/dht/GridDhtTxFinishFuture.java | 92 +++++- .../cache/distributed/dht/GridDhtTxLocal.java | 27 +- .../distributed/dht/GridDhtTxPrepareFuture.java | 124 +++++++- .../dht/atomic/GridDhtAtomicCache.java | 137 ++++++--- .../GridDhtAtomicDeferredUpdateResponse.java | 7 + .../dht/atomic/GridDhtAtomicUpdateFuture.java | 47 +++- .../dht/atomic/GridDhtAtomicUpdateRequest.java | 6 + .../dht/atomic/GridDhtAtomicUpdateResponse.java | 6 + .../dht/atomic/GridNearAtomicUpdateFuture.java | 54 +++- .../dht/atomic/GridNearAtomicUpdateRequest.java | 6 + .../atomic/GridNearAtomicUpdateResponse.java | 6 + .../dht/colocated/GridDhtColocatedCache.java | 10 + .../colocated/GridDhtColocatedLockFuture.java | 71 +++-- .../GridDhtPartitionsExchangeFuture.java | 26 +- .../near/GridNearOptimisticTxPrepareFuture.java | 32 +++ .../GridNearPessimisticTxPrepareFuture.java | 34 ++- .../near/GridNearTxFinishFuture.java | 97 ++++++- .../near/GridNearTxPrepareFutureAdapter.java | 7 +- .../cache/transactions/IgniteTxHandler.java | 281 ++++++++++++++----- modules/core/src/test/config/log4j-test.xml | 6 + 40 files changed, 1495 insertions(+), 272 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/ignite/blob/8ed13e84/modules/core/src/main/java/org/apache/ignite/IgniteSystemProperties.java ---------------------------------------------------------------------- diff --git a/modules/core/src/main/java/org/apache/ignite/IgniteSystemProperties.java b/modules/core/src/main/java/org/apache/ignite/IgniteSystemProperties.java index 50d60e8..254c60f 100644 --- a/modules/core/src/main/java/org/apache/ignite/IgniteSystemProperties.java +++ b/modules/core/src/main/java/org/apache/ignite/IgniteSystemProperties.java @@ -375,6 +375,12 @@ public final class IgniteSystemProperties { /** Number of times pending cache objects will be dumped to the log in case of partition exchange timeout. */ public static final String IGNITE_DUMP_PENDING_OBJECTS_THRESHOLD = "IGNITE_DUMP_PENDING_OBJECTS_THRESHOLD"; + /** If this property is set to {@code true} then Ignite will log thread dump in case of partition exchange timeout. */ + public static final String IGNITE_THREAD_DUMP_ON_EXCHANGE_TIMEOUT = "IGNITE_THREAD_DUMP_ON_EXCHANGE_TIMEOUT"; + + /** Cache operations that take more time than value of this property will be output to log. Set to {@code 0} to disable. */ + public static final String IGNITE_LONG_OPERATIONS_DUMP_TIMEOUT = "IGNITE_LONG_OPERATIONS_DUMP_TIMEOUT"; + /** JDBC driver cursor remove delay. */ public static final String IGNITE_JDBC_DRIVER_CURSOR_REMOVE_DELAY = "IGNITE_JDBC_DRIVER_CURSOR_RMV_DELAY"; @@ -387,7 +393,7 @@ public final class IgniteSystemProperties { /** * Manages {@link OptimizedMarshaller} behavior of {@code serialVersionUID} computation for * {@link Serializable} classes. - * */ + */ public static final String IGNITE_OPTIMIZED_MARSHALLER_USE_DEFAULT_SUID = "IGNITE_OPTIMIZED_MARSHALLER_USE_DEFAULT_SUID"; http://git-wip-us.apache.org/repos/asf/ignite/blob/8ed13e84/modules/core/src/main/java/org/apache/ignite/internal/IgniteKernal.java ---------------------------------------------------------------------- diff --git a/modules/core/src/main/java/org/apache/ignite/internal/IgniteKernal.java b/modules/core/src/main/java/org/apache/ignite/internal/IgniteKernal.java index 9d42598..9b26276 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/IgniteKernal.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/IgniteKernal.java @@ -300,6 +300,10 @@ public class IgniteKernal implements IgniteEx, IgniteMXBean, Externalizable { @GridToStringExclude private GridTimeoutProcessor.CancelableTask metricsLogTask; + /** */ + @GridToStringExclude + private GridTimeoutProcessor.CancelableTask longOpDumpTask; + /** Indicate error on grid stop. */ @GridToStringExclude private boolean errOnStop; @@ -1073,6 +1077,20 @@ public class IgniteKernal implements IgniteEx, IgniteMXBean, Externalizable { }, metricsLogFreq, metricsLogFreq); } + final long longOpDumpTimeout = + IgniteSystemProperties.getLong(IgniteSystemProperties.IGNITE_LONG_OPERATIONS_DUMP_TIMEOUT, 60_000); + + if (longOpDumpTimeout > 0) { + longOpDumpTask = ctx.timeout().schedule(new Runnable() { + @Override public void run() { + GridKernalContext ctx = IgniteKernal.this.ctx; + + if (ctx != null) + ctx.cache().context().exchange().dumpLongRunningOperations(longOpDumpTimeout); + } + }, longOpDumpTimeout, longOpDumpTimeout); + } + ctx.performance().logSuggestions(log, gridName); U.quietAndInfo(log, "To start Console Management & Monitoring run ignitevisorcmd.{sh|bat}"); @@ -1883,6 +1901,9 @@ public class IgniteKernal implements IgniteEx, IgniteMXBean, Externalizable { if (metricsLogTask != null) metricsLogTask.close(); + if (longOpDumpTask != null) + longOpDumpTask.close(); + boolean interrupted = false; while (true) { http://git-wip-us.apache.org/repos/asf/ignite/blob/8ed13e84/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheAdapter.java ---------------------------------------------------------------------- diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheAdapter.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheAdapter.java index 1a55fe3..028f516 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheAdapter.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheAdapter.java @@ -266,6 +266,9 @@ public abstract class GridCacheAdapter implements IgniteInternalCache aff; @@ -328,6 +331,7 @@ public abstract class GridCacheAdapter implements IgniteInternalCache extends GridCacheSharedMana } /** - * + * @throws Exception If failed. */ - public void dumpDebugInfo() { + public void dumpDebugInfo() throws Exception { U.warn(log, "Ready affinity version: " + readyTopVer.get()); U.warn(log, "Last exchange future: " + lastInitializedFut); @@ -1122,9 +1134,103 @@ public class GridCachePartitionExchangeManager extends GridCacheSharedMana } /** - * + * @param timeout Operation timeout. */ - public void dumpPendingObjects() { + public void dumpLongRunningOperations(long timeout) { + try { + GridDhtPartitionsExchangeFuture lastFut = lastInitializedFut; + + // If exchange is in progress it will dump all hanging operations if any. + if (lastFut != null && !lastFut.isDone()) + return; + + long curTime = U.currentTimeMillis(); + + boolean found = false; + + IgniteTxManager tm = cctx.tm(); + + if (tm != null) { + for (IgniteInternalTx tx : tm.activeTransactions()) { + if (curTime - tx.startTime() > timeout) { + found = true; + + if (longRunningOpsDumpCnt < GridDhtPartitionsExchangeFuture.DUMP_PENDING_OBJECTS_THRESHOLD) { + U.warn(log, "Found long running transaction [startTime=" + formatTime(tx.startTime()) + + ", curTime=" + formatTime(curTime) + ", tx=" + tx + ']'); + } + else + break; + } + } + } + + GridCacheMvccManager mvcc = cctx.mvcc(); + + if (mvcc != null) { + for (GridCacheFuture fut : mvcc.activeFutures()) { + if (curTime - fut.startTime() > timeout) { + found = true; + + if (longRunningOpsDumpCnt < GridDhtPartitionsExchangeFuture.DUMP_PENDING_OBJECTS_THRESHOLD) { + U.warn(log, "Found long running cache future [startTime=" + formatTime(fut.startTime()) + + ", curTime=" + formatTime(curTime) + ", fut=" + fut + ']'); + } + else + break; + } + } + + for (GridCacheFuture fut : mvcc.atomicFutures()) { + if (curTime - fut.startTime() > timeout) { + found = true; + + if (longRunningOpsDumpCnt < GridDhtPartitionsExchangeFuture.DUMP_PENDING_OBJECTS_THRESHOLD) { + U.warn(log, "Found long running cache future [startTime=" + formatTime(fut.startTime()) + + ", curTime=" + formatTime(curTime) + ", fut=" + fut + ']'); + } + else + break; + } + } + } + + if (found) { + if (longRunningOpsDumpCnt < GridDhtPartitionsExchangeFuture.DUMP_PENDING_OBJECTS_THRESHOLD) { + longRunningOpsDumpCnt++; + + if (IgniteSystemProperties.getBoolean(IGNITE_THREAD_DUMP_ON_EXCHANGE_TIMEOUT, false)) { + U.warn(log, "Found long running cache operations, dump threads."); + + U.dumpThreads(log); + } + + U.warn(log, "Found long running cache operations, dump IO statistics."); + + // Dump IO manager statistics. + cctx.gridIO().dumpStats(); + } + } + else + longRunningOpsDumpCnt = 0; + } + catch (Exception e) { + U.error(log, "Failed to dump debug information: " + e, e); + } + } + + /** + * @param time Time. + * @return Time string. + */ + private String formatTime(long time) { + return dateFormat.format(new Date(time)); + } + + /** + * @throws Exception If failed. + */ + private void dumpPendingObjects() throws Exception { IgniteTxManager tm = cctx.tm(); if (tm != null) { @@ -1281,7 +1387,36 @@ public class GridCachePartitionExchangeManager extends GridCacheSharedMana exchFut.init(); - exchFut.get(); + int dumpedObjects = 0; + + while (true) { + try { + exchFut.get(2 * cctx.gridConfig().getNetworkTimeout(), TimeUnit.MILLISECONDS); + + break; + } + catch (IgniteFutureTimeoutCheckedException ignored) { + U.warn(log, "Failed to wait for partition map exchange [" + + "topVer=" + exchFut.topologyVersion() + + ", node=" + cctx.localNodeId() + "]. " + + "Dumping pending objects that might be the cause: "); + + if (dumpedObjects < GridDhtPartitionsExchangeFuture.DUMP_PENDING_OBJECTS_THRESHOLD) { + try { + dumpDebugInfo(); + } + catch (Exception e) { + U.error(log, "Failed to dump debug information: " + e, e); + } + + if (IgniteSystemProperties.getBoolean(IGNITE_THREAD_DUMP_ON_EXCHANGE_TIMEOUT, false)) + U.dumpThreads(log); + + dumpedObjects++; + } + } + } + if (log.isDebugEnabled()) log.debug("After waiting for exchange future [exchFut=" + exchFut + ", worker=" + @@ -1408,7 +1543,7 @@ public class GridCachePartitionExchangeManager extends GridCacheSharedMana if (marshR != null || !rebalanceQ.isEmpty()) { if (futQ.isEmpty()) { - U.log(log, "Rebalancing required" + + U.log(log, "Rebalancing required " + "[top=" + exchFut.topologyVersion() + ", evt=" + exchFut.discoveryEvent().name() + ", node=" + exchFut.discoveryEvent().eventNode().id() + ']'); http://git-wip-us.apache.org/repos/asf/ignite/blob/8ed13e84/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheSharedContext.java ---------------------------------------------------------------------- diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheSharedContext.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheSharedContext.java index 341f610..1130218 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheSharedContext.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheSharedContext.java @@ -51,6 +51,7 @@ import org.apache.ignite.internal.util.future.GridCompoundFuture; import org.apache.ignite.internal.util.future.GridFinishedFuture; import org.apache.ignite.internal.util.tostring.GridToStringExclude; import org.apache.ignite.internal.util.typedef.F; +import org.apache.ignite.internal.util.typedef.internal.CU; import org.apache.ignite.lang.IgniteFuture; import org.apache.ignite.marshaller.Marshaller; import org.jetbrains.annotations.Nullable; @@ -104,6 +105,24 @@ public class GridCacheSharedContext { /** Indicating whether local store keeps primary only. */ private final boolean locStorePrimaryOnly = IgniteSystemProperties.getBoolean(IGNITE_LOCAL_STORE_KEEPS_PRIMARY_ONLY); + /** */ + private final IgniteLogger msgLog; + + /** */ + private final IgniteLogger atomicMsgLog; + + /** */ + private final IgniteLogger txPrepareMsgLog; + + /** */ + private final IgniteLogger txFinishMsgLog; + + /** */ + private final IgniteLogger txLockMsgLog; + + /** */ + private final IgniteLogger txRecoveryMsgLog; + /** * @param kernalCtx Context. * @param txMgr Transaction manager. @@ -137,6 +156,55 @@ public class GridCacheSharedContext { ctxMap = new ConcurrentHashMap<>(); locStoreCnt = new AtomicInteger(); + + msgLog = kernalCtx.log(CU.CACHE_MSG_LOG_CATEGORY); + atomicMsgLog = kernalCtx.log(CU.ATOMIC_MSG_LOG_CATEGORY); + txPrepareMsgLog = kernalCtx.log(CU.TX_MSG_PREPARE_LOG_CATEGORY); + txFinishMsgLog = kernalCtx.log(CU.TX_MSG_FINISH_LOG_CATEGORY); + txLockMsgLog = kernalCtx.log(CU.TX_MSG_LOCK_LOG_CATEGORY); + txRecoveryMsgLog = kernalCtx.log(CU.TX_MSG_RECOVERY_LOG_CATEGORY); + } + + /** + * @return Logger. + */ + public IgniteLogger messageLogger() { + return msgLog; + } + + /** + * @return Logger. + */ + public IgniteLogger atomicMessageLogger() { + return atomicMsgLog; + } + + /** + * @return Logger. + */ + public IgniteLogger txPrepareMessageLogger() { + return txPrepareMsgLog; + } + + /** + * @return Logger. + */ + public IgniteLogger txFinishMessageLogger() { + return txFinishMsgLog; + } + + /** + * @return Logger. + */ + public IgniteLogger txLockMessageLogger() { + return txLockMsgLog; + } + + /** + * @return Logger. + */ + public IgniteLogger txRecoveryMessageLogger() { + return txRecoveryMsgLog; } /** http://git-wip-us.apache.org/repos/asf/ignite/blob/8ed13e84/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheUtils.java ---------------------------------------------------------------------- diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheUtils.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheUtils.java index 87c4a3a..ba563e6 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheUtils.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/GridCacheUtils.java @@ -128,6 +128,27 @@ public class GridCacheUtils { /** Marshaller system cache name. */ public static final String MARSH_CACHE_NAME = "ignite-marshaller-sys-cache"; + /** */ + public static final String CACHE_MSG_LOG_CATEGORY = "org.apache.ignite.cache.msg"; + + /** */ + public static final String ATOMIC_MSG_LOG_CATEGORY = CACHE_MSG_LOG_CATEGORY + ".atomic"; + + /** */ + public static final String TX_MSG_LOG_CATEGORY = CACHE_MSG_LOG_CATEGORY + ".tx"; + + /** */ + public static final String TX_MSG_PREPARE_LOG_CATEGORY = TX_MSG_LOG_CATEGORY + ".prepare"; + + /** */ + public static final String TX_MSG_FINISH_LOG_CATEGORY = TX_MSG_LOG_CATEGORY + ".finish"; + + /** */ + public static final String TX_MSG_LOCK_LOG_CATEGORY = TX_MSG_LOG_CATEGORY + ".lock"; + + /** */ + public static final String TX_MSG_RECOVERY_LOG_CATEGORY = TX_MSG_LOG_CATEGORY + ".recovery"; + /** Default mask name. */ private static final String DEFAULT_MASK_NAME = ""; http://git-wip-us.apache.org/repos/asf/ignite/blob/8ed13e84/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/GridCacheTxRecoveryFuture.java ---------------------------------------------------------------------- diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/GridCacheTxRecoveryFuture.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/GridCacheTxRecoveryFuture.java index 1648de0..4fd45b2 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/GridCacheTxRecoveryFuture.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/GridCacheTxRecoveryFuture.java @@ -54,6 +54,9 @@ public class GridCacheTxRecoveryFuture extends GridCompoundIdentityFuture(); @@ -168,11 +173,24 @@ public class GridCacheTxRecoveryFuture extends GridCompoundIdentityFuture