IGNITE-4513 Improve debug logging.
Project: http://git-wip-us.apache.org/repos/asf/ignite/repo Commit: http://git-wip-us.apache.org/repos/asf/ignite/commit/496fb173 Tree: http://git-wip-us.apache.org/repos/asf/ignite/tree/496fb173 Diff: http://git-wip-us.apache.org/repos/asf/ignite/diff/496fb173 Branch: refs/heads/master Commit: 496fb173d55a8ea0702fcb70a4e807f61d8fc53e Parents: 1665a61 Author: nikolay_tikhonov <[email protected]> Authored: Mon Jan 16 13:19:51 2017 +0300 Committer: nikolay_tikhonov <[email protected]> Committed: Mon Jan 16 13:19:51 2017 +0300 ---------------------------------------------------------------------- .../processors/cache/GridCacheUtils.java | 3 + .../continuous/CacheContinuousQueryHandler.java | 81 +++++++++++++++++--- modules/core/src/test/config/log4j-test.xml | 6 ++ 3 files changed, 79 insertions(+), 11 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/ignite/blob/496fb173/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 d32f4c1..8ee77e3 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 @@ -123,6 +123,9 @@ public class GridCacheUtils { public static final String MARSH_CACHE_NAME = "ignite-marshaller-sys-cache"; /** */ + public static final String CONTINUOUS_QRY_LOG_CATEGORY = "org.apache.ignite.continuous.query"; + + /** */ public static final String CACHE_MSG_LOG_CATEGORY = "org.apache.ignite.cache.msg"; /** */ http://git-wip-us.apache.org/repos/asf/ignite/blob/496fb173/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/query/continuous/CacheContinuousQueryHandler.java ---------------------------------------------------------------------- diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/query/continuous/CacheContinuousQueryHandler.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/query/continuous/CacheContinuousQueryHandler.java index 10784fc..83edab4 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/query/continuous/CacheContinuousQueryHandler.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/query/continuous/CacheContinuousQueryHandler.java @@ -352,7 +352,7 @@ public class CacheContinuousQueryHandler<K, V> implements GridContinuousHandler assert !skipPrimaryCheck || loc; - log = ctx.log(CacheContinuousQueryHandler.class); + log = ctx.log(CU.CONTINUOUS_QRY_LOG_CATEGORY); CacheContinuousQueryListener<K, V> lsnr = new CacheContinuousQueryListener<K, V>() { @Override public void onExecution() { @@ -384,7 +384,10 @@ public class CacheContinuousQueryHandler<K, V> implements GridContinuousHandler final boolean recordIgniteEvt, GridDhtAtomicAbstractUpdateFuture fut) { if (ignoreExpired && evt.getEventType() == EventType.EXPIRED) - return ; + return; + + if (log.isDebugEnabled()) + log.debug("Entry updated on affinity node [evt=" + evt + ", primary=" + primary + ']'); final GridCacheContext<K, V> cctx = cacheContext(ctx); @@ -407,6 +410,10 @@ public class CacheContinuousQueryHandler<K, V> implements GridContinuousHandler else { final boolean notify = filter(evt, primary); + if (log.isDebugEnabled()) + log.debug("Filter invoked for event [evt=" + evt + ", primary=" + primary + + ", notify=" + notify + ']'); + if (primary || skipPrimaryCheck) { if (fut == null) onEntryUpdate(evt, notify, loc, recordIgniteEvt); @@ -474,7 +481,8 @@ public class CacheContinuousQueryHandler<K, V> implements GridContinuousHandler backupQueue0.clear(); } catch (IgniteCheckedException e) { - U.error(ctx.log(getClass()), "Failed to send backup event notification to node: " + nodeId, e); + U.error(ctx.log(CU.CONTINUOUS_QRY_LOG_CATEGORY), + "Failed to send backup event notification to node: " + nodeId, e); } } @@ -653,7 +661,7 @@ public class CacheContinuousQueryHandler<K, V> implements GridContinuousHandler final GridCacheContext cctx = cacheContext(ctx); if (cctx == null) { - IgniteLogger log = ctx.log(CacheContinuousQueryHandler.class); + IgniteLogger log = ctx.log(CU.CONTINUOUS_QRY_LOG_CATEGORY); if (log.isDebugEnabled()) log.debug("Failed to notify callback, cache is not found: " + cacheId); @@ -689,7 +697,7 @@ public class CacheContinuousQueryHandler<K, V> implements GridContinuousHandler if (ignoreClsNotFound) assert internal; else - U.error(ctx.log(getClass()), "Failed to unmarshal entry.", ex); + U.error(ctx.log(CU.CONTINUOUS_QRY_LOG_CATEGORY), "Failed to unmarshal entry.", ex); } } @@ -799,8 +807,12 @@ public class CacheContinuousQueryHandler<K, V> implements GridContinuousHandler CacheContinuousQueryEntry e = handleEntry(entry); - if (e != null) + if (e != null) { + if (log.isDebugEnabled()) + log.debug("Send the following event to listener: " + e); + ctx.continuous().addNotification(nodeId, routineId, entry, topic, sync, true); + } } } catch (ClusterTopologyCheckedException ex) { @@ -809,7 +821,7 @@ public class CacheContinuousQueryHandler<K, V> implements GridContinuousHandler "[node=" + nodeId + ", err=" + ex + ']'); } catch (IgniteCheckedException ex) { - U.error(ctx.log(getClass()), "Failed to send event notification to node: " + nodeId, ex); + U.error(ctx.log(CU.CONTINUOUS_QRY_LOG_CATEGORY), "Failed to send event notification to node: " + nodeId, ex); } if (recordIgniteEvt && notify) { @@ -875,7 +887,7 @@ public class CacheContinuousQueryHandler<K, V> implements GridContinuousHandler partCntr = initUpdCntrs.get(partId); } - rec = new PartitionRecovery(ctx.log(getClass()), initTopVer0, partCntr); + rec = new PartitionRecovery(ctx.log(CU.CONTINUOUS_QRY_LOG_CATEGORY), initTopVer0, partCntr); PartitionRecovery oldRec = rcvs.putIfAbsent(partId, rec); @@ -984,12 +996,27 @@ public class CacheContinuousQueryHandler<K, V> implements GridContinuousHandler List<CacheEntryEvent<? extends K, ? extends V>> entries; synchronized (pendingEvts) { + if (log.isDebugEnabled()) { + log.debug("Handling event [lastFiredEvt=" + lastFiredEvt + + ", curTop=" + curTop + + ", entUpdCnt=" + entry.updateCounter() + + ", partId=" + entry.partition() + + ", pendingEvts=" + pendingEvts + ']'); + } + // Received first event. if (curTop == AffinityTopologyVersion.NONE) { lastFiredEvt = entry.updateCounter(); curTop = entry.topologyVersion(); + if (log.isDebugEnabled()) { + log.debug("First event [lastFiredEvt=" + lastFiredEvt + + ", curTop=" + curTop + + ", entUpdCnt=" + entry.updateCounter() + + ", partId=" + entry.partition() + ']'); + } + return !entry.isFiltered() ? F.<CacheEntryEvent<? extends K, ? extends V>> asList(new CacheContinuousQueryEvent<K, V>(cache, cctx, entry)) : @@ -1014,6 +1041,13 @@ public class CacheContinuousQueryHandler<K, V> implements GridContinuousHandler if (!entry.isFiltered()) entries.add(new CacheContinuousQueryEvent<K, V>(cache, cctx, entry)); + if (log.isDebugEnabled()) + log.debug("Partition was lost [lastFiredEvt=" + lastFiredEvt + + ", curTop=" + curTop + + ", entUpdCnt=" + entry.updateCounter() + + ", partId=" + entry.partition() + + ", pendingEvts=" + pendingEvts + ']'); + return entries; } @@ -1039,8 +1073,16 @@ public class CacheContinuousQueryHandler<K, V> implements GridContinuousHandler return Collections.emptyList(); } - if (pendingEvts.isEmpty()) + if (pendingEvts.isEmpty()) { + if (log.isDebugEnabled()) { + log.debug("Nothing sent to listener [lastFiredEvt=" + lastFiredEvt + + ", curTop=" + curTop + + ", entUpdCnt=" + entry.updateCounter() + + ", partId=" + entry.partition() + ']'); + } + return Collections.emptyList(); + } Iterator<Map.Entry<Long, CacheContinuousQueryEntry>> iter = pendingEvts.entrySet().iterator(); @@ -1057,6 +1099,14 @@ public class CacheContinuousQueryHandler<K, V> implements GridContinuousHandler iter.remove(); } + + if (log.isDebugEnabled()) { + log.debug("Pending events reached max of buffer size [lastFiredEvt=" + lastFiredEvt + + ", curTop=" + curTop + + ", entUpdCnt=" + entry.updateCounter() + + ", partId=" + entry.partition() + + ", pendingEvts=" + pendingEvts + ']'); + } } else { // Elements are consistently. @@ -1077,6 +1127,15 @@ public class CacheContinuousQueryHandler<K, V> implements GridContinuousHandler } } + if (log.isDebugEnabled()) { + log.debug("Will send to listener the following events [entries=" + entries + + ", lastFiredEvt=" + lastFiredEvt + + ", curTop=" + curTop + + ", entUpdCnt=" + entry.updateCounter() + + ", partId=" + entry.partition() + + ", pendingEvts=" + pendingEvts + ']'); + } + return entries; } } @@ -1254,14 +1313,14 @@ public class CacheContinuousQueryHandler<K, V> implements GridContinuousHandler cctx.io().send(node, msg, GridIoPolicy.SYSTEM_POOL); } catch (ClusterTopologyCheckedException e) { - IgniteLogger log = ctx.log(getClass()); + IgniteLogger log = ctx.log(CU.CONTINUOUS_QRY_LOG_CATEGORY); if (log.isDebugEnabled()) log.debug("Failed to send acknowledge message, node left " + "[msg=" + msg + ", node=" + node + ']'); } catch (IgniteCheckedException e) { - IgniteLogger log = ctx.log(getClass()); + IgniteLogger log = ctx.log(CU.CONTINUOUS_QRY_LOG_CATEGORY); U.error(log, "Failed to send acknowledge message " + "[msg=" + msg + ", node=" + node + ']', e); http://git-wip-us.apache.org/repos/asf/ignite/blob/496fb173/modules/core/src/test/config/log4j-test.xml ---------------------------------------------------------------------- diff --git a/modules/core/src/test/config/log4j-test.xml b/modules/core/src/test/config/log4j-test.xml index 276de8c..638b260 100644 --- a/modules/core/src/test/config/log4j-test.xml +++ b/modules/core/src/test/config/log4j-test.xml @@ -102,6 +102,12 @@ </category> --> + <!-- + <category name="org.apache.ignite.continuous.query"> + <level value="DEBUG"/> + </category> + --> + <!-- Disable all open source debugging. --> <category name="org"> <level value="INFO"/>
