This is an automated email from the ASF dual-hosted git repository. rustyrazorblade pushed a commit to branch trunk in repository https://gitbox.apache.org/repos/asf/cassandra.git
The following commit(s) were added to refs/heads/trunk by this push: new dd9a6e0 Use more appropriate logging levels. dd9a6e0 is described below commit dd9a6e0a8a691bdee357eb6559f1b2b92b076925 Author: Jon Haddad j...@jonhaddad.com <j...@jonhaddad.com> AuthorDate: Tue Mar 24 13:44:17 2020 -0700 Use more appropriate logging levels. The following logging was changed: * When the Commit log reader finishes logging each segment, from debug to info * When starting a new compaction, logging details of the compaction task, from debug -> info * When finishing a compaction, logging details of how many sstables, sizes, etc, from debug -> info * When performing a validation compaction, adding helpful logging * When flushing memtables, log details. debug -> info * When flushing largest memtable to free up room, logging more details at INFO * Various logging messages for incremental repair moved to INFO from debug * When failing incremental repair phase, log a warning instead of debug message Patch by Jon Haddad; Reviewed by Alexander Dejanovski for CASSANDRA-15661 --- CHANGES.txt | 1 + .../org/apache/cassandra/db/ColumnFamilyStore.java | 4 +-- src/java/org/apache/cassandra/db/Memtable.java | 12 ++++---- .../cassandra/db/commitlog/CommitLogReader.java | 2 +- .../cassandra/db/compaction/CompactionTask.java | 33 +++++++++++----------- .../db/repair/CassandraValidationIterator.java | 2 ++ .../org/apache/cassandra/io/sstable/SSTable.java | 2 +- .../cassandra/io/sstable/format/SSTableReader.java | 6 ++-- .../apache/cassandra/repair/ValidationManager.java | 1 + .../repair/consistent/CoordinatorSession.java | 12 ++++---- .../cassandra/repair/consistent/LocalSessions.java | 18 ++++++------ .../transport/ConnectionLimitHandler.java | 4 +-- 12 files changed, 48 insertions(+), 49 deletions(-) diff --git a/CHANGES.txt b/CHANGES.txt index 3057ca6..dbe5926 100644 --- a/CHANGES.txt +++ b/CHANGES.txt @@ -1,4 +1,5 @@ 4.0-alpha4 + * Use more appropriate logging levels (CASSANDRA-15661) * Added production recommendations and improved compaction doc organization * Document usage of EC2Snitch with intra-region VPC peering (CASSANDRA-15337) * Fixed flakey test in SASIIndexTest by shutting down its ExecutorService (CASSANDRA-15528) diff --git a/src/java/org/apache/cassandra/db/ColumnFamilyStore.java b/src/java/org/apache/cassandra/db/ColumnFamilyStore.java index 61129bb..ea04c86 100644 --- a/src/java/org/apache/cassandra/db/ColumnFamilyStore.java +++ b/src/java/org/apache/cassandra/db/ColumnFamilyStore.java @@ -843,7 +843,7 @@ public class ColumnFamilyStore implements ColumnFamilyStoreMBean offHeapTotal += allocator.offHeap().owns(); } - logger.debug("Enqueuing flush of {}: {}", + logger.info("Enqueuing flush of {}: {}", name, String.format("%s (%.0f%%) on-heap, %s (%.0f%%) off-heap", FBUtilities.prettyPrintMemory(onHeapTotal), @@ -1233,7 +1233,7 @@ public class ColumnFamilyStore implements ColumnFamilyStoreMBean float flushingOffHeap = Memtable.MEMORY_POOL.offHeap.reclaimingRatio(); float thisOnHeap = largest.getAllocator().onHeap().ownershipRatio(); float thisOffHeap = largest.getAllocator().offHeap().ownershipRatio(); - logger.debug("Flushing largest {} to free up room. Used total: {}, live: {}, flushing: {}, this: {}", + logger.info("Flushing largest {} to free up room. Used total: {}, live: {}, flushing: {}, this: {}", largest.cfs, ratio(usedOnHeap, usedOffHeap), ratio(liveOnHeap, liveOffHeap), ratio(flushingOnHeap, flushingOffHeap), ratio(thisOnHeap, thisOffHeap)); largest.cfs.switchMemtableIfCurrent(largest); diff --git a/src/java/org/apache/cassandra/db/Memtable.java b/src/java/org/apache/cassandra/db/Memtable.java index 436b7ef..ba6337b 100644 --- a/src/java/org/apache/cassandra/db/Memtable.java +++ b/src/java/org/apache/cassandra/db/Memtable.java @@ -449,8 +449,7 @@ public class Memtable implements Comparable<Memtable> private void writeSortedContents() { - if (logger.isDebugEnabled()) - logger.debug("Writing {}, flushed range = ({}, {}]", Memtable.this.toString(), from, to); + logger.info("Writing {}, flushed range = ({}, {}]", Memtable.this.toString(), from, to); boolean trackContention = logger.isTraceEnabled(); int heavilyContendedRowCount = 0; @@ -479,11 +478,10 @@ public class Memtable implements Comparable<Memtable> } long bytesFlushed = writer.getFilePointer(); - if (logger.isDebugEnabled()) - logger.debug("Completed flushing {} ({}) for commitlog position {}", - writer.getFilename(), - FBUtilities.prettyPrintMemory(bytesFlushed), - commitLogUpperBound); + logger.info("Completed flushing {} ({}) for commitlog position {}", + writer.getFilename(), + FBUtilities.prettyPrintMemory(bytesFlushed), + commitLogUpperBound); // Update the metrics cfs.metric.bytesFlushed.inc(bytesFlushed); diff --git a/src/java/org/apache/cassandra/db/commitlog/CommitLogReader.java b/src/java/org/apache/cassandra/db/commitlog/CommitLogReader.java index 078bb53..c91841f 100644 --- a/src/java/org/apache/cassandra/db/commitlog/CommitLogReader.java +++ b/src/java/org/apache/cassandra/db/commitlog/CommitLogReader.java @@ -253,7 +253,7 @@ public class CommitLogReader throw (IOException) re.getCause(); throw re; } - logger.debug("Finished reading {}", file); + logger.info("Finished reading {}", file); } } diff --git a/src/java/org/apache/cassandra/db/compaction/CompactionTask.java b/src/java/org/apache/cassandra/db/compaction/CompactionTask.java index 725f04d..764ad5b 100644 --- a/src/java/org/apache/cassandra/db/compaction/CompactionTask.java +++ b/src/java/org/apache/cassandra/db/compaction/CompactionTask.java @@ -153,7 +153,7 @@ public class CompactionTask extends AbstractCompactionTask } ssTableLoggerMsg.append("]"); - logger.debug("Compacting ({}) {}", taskId, ssTableLoggerMsg); + logger.info("Compacting ({}) {}", taskId, ssTableLoggerMsg); RateLimiter limiter = CompactionManager.instance.getRateLimiter(); long start = System.nanoTime(); @@ -248,22 +248,21 @@ public class CompactionTask extends AbstractCompactionTask String mergeSummary = updateCompactionHistory(cfs.keyspace.getName(), cfs.getTableName(), mergedRowCounts, startsize, endsize); - if (logger.isDebugEnabled()) - logger.debug(String.format("Compacted (%s) %d sstables to [%s] to level=%d. %s to %s (~%d%% of original) in %,dms. Read Throughput = %s, Write Throughput = %s, Row Throughput = ~%,d/s. %,d total partitions merged to %,d. Partition merge counts were {%s}", - taskId, - transaction.originals().size(), - newSSTableNames.toString(), - getLevel(), - FBUtilities.prettyPrintMemory(startsize), - FBUtilities.prettyPrintMemory(endsize), - (int) (ratio * 100), - dTime, - FBUtilities.prettyPrintMemoryPerSecond(startsize, durationInNano), - FBUtilities.prettyPrintMemoryPerSecond(endsize, durationInNano), - (int) totalSourceCQLRows / (TimeUnit.NANOSECONDS.toSeconds(durationInNano) + 1), - totalSourceRows, - totalKeysWritten, - mergeSummary)); + logger.info(String.format("Compacted (%s) %d sstables to [%s] to level=%d. %s to %s (~%d%% of original) in %,dms. Read Throughput = %s, Write Throughput = %s, Row Throughput = ~%,d/s. %,d total partitions merged to %,d. Partition merge counts were {%s}", + taskId, + transaction.originals().size(), + newSSTableNames.toString(), + getLevel(), + FBUtilities.prettyPrintMemory(startsize), + FBUtilities.prettyPrintMemory(endsize), + (int) (ratio * 100), + dTime, + FBUtilities.prettyPrintMemoryPerSecond(startsize, durationInNano), + FBUtilities.prettyPrintMemoryPerSecond(endsize, durationInNano), + (int) totalSourceCQLRows / (TimeUnit.NANOSECONDS.toSeconds(durationInNano) + 1), + totalSourceRows, + totalKeysWritten, + mergeSummary)); if (logger.isTraceEnabled()) { logger.trace("CF Total Bytes Compacted: {}", FBUtilities.prettyPrintMemory(CompactionTask.addToTotalBytesCompacted(endsize))); diff --git a/src/java/org/apache/cassandra/db/repair/CassandraValidationIterator.java b/src/java/org/apache/cassandra/db/repair/CassandraValidationIterator.java index 4eea678..6c6f084 100644 --- a/src/java/org/apache/cassandra/db/repair/CassandraValidationIterator.java +++ b/src/java/org/apache/cassandra/db/repair/CassandraValidationIterator.java @@ -204,6 +204,8 @@ public class CassandraValidationIterator extends ValidationPartitionIterator } Preconditions.checkArgument(sstables != null); + logger.info("Performing validation compaction on {} sstables", sstables.size()); + logger.debug("Performing validation compaction on {}", sstables); controller = new ValidationCompactionController(cfs, getDefaultGcBefore(cfs, nowInSec)); scanners = cfs.getCompactionStrategyManager().getScanners(sstables, ranges); ci = new ValidationCompactionIterator(scanners.scanners, controller, nowInSec, CompactionManager.instance.active); diff --git a/src/java/org/apache/cassandra/io/sstable/SSTable.java b/src/java/org/apache/cassandra/io/sstable/SSTable.java index 055bf24..348d7f5 100644 --- a/src/java/org/apache/cassandra/io/sstable/SSTable.java +++ b/src/java/org/apache/cassandra/io/sstable/SSTable.java @@ -108,7 +108,7 @@ public abstract class SSTable */ public static boolean delete(Descriptor desc, Set<Component> components) { - logger.debug("Deleting sstable: {}", desc); + logger.info("Deleting sstable: {}", desc); // remove the DATA component first if it exists if (components.contains(Component.DATA)) FileUtils.deleteWithConfirm(desc.filenameFor(Component.DATA)); diff --git a/src/java/org/apache/cassandra/io/sstable/format/SSTableReader.java b/src/java/org/apache/cassandra/io/sstable/format/SSTableReader.java index 92a432e..cff6042 100644 --- a/src/java/org/apache/cassandra/io/sstable/format/SSTableReader.java +++ b/src/java/org/apache/cassandra/io/sstable/format/SSTableReader.java @@ -430,8 +430,7 @@ public abstract class SSTableReader extends SSTable implements SelfRefCounted<SS } long fileLength = new File(descriptor.filenameFor(Component.DATA)).length(); - if (logger.isDebugEnabled()) - logger.debug("Opening {} ({})", descriptor, FBUtilities.prettyPrintMemory(fileLength)); + logger.info("Opening {} ({})", descriptor, FBUtilities.prettyPrintMemory(fileLength)); final SSTableReader sstable; try @@ -530,8 +529,7 @@ public abstract class SSTableReader extends SSTable implements SelfRefCounted<SS } long fileLength = new File(descriptor.filenameFor(Component.DATA)).length(); - if (logger.isDebugEnabled()) - logger.debug("Opening {} ({})", descriptor, FBUtilities.prettyPrintMemory(fileLength)); + logger.info("Opening {} ({})", descriptor, FBUtilities.prettyPrintMemory(fileLength)); final SSTableReader sstable; try diff --git a/src/java/org/apache/cassandra/repair/ValidationManager.java b/src/java/org/apache/cassandra/repair/ValidationManager.java index bbd5219..4bbffbf 100644 --- a/src/java/org/apache/cassandra/repair/ValidationManager.java +++ b/src/java/org/apache/cassandra/repair/ValidationManager.java @@ -165,6 +165,7 @@ public class ValidationManager { // we need to inform the remote end of our failure, otherwise it will hang on repair forever validator.fail(); + logger.error("Validation failed.", e); throw e; } return this; diff --git a/src/java/org/apache/cassandra/repair/consistent/CoordinatorSession.java b/src/java/org/apache/cassandra/repair/consistent/CoordinatorSession.java index d0b1f70..9d440c2 100644 --- a/src/java/org/apache/cassandra/repair/consistent/CoordinatorSession.java +++ b/src/java/org/apache/cassandra/repair/consistent/CoordinatorSession.java @@ -150,7 +150,7 @@ public class CoordinatorSession extends ConsistentSession { Preconditions.checkArgument(allStates(State.PREPARING)); - logger.debug("Beginning prepare phase of incremental repair session {}", sessionID); + logger.info("Beginning prepare phase of incremental repair session {}", sessionID); Message<RepairMessage> message = Message.out(Verb.PREPARE_CONSISTENT_REQ, new PrepareConsistentRequest(sessionID, coordinator, participants)); for (final InetAddressAndPort participant : participants) @@ -164,7 +164,7 @@ public class CoordinatorSession extends ConsistentSession { if (!success) { - logger.debug("{} failed the prepare phase for incremental repair session {}", participant, sessionID); + logger.warn("{} failed the prepare phase for incremental repair session {}", participant, sessionID); sendFailureMessageToParticipants(); setParticipantState(participant, State.FAILED); } @@ -198,7 +198,7 @@ public class CoordinatorSession extends ConsistentSession public synchronized ListenableFuture<Boolean> finalizePropose() { Preconditions.checkArgument(allStates(State.REPAIRING)); - logger.debug("Proposing finalization of repair session {}", sessionID); + logger.info("Proposing finalization of repair session {}", sessionID); Message<RepairMessage> message = Message.out(Verb.FINALIZE_PROPOSE_MSG, new FinalizePropose(sessionID)); for (final InetAddressAndPort participant : participants) { @@ -215,7 +215,7 @@ public class CoordinatorSession extends ConsistentSession } else if (!success) { - logger.debug("Finalization proposal of session {} rejected by {}. Aborting session", sessionID, participant); + logger.warn("Finalization proposal of session {} rejected by {}. Aborting session", sessionID, participant); fail(); finalizeProposeFuture.set(false); } @@ -225,7 +225,7 @@ public class CoordinatorSession extends ConsistentSession setParticipantState(participant, State.FINALIZE_PROMISED); if (getState() == State.FINALIZE_PROMISED) { - logger.debug("Finalization proposal for repair session {} accepted by all participants.", sessionID); + logger.info("Finalization proposal for repair session {} accepted by all participants.", sessionID); finalizeProposeFuture.set(true); } } @@ -234,7 +234,7 @@ public class CoordinatorSession extends ConsistentSession public synchronized void finalizeCommit() { Preconditions.checkArgument(allStates(State.FINALIZE_PROMISED)); - logger.debug("Committing finalization of repair session {}", sessionID); + logger.info("Committing finalization of repair session {}", sessionID); Message<RepairMessage> message = Message.out(Verb.FINALIZE_COMMIT_MSG, new FinalizeCommit(sessionID)); for (final InetAddressAndPort participant : participants) { diff --git a/src/java/org/apache/cassandra/repair/consistent/LocalSessions.java b/src/java/org/apache/cassandra/repair/consistent/LocalSessions.java index fa224d1..a35c50a 100644 --- a/src/java/org/apache/cassandra/repair/consistent/LocalSessions.java +++ b/src/java/org/apache/cassandra/repair/consistent/LocalSessions.java @@ -277,7 +277,7 @@ public class LocalSessions { if (!sessionHasData(session)) { - logger.debug("Auto deleting repair session {}", session); + logger.info("Auto deleting repair session {}", session); deleteSession(session.sessionID); } else @@ -554,7 +554,7 @@ public class LocalSessions public synchronized void deleteSession(UUID sessionID) { - logger.debug("Deleting local repair session {}", sessionID); + logger.info("Deleting local repair session {}", sessionID); LocalSession session = getSession(sessionID); Preconditions.checkArgument(session.isCompleted(), "Cannot delete incomplete sessions"); @@ -679,7 +679,7 @@ public class LocalSessions LocalSession session = getSession(sessionID); if (session != null && session.getState() != REPAIRING) { - logger.debug("Setting local incremental repair session {} to REPAIRING", session); + logger.info("Setting local incremental repair session {} to REPAIRING", session); setStateAndSave(session, REPAIRING); } } @@ -691,7 +691,7 @@ public class LocalSessions LocalSession session = getSession(sessionID); if (session == null) { - logger.debug("Received FinalizePropose message for unknown repair session {}, responding with failure", sessionID); + logger.info("Received FinalizePropose message for unknown repair session {}, responding with failure", sessionID); sendMessage(from, Message.out(FAILED_SESSION_MSG, new FailSession(sessionID))); return; } @@ -710,11 +710,11 @@ public class LocalSessions syncTable(); sendMessage(from, Message.out(FINALIZE_PROMISE_MSG, new FinalizePromise(sessionID, getBroadcastAddressAndPort(), true))); - logger.debug("Received FinalizePropose message for incremental repair session {}, responded with FinalizePromise", sessionID); + logger.info("Received FinalizePropose message for incremental repair session {}, responded with FinalizePromise", sessionID); } catch (IllegalArgumentException e) { - logger.error(String.format("Error handling FinalizePropose message for %s", session), e); + logger.error("Error handling FinalizePropose message for {}", session, e); failSession(sessionID); } } @@ -762,7 +762,7 @@ public class LocalSessions public void sendStatusRequest(LocalSession session) { - logger.debug("Attempting to learn the outcome of unfinished local incremental repair session {}", session.sessionID); + logger.info("Attempting to learn the outcome of unfinished local incremental repair session {}", session.sessionID); Message<StatusRequest> request = Message.out(STATUS_REQ, new StatusRequest(session.sessionID)); for (InetAddressAndPort participant : session.participants) @@ -787,7 +787,7 @@ public class LocalSessions else { sendMessage(from, Message.out(STATUS_RSP, new StatusResponse(sessionID, session.getState()))); - logger.debug("Responding to status response message for incremental repair session {} with local state {}", sessionID, session.getState()); + logger.info("Responding to status response message for incremental repair session {} with local state {}", sessionID, session.getState()); } } @@ -811,7 +811,7 @@ public class LocalSessions } else { - logger.debug("Received StatusResponse for repair session {} with state {}, which is not actionable. Doing nothing.", sessionID, response.state); + logger.info("Received StatusResponse for repair session {} with state {}, which is not actionable. Doing nothing.", sessionID, response.state); } } diff --git a/src/java/org/apache/cassandra/transport/ConnectionLimitHandler.java b/src/java/org/apache/cassandra/transport/ConnectionLimitHandler.java index 3b2765f..2269036 100644 --- a/src/java/org/apache/cassandra/transport/ConnectionLimitHandler.java +++ b/src/java/org/apache/cassandra/transport/ConnectionLimitHandler.java @@ -61,7 +61,7 @@ final class ConnectionLimitHandler extends ChannelInboundHandlerAdapter if (count > limit) { // The decrement will be done in channelClosed(...) - noSpamLogger.warn("Exceeded maximum native connection limit of {} by using {} connections", limit, count); + noSpamLogger.error("Exceeded maximum native connection limit of {} by using {} connections (see native_transport_max_concurrent_connections in cassandra.yaml)", limit, count); ctx.close(); } else @@ -85,7 +85,7 @@ final class ConnectionLimitHandler extends ChannelInboundHandlerAdapter if (perIpCount.incrementAndGet() > perIpLimit) { // The decrement will be done in channelClosed(...) - noSpamLogger.warn("Exceeded maximum native connection limit per ip of {} by using {} connections", perIpLimit, perIpCount); + noSpamLogger.error("Exceeded maximum native connection limit per ip of {} by using {} connections (see native_transport_max_concurrent_connections_per_ip)", perIpLimit, perIpCount); ctx.close(); return; } --------------------------------------------------------------------- To unsubscribe, e-mail: commits-unsubscr...@cassandra.apache.org For additional commands, e-mail: commits-h...@cassandra.apache.org