Out-of-core is logging too aggressively

Summary: Example aggressive logging at INFO level: INFO <datestamp> [ooc-io-0] org.apache.giraph.ooc.policy.ThresholdBasedOracle - getNextIOActions: usedMemoryFraction = 0.79 INFO <datestamp> [ooc-io-0] org.apache.giraph.ooc.OutOfCoreIOCallable - call: thread 0's next IO command is: LoadPartitionIOCommand: (partitionId = 4676, superstep = 0) INFO <datestamp> [ooc-io-0] org.apache.giraph.ooc.OutOfCoreIOCallable - call: thread 0's command LoadPartitionIOCommand: (partitionId = 4676, superstep = 0) completed: bytes= 0, duration=0, bandwidth=NaN, bandwidth (excluding GC time)=NaN Test Plan: mvn clean verify -P hadoop_facebook Reviewers: majakabiljo, maja.kabiljo, sergey.edunov, heslami Reviewed By: heslami Subscribers: dionysis.logothetis Differential Revision: https://reviews.facebook.net/D62853
apache · Aug 30, 2016 · 8205f0d · 8205f0d
1 parent a15675c
commit 8205f0d
Show file tree

Hide file tree

Showing 3 changed files with 10 additions and 8 deletions.
diff --git a/giraph-core/src/main/java/org/apache/giraph/ooc/OutOfCoreIOCallable.java b/giraph-core/src/main/java/org/apache/giraph/ooc/OutOfCoreIOCallable.java
@@ -76,8 +76,8 @@ public Void call() throws Exception {
     while (true) {
       oocEngine.getSuperstepLock().readLock().lock();
       IOCommand command = oocEngine.getIOScheduler().getNextIOCommand(diskId);
-      if (LOG.isInfoEnabled() && !(command instanceof WaitIOCommand)) {
-        LOG.info("call: thread " + diskId + "'s next IO command is: " +
+      if (LOG.isDebugEnabled() && !(command instanceof WaitIOCommand)) {
+        LOG.debug("call: thread " + diskId + "'s next IO command is: " +
             command);
       }
       if (command == null) {
@@ -101,8 +101,8 @@ public Void call() throws Exception {
         timeInGC = oocEngine.getServiceWorker().getGraphTaskManager()
             .getSuperstepGCTime() - timeInGC;
         bytes = command.bytesTransferred();
-        if (LOG.isInfoEnabled() && !(command instanceof WaitIOCommand)) {
-          LOG.info("call: thread " + diskId + "'s command " + command +
+        if (LOG.isDebugEnabled() && !(command instanceof WaitIOCommand)) {
+          LOG.debug("call: thread " + diskId + "'s command " + command +
               " completed: bytes= " + bytes + ", duration=" + duration + ", " +
               "bandwidth=" + String.format("%.2f", (double) bytes / duration *
               1000 / 1024 / 1024) +

diff --git a/giraph-core/src/main/java/org/apache/giraph/ooc/policy/FixedPartitionsOracle.java b/giraph-core/src/main/java/org/apache/giraph/ooc/policy/FixedPartitionsOracle.java
@@ -95,8 +95,10 @@ public IOAction[] getNextIOActions() {
         IOAction.LOAD_PARTITION,
         IOAction.STORE_MESSAGES_AND_BUFFERS};
     } else if (numPartitions > maxPartitionsInMemory) {
-      LOG.warn("getNextIOActions: number of partitions in memory passed the " +
-          "specified threshold!");
+      if (LOG.isDebugEnabled()) {
+        LOG.debug("getNextIOActions: number of partitions in memory passed " +
+          "the specified threshold!");
+      }
       return new IOAction[]{
         IOAction.STORE_PARTITION,
         IOAction.STORE_MESSAGES_AND_BUFFERS};

diff --git a/giraph-core/src/main/java/org/apache/giraph/ooc/policy/ThresholdBasedOracle.java b/giraph-core/src/main/java/org/apache/giraph/ooc/policy/ThresholdBasedOracle.java
@@ -285,8 +285,8 @@ public void updateRates(double usedMemoryFraction) {
   @Override
   public IOAction[] getNextIOActions() {
     double usedMemoryFraction = 1 - MemoryUtils.freeMemoryFraction();
-    if (LOG.isInfoEnabled()) {
-      LOG.info(String.format("getNextIOActions: usedMemoryFraction = %.2f",
+    if (LOG.isDebugEnabled()) {
+      LOG.debug(String.format("getNextIOActions: usedMemoryFraction = %.2f",
           usedMemoryFraction));
     }
     if (usedMemoryFraction > highMemoryPressure) {