You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@cassandra.apache.org by ru...@apache.org on 2020/04/01 15:16:15 UTC
[cassandra] branch trunk updated: Use more appropriate logging
levels.
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 jon@jonhaddad.com <jo...@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-unsubscribe@cassandra.apache.org
For additional commands, e-mail: commits-help@cassandra.apache.org