You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@giraph.apache.org by ik...@apache.org on 2016/03/08 22:02:42 UTC
git commit: updated refs/heads/trunk to c6af3ed
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 <ik...@fb.com>
Authored: Fri Mar 4 12:33:35 2016 -0800
Committer: Igor Kabiljo <ik...@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);
+ }
+ }
}