giraph-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From ikabi...@apache.org
Subject git commit: updated refs/heads/trunk to c6af3ed
Date Tue, 08 Mar 2016 21:02:42 GMT
Repository: giraph
Updated Branches:
  refs/heads/trunk 0f8d3377e -> c6af3ed8a


[easy] Log aggregate times per piece at the end

Test Plan:
It prints:

  16/03/04 12:46:38 INFO internal.BlockMasterLogic: Time sums master:
     count    time %       time	name
        34    37.50%   00:00:00	PageRankCheckConvergence
        34    62.50%   00:00:00	PageRankUpdate
        68             00:00:00	total

  16/03/04 12:46:38 INFO internal.BlockMasterLogic: Time sums worker:
     count    time %       time	name
        33    50.00%   00:00:00	[receiver=PageRankCheckConvergence,sender=PageRankUpdate]
         1     0.82%   00:00:00	[receiver=PageRankCheckConvergence,sender=null]
        34    47.54%   00:00:00	[receiver=PageRankUpdate,sender=PageRankCheckConvergence]
         1     1.64%   00:00:00	[receiver=null,sender=PageRankUpdate]
        69             00:00:00	total

Reviewers: dionysis.logothetis, sergey.edunov, maja.kabiljo, spupyrev

Reviewed By: spupyrev

Differential Revision: https://reviews.facebook.net/D55113


Project: http://git-wip-us.apache.org/repos/asf/giraph/repo
Commit: http://git-wip-us.apache.org/repos/asf/giraph/commit/c6af3ed8
Tree: http://git-wip-us.apache.org/repos/asf/giraph/tree/c6af3ed8
Diff: http://git-wip-us.apache.org/repos/asf/giraph/diff/c6af3ed8

Branch: refs/heads/trunk
Commit: c6af3ed8a52ddfc3c54c69dab18e36345ba5b92e
Parents: 0f8d337
Author: Igor Kabiljo <ikabiljo@fb.com>
Authored: Fri Mar 4 12:33:35 2016 -0800
Committer: Igor Kabiljo <ikabiljo@fb.com>
Committed: Tue Mar 8 13:02:32 2016 -0800

