Reduce unnecessary log lines from compactor (#3590)

Due to many of the unnecessary log lines invoked by the compactor the corfu.9000 log file becomes too chatty and also leads to quick rolling over. This fix helps with the above issue - uses markers to mark unimportant logs and then filter them out in the logback file.
CorfuDB · Apr 17, 2023 · 630d4ae · 630d4ae
1 parent 835f53d
commit 630d4ae
Show file tree

Hide file tree

Showing 7 changed files with 15 additions and 5 deletions.
diff --git a/infrastructure/src/main/resources/logback.prod.xml b/infrastructure/src/main/resources/logback.prod.xml
@@ -3,6 +3,12 @@
 
     <property name="LOG_DIRECTORY" value="/var/log/corfu" />
 
+    <turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
+        <Marker>NOT_IMPORTANT</Marker>
+        <OnMatch>DENY</OnMatch>
+        <OnMismatch>NEUTRAL</OnMismatch>
+    </turboFilter>
+
     <appender name="file" class="ch.qos.logback.core.rolling.RollingFileAppender">
         <file>${LOG_DIRECTORY}/corfu.9000.log</file>
         <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">

diff --git a/runtime/src/main/java/org/corfudb/runtime/CorfuRuntime.java b/runtime/src/main/java/org/corfudb/runtime/CorfuRuntime.java
@@ -42,6 +42,8 @@
 import org.corfudb.util.serializer.Serializers;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
+import org.slf4j.Marker;
+import org.slf4j.MarkerFactory;
 
 import javax.annotation.Nonnull;
 import java.nio.file.Path;
@@ -168,6 +170,8 @@ public class CorfuRuntime {
     @Getter
     private volatile boolean isShutdown = false;
 
+    public static final Marker LOG_NOT_IMPORTANT = MarkerFactory.getMarker("NOT_IMPORTANT");
+
 
     /**
      * This thread is used by fetchLayout to find a new layout in the system

diff --git a/runtime/src/main/java/org/corfudb/runtime/collections/CorfuStore.java b/runtime/src/main/java/org/corfudb/runtime/collections/CorfuStore.java
@@ -102,7 +102,7 @@ Table<K, V, M> openTable(@Nonnull final String namespace,
         Table table =
                 runtime.getTableRegistry().openTable(namespace, tableName, kClass, vClass, mClass, tableOptions);
         corfuStoreMetrics.recordTableCount();
-        log.info("openTable {}${} took {}ms", namespace, tableName, (System.currentTimeMillis() - startTime));
+        log.info(CorfuRuntime.LOG_NOT_IMPORTANT, "openTable {}${} took {}ms", namespace, tableName, (System.currentTimeMillis() - startTime));
         return table;
     }
 

diff --git a/runtime/src/main/java/org/corfudb/runtime/object/MVOCorfuCompileProxy.java b/runtime/src/main/java/org/corfudb/runtime/object/MVOCorfuCompileProxy.java
@@ -92,7 +92,7 @@ private <R> R accessInner(ICorfuSMRAccess<R, T> accessMethod,
 
         // Linearize this read against a timestamp
         long timestamp = rt.getSequencerView().query(getStreamID());
-        log.debug("Access[{}] conflictObj={} version={}", this, conflictObject, timestamp);
+        log.trace("Access[{}] conflictObj={} version={}", this, conflictObject, timestamp);
 
         // Perform underlying access
         ICorfuSMRSnapshotProxy<T> snapshotProxy = underlyingMVO.getSnapshotProxy(timestamp);

diff --git a/...src/main/java/org/corfudb/runtime/object/transactions/OptimisticTransactionalContext.java b/...src/main/java/org/corfudb/runtime/object/transactions/OptimisticTransactionalContext.java
@@ -72,7 +72,7 @@ public <R, T extends ICorfuSMR<T>> R access(ICorfuSMRProxyInternal<T> proxy,
                                                 Object[] conflictObject) {
         long startAccessTime = System.nanoTime();
         try {
-            log.debug("Access[{},{}] conflictObj={}", this, proxy, conflictObject);
+            log.trace("Access[{},{}] conflictObj={}", this, proxy, conflictObject);
 
             // First, we add this access to the read set
             addToReadSet(proxy, conflictObject);

diff --git a/runtime/src/main/java/org/corfudb/runtime/view/SMRObject.java b/runtime/src/main/java/org/corfudb/runtime/view/SMRObject.java
@@ -137,7 +137,7 @@ public T open() {
             final SMRObject<T> smrObject = build();
 
             try {
-                log.info("ObjectBuilder: open Corfu stream {} id {}", smrObject.getStreamName(),
+                log.info(CorfuRuntime.LOG_NOT_IMPORTANT, "ObjectBuilder: open Corfu stream {} id {}", smrObject.getStreamName(),
                         smrObject.getStreamID());
 
                 if (smrObject.getOption() == ObjectOpenOption.NO_CACHE) {

diff --git a/runtime/src/main/java/org/corfudb/runtime/view/TableRegistry.java b/runtime/src/main/java/org/corfudb/runtime/view/TableRegistry.java
@@ -576,7 +576,7 @@ Table<K, V, M> openTable(@Nonnull final String namespace,
                 .map(StreamTagInfo::getStreamId)
                 .collect(Collectors.toSet());
 
-        log.info("openTable: opening {}${} with stream tags {}", namespace, tableName, streamTagInfoForTable);
+        log.info(CorfuRuntime.LOG_NOT_IMPORTANT, "openTable: opening {}${} with stream tags {}", namespace, tableName, streamTagInfoForTable);
 
         // Open and return table instance.
         Table<K, V, M> table = new Table<>(