This is an automated email from the ASF dual-hosted git repository. boglesby pushed a commit to branch feature/GEM-1772 in repository https://gitbox.apache.org/repos/asf/geode.git
commit 3e9a15d8a2682cd320fe82a2926a92b674da986a Author: Barry Oglesby <[email protected]> AuthorDate: Tue Jun 19 12:00:09 2018 -0700 GEM-1772: Added debugging --- .../distributed/internal/ReplyProcessor21.java | 7 ++-- .../distributed/internal/direct/DirectChannel.java | 9 +++-- .../internal/cache/DistributedCacheOperation.java | 12 ++++--- .../internal/cache/DistributedPutAllOperation.java | 8 +++-- .../internal/cache/InitialImageOperation.java | 38 ++++++++++++---------- .../cache/partitioned/PutAllPRMessage.java | 20 +++++++----- .../geode/internal/i18n/LocalizedStrings.java | 2 +- 7 files changed, 56 insertions(+), 40 deletions(-) diff --git a/geode-core/src/main/java/org/apache/geode/distributed/internal/ReplyProcessor21.java b/geode-core/src/main/java/org/apache/geode/distributed/internal/ReplyProcessor21.java index 3ffd31d..d3cf1ad 100644 --- a/geode-core/src/main/java/org/apache/geode/distributed/internal/ReplyProcessor21.java +++ b/geode-core/src/main/java/org/apache/geode/distributed/internal/ReplyProcessor21.java @@ -35,6 +35,7 @@ import org.apache.geode.i18n.StringId; import org.apache.geode.internal.Assert; import org.apache.geode.internal.DSFIDNotFoundException; import org.apache.geode.internal.Version; +import org.apache.geode.internal.cache.partitioned.PutAllPRMessage; import org.apache.geode.internal.cache.versions.ConcurrentCacheModificationException; import org.apache.geode.internal.i18n.LocalizedStrings; import org.apache.geode.internal.logging.LogService; @@ -394,8 +395,10 @@ public class ReplyProcessor21 implements MembershipListener { } protected void process(DistributionMessage msg, boolean warn) { - if (logger.isDebugEnabled()) { - logger.debug("{} got process({}) from {}", this, msg, msg.getSender()); + if (msg instanceof PutAllPRMessage.PutAllReplyMessage) { + //if (logger.isDebugEnabled()) { + logger.warn("XXX {} got process({}) from {}", this, msg, msg.getSender()); + //} } if (msg instanceof ReplyMessage) { ReplyException ex = ((ReplyMessage) msg).getException(); diff --git a/geode-core/src/main/java/org/apache/geode/distributed/internal/direct/DirectChannel.java b/geode-core/src/main/java/org/apache/geode/distributed/internal/direct/DirectChannel.java index 970957f..eaa062e 100644 --- a/geode-core/src/main/java/org/apache/geode/distributed/internal/direct/DirectChannel.java +++ b/geode-core/src/main/java/org/apache/geode/distributed/internal/direct/DirectChannel.java @@ -47,6 +47,7 @@ import org.apache.geode.distributed.internal.membership.InternalDistributedMembe import org.apache.geode.distributed.internal.membership.MembershipManager; import org.apache.geode.i18n.StringId; import org.apache.geode.internal.cache.DirectReplyMessage; +import org.apache.geode.internal.cache.DistributedPutAllOperation; import org.apache.geode.internal.i18n.LocalizedStrings; import org.apache.geode.internal.logging.LogService; import org.apache.geode.internal.logging.log4j.AlertAppender; @@ -315,9 +316,11 @@ public class DirectChannel { if (!directReply && directMsg != null) { directMsg.registerProcessor(); } - if (logger.isDebugEnabled()) { - logger.debug("Sending ({}) to {} peers ({}) via tcp/ip", - msg, p_destinations.length, Arrays.toString(p_destinations)); + if (msg instanceof DistributedPutAllOperation.PutAllMessage) { + //if (logger.isDebugEnabled()) { + logger.warn("XXX DirectChannel sendToMany Sending ({}) to {} peers ({}) via tcp/ip", + msg, p_destinations.length, Arrays.toString(p_destinations)); + //} } try { diff --git a/geode-core/src/main/java/org/apache/geode/internal/cache/DistributedCacheOperation.java b/geode-core/src/main/java/org/apache/geode/internal/cache/DistributedCacheOperation.java index 4fee0a0..35dca1d 100644 --- a/geode-core/src/main/java/org/apache/geode/internal/cache/DistributedCacheOperation.java +++ b/geode-core/src/main/java/org/apache/geode/internal/cache/DistributedCacheOperation.java @@ -452,9 +452,11 @@ public abstract class DistributedCacheOperation { } } - if (logger.isDebugEnabled()) { - logger.debug("recipients for {}: {} with adjunct messages to: {}", this, recipients, - adjunctRecipients); + if (this instanceof DistributedPutAllOperation) { + //if (logger.isDebugEnabled()) { + logger.warn("XXX DistributedPutAllOperation _distribute recipients for {}: {} with adjunct messages to: {}", this, recipients, + adjunctRecipients); + //} } if (shouldAck) { @@ -604,8 +606,8 @@ public abstract class DistributedCacheOperation { cachelessNodes.addAll(cachelessNodesWithNoCacheServer); } - if (failures != null && !failures.isEmpty() && logger.isDebugEnabled()) { - logger.debug("Failed sending ({}) to {} while processing event:{}", msg, failures, event); + if (failures != null && !failures.isEmpty()) { + logger.warn("XXX DistributedPutAllOperation _distribute Failed sending ({}) to {} while processing event:{}", msg, failures, event); } Set<InternalDistributedMember> adjunctRecipientsWithNoCacheServer = diff --git a/geode-core/src/main/java/org/apache/geode/internal/cache/DistributedPutAllOperation.java b/geode-core/src/main/java/org/apache/geode/internal/cache/DistributedPutAllOperation.java index 3fd97d1..29c38af 100644 --- a/geode-core/src/main/java/org/apache/geode/internal/cache/DistributedPutAllOperation.java +++ b/geode-core/src/main/java/org/apache/geode/internal/cache/DistributedPutAllOperation.java @@ -1175,12 +1175,14 @@ public class DistributedPutAllOperation extends AbstractUpdateOperation { public void run() { final boolean isDebugEnabled = logger.isDebugEnabled(); for (int i = 0; i < putAllDataSize; ++i) { - if (isDebugEnabled) { - logger.debug("putAll processing {} with {} sender={}", putAllData[i], + //if (isDebugEnabled) { + logger.warn("XXX PutAllMessage basicOperateOnRegion putAll processing {} with {} sender={}", putAllData[i], putAllData[i].versionTag, sender); - } + //} putAllData[i].setSender(sender); doEntryPut(putAllData[i], rgn); + logger.warn("XXX PutAllMessage basicOperateOnRegion putAll done processing {} with {} sender={}", putAllData[i], + putAllData[i].versionTag, sender); } } }, ev.getEventId()); diff --git a/geode-core/src/main/java/org/apache/geode/internal/cache/InitialImageOperation.java b/geode-core/src/main/java/org/apache/geode/internal/cache/InitialImageOperation.java index 1f04280..a265cdd 100644 --- a/geode-core/src/main/java/org/apache/geode/internal/cache/InitialImageOperation.java +++ b/geode-core/src/main/java/org/apache/geode/internal/cache/InitialImageOperation.java @@ -563,11 +563,11 @@ public class InitialImageOperation { } if (this.gotImage) { // TODO add localizedString - logger.info("{} is done getting image from {}. isDeltaGII is {}", this.region.getName(), + logger.info("XXX {} is done getting image from {}. isDeltaGII is {}", this.region.getName(), recipient, this.isDeltaGII); } else { // TODO add localizedString - logger.info("{} failed to get image from {}", this.region.getName(), recipient); + logger.info("XXX {} failed to get image from {}", this.region.getName(), recipient); } if (this.region.getDataPolicy().withPersistence()) { logger.info(LocalizedMessage.create( @@ -1304,7 +1304,9 @@ public class InitialImageOperation { // bug 37461: don't allow abort flag to be reset boolean isAborted = this.abort; // volatile fetch if (!isAborted) { + logger.warn("XXX ImageProcessor.process about to process chunk entries=" + m.entries); isAborted = !processChunk(m.entries, m.getSender(), m.remoteVersion); + logger.warn("XXX ImageProcessor.process processed chunk entries isAborted=" + isAborted); if (isAborted) { this.abort = true; // volatile store } else { @@ -1670,10 +1672,9 @@ public class InitialImageOperation { final int seriesNum = 0; // chunkEntries returns false if didn't finish - if (isGiiDebugEnabled) { - logger.trace(LogMarker.INITIAL_IMAGE_VERBOSE, - "RequestImageMessage: Starting chunkEntries for {}", rgn.getFullPath()); - } + //if (isGiiDebugEnabled) { + logger.warn("XXX RequestImageMessage: Starting chunkEntries for {}", rgn.getFullPath()); + //} final InitialImageFlowControl flowControl = InitialImageFlowControl.register(dm, getSender()); @@ -1731,18 +1732,17 @@ public class InitialImageOperation { && rgn.getConcurrencyChecksEnabled()) { synchronized (rgn.getCache().getTombstoneService().getBlockGCLock()) { if (goWithFullGII(rgn, this.versionVector)) { - if (isGiiDebugEnabled) { - logger.trace(LogMarker.INITIAL_IMAGE_VERBOSE, "have to do fullGII"); - } + //if (isGiiDebugEnabled) { + logger.warn("XXX Doing full GII for {}", rgn.getFullPath()); + //} this.versionVector = null; // full GII } else { // lock GIILock only for deltaGII int count = rgn.getCache().getTombstoneService().incrementGCBlockCount(); markedOngoingGII = true; - if (isGiiDebugEnabled) { - logger.trace(LogMarker.INITIAL_IMAGE_VERBOSE, "There're {} Delta GII on going", - count); - } + //if (isGiiDebugEnabled) { + logger.warn("XX Doing delta GII for {}", rgn.getFullPath()); + //} } } } @@ -1780,9 +1780,11 @@ public class InitialImageOperation { if (this.last && rgn.getVersionVector() != null) { gcVersions = rgn.getVersionVector().getMemberToGCVersion(); } + logger.warn("XXX RequestImageMessage.executeWith about to send chunk " + (msgNum+1)); replyWithData(dm, entries, seriesNum, msgNum++, numSeries, this.last, flowControlId, versionVector != null, holderToSend, gcVersions); + logger.warn("XXX RequestImageMessage.executeWith sent chunk " + (msgNum)); } return !abort; } catch (CancelException e) { @@ -1792,11 +1794,10 @@ public class InitialImageOperation { }); - if (isGiiDebugEnabled) { - logger.trace(LogMarker.INITIAL_IMAGE_VERBOSE, - "RequestImageMessage: ended chunkEntries for {}; finished = {}", rgn.getFullPath(), + //if (isGiiDebugEnabled) { + logger.warn("XXX RequestImageMessage: ended chunkEntries for {}; finished = {}", rgn.getFullPath(), finished); - } + //} // Call to chunkEntries above will have sent at least one // reply with last==true for the last message. (unless doing abortTest or @@ -1870,6 +1871,7 @@ public class InitialImageOperation { // null chunk signals receiver that we are aborting ImageReplyMessage.send(getSender(), processorId, rex, dm, null, 0, 0, 1, true, 0, false, null, null); + logger.warn("XXX RequestImageMessage.process sent failure message"); } // !success if (internalAfterSentImageReply != null @@ -1934,6 +1936,7 @@ public class InitialImageOperation { && it.hasNext()) { RegionEntry mapEntry = (RegionEntry) it.next(); Object key = mapEntry.getKey(); + logger.warn("XXX RequestImageMessage.chunkEntries checking key=" + key); if (rgn.checkEntryNotValid(mapEntry)) { // entry was just removed continue; } @@ -2001,6 +2004,7 @@ public class InitialImageOperation { entry.setLastModified(rgn.getDistributionManager(), mapEntry.getLastModified()); } + logger.warn("XXX RequestImageMessage.chunkEntries adding to chunk entry=" + entry); chunkEntries.add(entry); currentChunkSize += entry.calcSerializedSize(); } diff --git a/geode-core/src/main/java/org/apache/geode/internal/cache/partitioned/PutAllPRMessage.java b/geode-core/src/main/java/org/apache/geode/internal/cache/partitioned/PutAllPRMessage.java index b6450b3..cca7891 100755 --- a/geode-core/src/main/java/org/apache/geode/internal/cache/partitioned/PutAllPRMessage.java +++ b/geode-core/src/main/java/org/apache/geode/internal/cache/partitioned/PutAllPRMessage.java @@ -194,9 +194,9 @@ public class PutAllPRMessage extends PartitionMessageWithDirectReply { PutAllResponse p = new PutAllResponse(r.getSystem(), recipients); initMessage(r, recipients, false, p); setTransactionDistributed(r.getCache().getTxManager().isDistributed()); - if (logger.isDebugEnabled()) { - logger.debug("PutAllPRMessage.send: recipient is {}, msg is {}", recipient, this); - } + //if (logger.isDebugEnabled()) { + logger.warn("XXX PutAllPRMessage.send: recipient is {}, msg is {}", recipient, this); + //} Set failures = r.getDistributionManager().putOutgoing(this); if (failures != null && failures.size() > 0) { @@ -317,6 +317,7 @@ public class PutAllPRMessage extends PartitionMessageWithDirectReply { long startTime) throws EntryExistsException, ForceReattemptException, DataLocationException { boolean sendReply = true; + logger.warn("XXX PutAllPRMessage.operateOnPartitionedRegion invoked msg=" + this); InternalDistributedMember eventSender = getSender(); long lastModified = 0L; @@ -330,6 +331,7 @@ public class PutAllPRMessage extends PartitionMessageWithDirectReply { if (sendReply) { sendReply(getSender(), getProcessorId(), dm, null, pr, startTime); } + logger.warn("XXX PutAllPRMessage.operateOnPartitionedRegion completed msg=" + this); return false; } @@ -400,11 +402,11 @@ public class PutAllPRMessage extends PartitionMessageWithDirectReply { baseEvent.setContext(this.bridgeContext); } baseEvent.setPossibleDuplicate(this.posDup); - if (logger.isDebugEnabled()) { - logger.debug( - "PutAllPRMessage.doLocalPutAll: eventSender is {}, baseEvent is {}, msg is {}", + //if (logger.isDebugEnabled()) { + logger.warn( + "XXX PutAllPRMessage.doLocalPutAll: eventSender is {}, baseEvent is {}, msg is {}", eventSender, baseEvent, this); - } + //} dpao = new DistributedPutAllOperation(baseEvent, putAllPRDataSize, false); } @@ -474,8 +476,8 @@ public class PutAllPRMessage extends PartitionMessageWithDirectReply { try { didPut = r.getDataView().putEntryOnRemote(ev, false, false, null, false, lastModified, true); - if (didPut && logger.isDebugEnabled()) { - logger.debug("PutAllPRMessage.doLocalPutAll:putLocally success for {}", ev); + if (didPut) { + logger.warn("XXX PutAllPRMessage.doLocalPutAll:putLocally success for {}", ev); } } catch (ConcurrentCacheModificationException e) { didPut = true; diff --git a/geode-core/src/main/java/org/apache/geode/internal/i18n/LocalizedStrings.java b/geode-core/src/main/java/org/apache/geode/internal/i18n/LocalizedStrings.java index cd86460..e1d5e9b 100755 --- a/geode-core/src/main/java/org/apache/geode/internal/i18n/LocalizedStrings.java +++ b/geode-core/src/main/java/org/apache/geode/internal/i18n/LocalizedStrings.java @@ -5568,7 +5568,7 @@ public class LocalizedStrings { public static final StringId CacheClientProxy_CQEXCEPTION_WHILE_CLOSING_NON_DURABLE_CQS_0 = new StringId(4334, "CqException while closing non durable Cqs. {0}"); public static final StringId InitialImageOperation_REGION_0_REQUESTING_INITIAL_IMAGE_FROM_1 = - new StringId(4336, "Region {0} requesting initial image from {1}"); + new StringId(4336, "XXX Region {0} requesting initial image from {1}"); public static final StringId CacheClientUpdater_ERROR_WHILE_PROCESSING_THE_CQ_MESSAGE_PROBLEM_WITH_READING_MESSAGE_FOR_CQ_0 = new StringId(4337, "Error while processing the CQ Message. Problem with reading message for CQ# : {0}");
