You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@mesos.apache.org by bm...@apache.org on 2013/07/13 01:08:46 UTC
git commit: Added timing information to Scheduler and Executor
callbacks when verbose logging is enabled.
Updated Branches:
refs/heads/master 9929d2b8c -> 0cb8a5d73
Added timing information to Scheduler and Executor callbacks when
verbose logging is enabled.
Review: https://reviews.apache.org/r/12520
Project: http://git-wip-us.apache.org/repos/asf/mesos/repo
Commit: http://git-wip-us.apache.org/repos/asf/mesos/commit/0cb8a5d7
Tree: http://git-wip-us.apache.org/repos/asf/mesos/tree/0cb8a5d7
Diff: http://git-wip-us.apache.org/repos/asf/mesos/diff/0cb8a5d7
Branch: refs/heads/master
Commit: 0cb8a5d73785c957d344aaded04802134f33a6f0
Parents: 9929d2b
Author: Benjamin Mahler <bm...@twitter.com>
Authored: Fri Jul 12 13:57:34 2013 -0700
Committer: Benjamin Mahler <bm...@twitter.com>
Committed: Fri Jul 12 16:08:37 2013 -0700
----------------------------------------------------------------------
src/exec/exec.cpp | 60 ++++++++++++++++++++++++++++++++++++++++
src/sched/sched.cpp | 71 ++++++++++++++++++++++++++++++++++++++++++++++++
2 files changed, 131 insertions(+)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/mesos/blob/0cb8a5d7/src/exec/exec.cpp
----------------------------------------------------------------------
diff --git a/src/exec/exec.cpp b/src/exec/exec.cpp
index 116168f..d467724 100644
--- a/src/exec/exec.cpp
+++ b/src/exec/exec.cpp
@@ -39,6 +39,7 @@
#include <stout/numify.hpp>
#include <stout/option.hpp>
#include <stout/os.hpp>
+#include <stout/stopwatch.hpp>
#include <stout/stringify.hpp>
#include <stout/uuid.hpp>
@@ -194,7 +195,15 @@ protected:
VLOG(1) << "Executor registered on slave " << slaveId;
connected = true;
+
+ Stopwatch stopwatch;
+ if (FLAGS_v >= 1) {
+ stopwatch.start();
+ }
+
executor->registered(driver, executorInfo, frameworkInfo, slaveInfo);
+
+ VLOG(1) << "Executor::registered took " << stopwatch.elapsed();
}
void reregistered(const SlaveID& slaveId, const SlaveInfo& slaveInfo)
@@ -207,7 +216,14 @@ protected:
VLOG(1) << "Executor re-registered on slave " << slaveId;
+ Stopwatch stopwatch;
+ if (FLAGS_v >= 1) {
+ stopwatch.start();
+ }
+
executor->reregistered(driver, slaveInfo);
+
+ VLOG(1) << "Executor::reregistered took " << stopwatch.elapsed();
}
void reconnect(const SlaveID& slaveId)
@@ -257,7 +273,14 @@ protected:
VLOG(1) << "Executor asked to run task '" << task.task_id() << "'";
+ Stopwatch stopwatch;
+ if (FLAGS_v >= 1) {
+ stopwatch.start();
+ }
+
executor->launchTask(driver, task);
+
+ VLOG(1) << "Executor::launchTask took " << stopwatch.elapsed();
}
void killTask(const TaskID& taskId)
@@ -270,7 +293,14 @@ protected:
VLOG(1) << "Executor asked to kill task '" << taskId << "'";
+ Stopwatch stopwatch;
+ if (FLAGS_v >= 1) {
+ stopwatch.start();
+ }
+
executor->killTask(driver, taskId);
+
+ VLOG(1) << "Executor::killTask took " << stopwatch.elapsed();
}
void statusUpdateAcknowledgement(
@@ -310,7 +340,14 @@ protected:
VLOG(1) << "Executor received framework message";
+ Stopwatch stopwatch;
+ if (FLAGS_v >= 1) {
+ stopwatch.start();
+ }
+
executor->frameworkMessage(driver, data);
+
+ VLOG(1) << "Executor::frameworkMessage took " << stopwatch.elapsed();
}
void shutdown()
@@ -327,8 +364,16 @@ protected:
spawn(new ShutdownProcess(), true);
}
+ Stopwatch stopwatch;
+ if (FLAGS_v >= 1) {
+ stopwatch.start();
+ }
+
// TODO(benh): Any need to invoke driver.stop?
executor->shutdown(driver);
+
+ VLOG(1) << "Executor::shutdown took " << stopwatch.elapsed();
+
aborted = true; // To make sure not to accept any new messages.
if (local) {
@@ -365,8 +410,16 @@ protected:
spawn(new ShutdownProcess(), true);
}
+ Stopwatch stopwatch;
+ if (FLAGS_v >= 1) {
+ stopwatch.start();
+ }
+
// TODO: Pass an argument to shutdown to tell it this is abnormal?
executor->shutdown(driver);
+
+ VLOG(1) << "Executor::shutdown took " << stopwatch.elapsed();
+
aborted = true; // To make sure not to accept any new messages.
// This is a pretty bad state ... no slave is left. Rather
@@ -387,8 +440,15 @@ protected:
driver->abort();
+ Stopwatch stopwatch;
+ if (FLAGS_v >= 1) {
+ stopwatch.start();
+ }
+
executor->error(driver, "Attempted to send TASK_STAGING status update");
+ VLOG(1) << "Executor::error took " << stopwatch.elapsed();
+
return;
}
http://git-wip-us.apache.org/repos/asf/mesos/blob/0cb8a5d7/src/sched/sched.cpp
----------------------------------------------------------------------
diff --git a/src/sched/sched.cpp b/src/sched/sched.cpp
index 7ea82e5..62abd38 100644
--- a/src/sched/sched.cpp
+++ b/src/sched/sched.cpp
@@ -43,6 +43,7 @@
#include <stout/flags.hpp>
#include <stout/hashmap.hpp>
#include <stout/os.hpp>
+#include <stout/stopwatch.hpp>
#include <stout/uuid.hpp>
#include "common/lock.hpp"
@@ -182,7 +183,14 @@ protected:
// If master failed over, inform the scheduler about the
// disconnection.
if (connected) {
+ Stopwatch stopwatch;
+ if (FLAGS_v >= 1) {
+ stopwatch.start();
+ }
+
scheduler->disconnected(driver);
+
+ VLOG(1) << "Scheduler::disconnected took " << stopwatch.elapsed();
}
connected = false;
@@ -196,7 +204,14 @@ protected:
// Inform the scheduler about the disconnection if the driver
// was previously registered with the master.
if (connected) {
+ Stopwatch stopwatch;
+ if (FLAGS_v >= 1) {
+ stopwatch.start();
+ }
+
scheduler->disconnected(driver);
+
+ VLOG(1) << "Scheduler::disconnected took " << stopwatch.elapsed();
}
// In this case, we don't actually invoke Scheduler::error
@@ -226,7 +241,14 @@ protected:
connected = true;
failover = false;
+ Stopwatch stopwatch;
+ if (FLAGS_v >= 1) {
+ stopwatch.start();
+ }
+
scheduler->registered(driver, frameworkId, masterInfo);
+
+ VLOG(1) << "Scheduler::registered took " << stopwatch.elapsed();
}
void reregistered(const FrameworkID& frameworkId, const MasterInfo& masterInfo)
@@ -250,7 +272,14 @@ protected:
connected = true;
failover = false;
+ Stopwatch stopwatch;
+ if (FLAGS_v >= 1) {
+ stopwatch.start();
+ }
+
scheduler->reregistered(driver, masterInfo);
+
+ VLOG(1) << "Scheduler::reregistered took " << stopwatch.elapsed();
}
void doReliableRegistration()
@@ -301,7 +330,14 @@ protected:
}
}
+ Stopwatch stopwatch;
+ if (FLAGS_v >= 1) {
+ stopwatch.start();
+ }
+
scheduler->resourceOffers(driver, offers);
+
+ VLOG(1) << "Scheduler::resourceOffers took " << stopwatch.elapsed();
}
void rescindOffer(const OfferID& offerId)
@@ -316,7 +352,14 @@ protected:
savedOffers.erase(offerId);
+ Stopwatch stopwatch;
+ if (FLAGS_v >= 1) {
+ stopwatch.start();
+ }
+
scheduler->offerRescinded(driver, offerId);
+
+ VLOG(1) << "Scheduler::offerRescinded took " << stopwatch.elapsed();
}
void statusUpdate(const StatusUpdate& update, const UPID& pid)
@@ -342,8 +385,15 @@ protected:
// multiple times (of course, if a scheduler re-uses a TaskID,
// that could be bad.
+ Stopwatch stopwatch;
+ if (FLAGS_v >= 1) {
+ stopwatch.start();
+ }
+
scheduler->statusUpdate(driver, status);
+ VLOG(1) << "Scheduler::statusUpdate took " << stopwatch.elapsed();
+
// Acknowledge the status update.
// NOTE: We do a dispatch here instead of directly sending the ACK because,
// we want to avoid sending the ACK if the driver was aborted when we
@@ -390,7 +440,14 @@ protected:
savedSlavePids.erase(slaveId);
+ Stopwatch stopwatch;
+ if (FLAGS_v >= 1) {
+ stopwatch.start();
+ }
+
scheduler->slaveLost(driver, slaveId);
+
+ VLOG(1) << "Scheduler::slaveLost took " << stopwatch.elapsed();
}
void frameworkMessage(const SlaveID& slaveId,
@@ -405,7 +462,14 @@ protected:
VLOG(2) << "Received framework message";
+ Stopwatch stopwatch;
+ if (FLAGS_v >= 1) {
+ stopwatch.start();
+ }
+
scheduler->frameworkMessage(driver, executorId, slaveId, data);
+
+ VLOG(1) << "Scheduler::frameworkMessage took " << stopwatch.elapsed();
}
void error(const string& message)
@@ -419,7 +483,14 @@ protected:
driver->abort();
+ Stopwatch stopwatch;
+ if (FLAGS_v >= 1) {
+ stopwatch.start();
+ }
+
scheduler->error(driver, message);
+
+ VLOG(1) << "Scheduler::error took " << stopwatch.elapsed();
}
void stop(bool failover)