----------------------------------------------------------------------
 .../framework/internal/BlockCounters.java       | 15 +++-
 .../framework/internal/BlockMasterLogic.java    | 93 +++++++++++++++++++-
 2 files changed, 102 insertions(+), 6 deletions(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/giraph/blob/c6af3ed8/giraph-block-app/src/main/java/org/apache/giraph/block_app/framework/internal/BlockCounters.java
----------------------------------------------------------------------
diff --git a/giraph-block-app/src/main/java/org/apache/giraph/block_app/framework/internal/BlockCounters.java
b/giraph-block-app/src/main/java/org/apache/giraph/block_app/framework/internal/BlockCounters.java
index 6a2fb39..da28537 100644
--- a/giraph-block-app/src/main/java/org/apache/giraph/block_app/framework/internal/BlockCounters.java
+++ b/giraph-block-app/src/main/java/org/apache/giraph/block_app/framework/internal/BlockCounters.java
@@ -20,6 +20,7 @@ package org.apache.giraph.block_app.framework.internal;
 import java.lang.reflect.Field;
 
 import org.apache.giraph.block_app.framework.api.StatusReporter;
+import org.apache.giraph.block_app.framework.internal.BlockMasterLogic.TimeStatsPerEvent;
 
 /** Utility class for Blocks Framework related counters */
 public class BlockCounters {
@@ -60,20 +61,26 @@ public class BlockCounters {
 
   public static void setMasterTimeCounter(
       PairedPieceAndStage<?> masterPiece, long superstep,
-      long millis, StatusReporter reporter) {
+      long millis, StatusReporter reporter,
+      TimeStatsPerEvent timeStats) {
+    String name = masterPiece.getPiece().toString();
     reporter.getCounter(
         GROUP + " Master Timers",
         String.format(
-            "In %6.1f %s (s)", superstep - 0.5, masterPiece.getPiece())
+            "In %6.1f %s (s)", superstep - 0.5, name)
     ).setValue(millis / 1000);
+    timeStats.inc(name, millis);
   }
 
   public static void setWorkerTimeCounter(
       BlockWorkerPieces<?> workerPieces, long superstep,
-      long millis, StatusReporter reporter) {
+      long millis, StatusReporter reporter,
+      TimeStatsPerEvent timeStats) {
+    String name = workerPieces.toStringShort();
     reporter.getCounter(
         GROUP + " Worker Timers",
-        String.format("In %6d %s (s)", superstep, workerPieces.toStringShort())
+        String.format("In %6d %s (s)", superstep, name)
     ).setValue(millis / 1000);
+    timeStats.inc(name, millis);
   }
 }

http://git-wip-us.apache.org/repos/asf/giraph/blob/c6af3ed8/giraph-block-app/src/main/java/org/apache/giraph/block_app/framework/internal/BlockMasterLogic.java
----------------------------------------------------------------------
diff --git a/giraph-block-app/src/main/java/org/apache/giraph/block_app/framework/internal/BlockMasterLogic.java
b/giraph-block-app/src/main/java/org/apache/giraph/block_app/framework/internal/BlockMasterLogic.java
index a52bb77..bd86c21 100644
--- a/giraph-block-app/src/main/java/org/apache/giraph/block_app/framework/internal/BlockMasterLogic.java
+++ b/giraph-block-app/src/main/java/org/apache/giraph/block_app/framework/internal/BlockMasterLogic.java
@@ -19,7 +19,11 @@ package org.apache.giraph.block_app.framework.internal;
 
 import java.util.HashSet;
 import java.util.Iterator;
+import java.util.Map;
+import java.util.Map.Entry;
+import java.util.TreeMap;
 
+import org.apache.commons.lang3.time.DurationFormatUtils;
 import org.apache.giraph.block_app.framework.BlockFactory;
 import org.apache.giraph.block_app.framework.BlockUtils;
 import org.apache.giraph.block_app.framework.api.BlockMasterApi;
@@ -28,6 +32,7 @@ import org.apache.giraph.block_app.framework.block.Block;
 import org.apache.giraph.block_app.framework.piece.AbstractPiece;
 import org.apache.giraph.conf.GiraphConfiguration;
 import org.apache.giraph.function.Consumer;
+import org.apache.giraph.writable.tuple.IntLongWritable;
 import org.apache.log4j.Logger;
 import org.python.google.common.base.Preconditions;
 
@@ -49,6 +54,13 @@ public class BlockMasterLogic<S> {
   private BlockWorkerPieces previousWorkerPieces;
   private boolean computationDone;
 
+  /** Tracks elapsed time on master for each distinct Piece */
+  private final TimeStatsPerEvent masterPerPieceTimeStats =
+      new TimeStatsPerEvent("master");
+  /** Tracks elapsed time on workers for each pair of recieve/send pieces. */
+  private final TimeStatsPerEvent workerPerPieceTimeStats =
+      new TimeStatsPerEvent("worker");
+
   /**
    * Initialize master logic to execute BlockFactory defined in
    * the configuration.
@@ -119,7 +131,7 @@ public class BlockMasterLogic<S> {
     if (lastTimestamp != -1) {
       BlockCounters.setWorkerTimeCounter(
           previousWorkerPieces, superstep - 1,
-          beforeMaster - lastTimestamp, masterApi);
+          beforeMaster - lastTimestamp, masterApi, workerPerPieceTimeStats);
     }
 
     if (previousPiece == null) {
@@ -139,7 +151,8 @@ public class BlockMasterLogic<S> {
 
       if (previousPiece.getPiece() != null) {
         BlockCounters.setMasterTimeCounter(
-            previousPiece, superstep, afterMaster - beforeMaster, masterApi);
+            previousPiece, superstep, afterMaster - beforeMaster, masterApi,
+            masterPerPieceTimeStats);
       }
 
       PairedPieceAndStage<S> nextPiece;
@@ -187,6 +200,82 @@ public class BlockMasterLogic<S> {
         closeAllWriters();
     Preconditions.checkState(!computationDone);
     computationDone = true;
+    IntLongWritable masterTimes = masterPerPieceTimeStats.logTimeSums();
+    IntLongWritable workerTimes = workerPerPieceTimeStats.logTimeSums();
+    LOG.info("Time split:\n" +
+        TimeStatsPerEvent.header() +
+        TimeStatsPerEvent.line(
+            masterTimes.getLeft().get(),
+            100.0 * masterTimes.getRight().get() /
+              (masterTimes.getRight().get() + workerTimes.getRight().get()),
+            masterTimes.getRight().get(),
+            "master") +
+        TimeStatsPerEvent.line(
+            workerTimes.getLeft().get(),
+            100.0 * workerTimes.getRight().get() /
+              (masterTimes.getRight().get() + workerTimes.getRight().get()),
+            workerTimes.getRight().get(),
+            "worker"));
   }
 
+  /**
+   * Class tracking invocation count and elapsed time for a set of events,
+   * each event being having a String name.
+   */
+  public static class TimeStatsPerEvent {
+    private final String groupName;
+    private final Map<String, IntLongWritable> keyToCountAndTime =
+        new TreeMap<>();
+
+    public TimeStatsPerEvent(String groupName) {
+      this.groupName = groupName;
+    }
+
+    public void inc(String name, long millis) {
+      IntLongWritable val = keyToCountAndTime.get(name);
+      if (val == null) {
+        val = new IntLongWritable();
+        keyToCountAndTime.put(name, val);
+      }
+      val.getLeft().set(val.getLeft().get() + 1);
+      val.getRight().set(val.getRight().get() + millis);
+    }
+
+    public IntLongWritable logTimeSums() {
+      StringBuilder sb = new StringBuilder("Time sums " + groupName + ":\n");
+      sb.append(header());
+      long total = 0;
+      int count = 0;
+      for (Entry<String, IntLongWritable> entry :
+            keyToCountAndTime.entrySet()) {
+        total += entry.getValue().getRight().get();
+        count += entry.getValue().getLeft().get();
+      }
+
+      for (Entry<String, IntLongWritable> entry :
+            keyToCountAndTime.entrySet()) {
+        sb.append(line(
+            entry.getValue().getLeft().get(),
+            (100.0 * entry.getValue().getRight().get()) / total,
+            entry.getValue().getRight().get(),
+            entry.getKey()));
+      }
+      LOG.info(sb);
+      return new IntLongWritable(count, total);
+    }
+
+    public static String header() {
+      return String.format(
+          "%10s%10s%11s   %s%n", "count", "time %", "time", "name");
+    }
+
+    public static String line(
+        int count, double percTime, long time, String name) {
+      return String.format("%10d%9.2f%%%11s   %s%n",
+          count,
+          percTime,
+          DurationFormatUtils.formatDuration(time, "HH:mm:ss"),
+          name);
+    }
+  }
 }


Mime
View raw message