Make recovery.py report time without failure detection.

Even though failure detection time is more deterministic
now, it is easier to compare changes to the recovery
routines if the times are separated in the report.

This means all recovery trends now record recovery time
not including the time for failure detection.

Author: rstutsman

scripts/recoverymetrics.py

@@ -375,9 +375,13 @@ def parseRecovery(recovery_dir):
 
     data.client = AttrDict()
     for line in open(glob('%s/client*.*.log' % recovery_dir)[0]):
-        m = re.search(r'\bRecovery completed in (\d+) ns\b', line)
+        m = re.search(
+            r'\bRecovery completed in (\d+) ns, failure detected in (\d+) ns\b',
+            line)
         if m:
-            data.client.recoveryNs = int(m.group(1))
+            failureDetectionNs = int(m.group(2))
+            data.client.recoveryNs = int(m.group(1)) - failureDetectionNs
+            data.client.failureDetectionNs = failureDetectionNs
     return data
 
 def rawSample(data):
@@ -408,6 +412,7 @@ def makeReport(data):
     servers = data.servers
 
     recoveryTime = data.client.recoveryNs / 1e9
+    failureDetectionTime = data.client.failureDetectionNs / 1e9
     report = Report()
 
     # TODO(ongaro): Size distributions of filtered segments
@@ -436,6 +441,9 @@ def on_backups(fun, fail=0):
 
     summary = report.add(Section('Summary'))
     summary.line('Recovery time', recoveryTime, 's')
+    summary.line('Failure detection time', failureDetectionTime, 's')
+    summary.line('Recovery + detection time',
+                 recoveryTime + failureDetectionTime, 's')
     summary.line('Masters', len(masters))
     summary.line('Backups', len(backups))
     summary.line('Total nodes', data.totalNodes)

src/CoordinatorService.cc

@@ -364,7 +364,7 @@ CoordinatorService::hintServerDown(const HintServerDownRpc::Request& reqHdr,
         return;
     }
 
-    LOG(NOTICE, "Server failure detected: id %lu (\"%s\")",
+    LOG(NOTICE, "Verified host failure, removing from cluster: id %lu (\"%s\")",
         *serverId, serviceLocator.c_str());
 
     /*

src/ServerMetrics.cc

@@ -39,10 +39,25 @@ ServerMetrics::ServerMetrics() : metrics()
 void
 ServerMetrics::load(Buffer& buffer)
 {
-    ProtoBuf::MetricList list;
     uint32_t bufferLength = buffer.getTotalLength();
     string s(static_cast<const char*>(buffer.getRange(0, bufferLength)),
                 bufferLength);
+    load(s);
+}
+
+/**
+ * Incorporate a server's metrics data into this object.  Existing
+ * entries are not deleted, but may be overridden by new data.
+ *
+ * \param s
+ *      Contains metrics data formatted as a binary string using Protocol
+ *      Buffers in the form of a MetricList, such as the result of a
+ *      GET_METRICS RPC.
+ */
+void
+ServerMetrics::load(const string& s)
+{
+    ProtoBuf::MetricList list;
     if (!list.ParseFromString(s)) {
         throw FormatError(HERE);
     }

src/ServerMetrics.h

@@ -36,6 +36,7 @@ class ServerMetrics {
     ServerMetrics();
     ~ServerMetrics();
     void load(Buffer& buffer);
+    void load(const string& s);
     ServerMetrics difference(ServerMetrics& other);
 
     // The following methods all delegate directly to the corresponding