Merge remote-tracking branch 'upstream/master'

Author: Crazee

BedrockCommand.cpp

@@ -6,7 +6,8 @@ BedrockCommand::BedrockCommand() :
     httpsRequest(nullptr),
     priority(PRIORITY_NORMAL),
     peekCount(0),
-    processCount(0)
+    processCount(0),
+    _inProgressTiming(INVALID, 0, 0)
 { }
 
 BedrockCommand::~BedrockCommand() {
@@ -21,7 +22,8 @@ BedrockCommand::BedrockCommand(SQLiteCommand&& from) :
     httpsRequest(nullptr),
     priority(PRIORITY_NORMAL),
     peekCount(0),
-    processCount(0)
+    processCount(0),
+    _inProgressTiming(INVALID, 0, 0)
 {
     _init();
 }
@@ -32,7 +34,8 @@ BedrockCommand::BedrockCommand(BedrockCommand&& from) :
     priority(from.priority),
     peekCount(from.peekCount),
     processCount(from.processCount),
-    timingInfo(from.timingInfo)
+    timingInfo(from.timingInfo),
+    _inProgressTiming(from._inProgressTiming)
 {
     // The move constructor (and likewise, the move assignment operator), don't simply copy this pointer value, but
     // they clear it from the old object, so that when its destructor is called, the HTTPS transaction isn't closed.
@@ -44,7 +47,8 @@ BedrockCommand::BedrockCommand(SData&& _request) :
     httpsRequest(nullptr),
     priority(PRIORITY_NORMAL),
     peekCount(0),
-    processCount(0)
+    processCount(0),
+    _inProgressTiming(INVALID, 0, 0)
 {
     _init();
 }
@@ -54,7 +58,8 @@ BedrockCommand::BedrockCommand(SData _request) :
     httpsRequest(nullptr),
     priority(PRIORITY_NORMAL),
     peekCount(0),
-    processCount(0)
+    processCount(0),
+    _inProgressTiming(INVALID, 0, 0)
 {
     _init();
 }
@@ -74,6 +79,7 @@ BedrockCommand& BedrockCommand::operator=(BedrockCommand&& from) {
         processCount = from.processCount;
         priority = from.priority;
         timingInfo = from.timingInfo;
+        _inProgressTiming = from._inProgressTiming;
 
         // And call the base class's move constructor as well.
         SQLiteCommand::operator=(move(from));
@@ -104,22 +110,81 @@ void BedrockCommand::_init() {
     }
 }
 
+void BedrockCommand::startTiming(TIMING_INFO type) {
+    if (get<0>(_inProgressTiming) != INVALID ||
+        get<1>(_inProgressTiming) != 0
+       ) {
+        SWARN("Starting timing, but looks like it was already running.");
+    }
+    get<0>(_inProgressTiming) = type;
+    get<1>(_inProgressTiming) = STimeNow();
+    get<2>(_inProgressTiming) = 0;
+}
+
+void BedrockCommand::stopTiming(TIMING_INFO type) {
+    if (get<0>(_inProgressTiming) != type ||
+        get<1>(_inProgressTiming) == 0
+       ) {
+        SWARN("Stopping timing, but looks like it wasn't already running.");
+    }
+
+    // Add it to the list of timing info.
+    get<2>(_inProgressTiming) = STimeNow();
+    timingInfo.push_back(_inProgressTiming);
+
+    // And reset it for next use.
+    get<0>(_inProgressTiming) = INVALID;
+    get<1>(_inProgressTiming) = 0;
+    get<2>(_inProgressTiming) = 0;
+}
+
 void BedrockCommand::finalizeTimingInfo() {
     uint64_t peekTotal = 0;
     uint64_t processTotal = 0;
+    uint64_t commitWorkerTotal = 0;
+    uint64_t commitSyncTotal = 0;
+    uint64_t queueWorkerTotal = 0;
+    uint64_t queueSyncTotal = 0;
     for (const auto& entry: timingInfo) {
         if (get<0>(entry) == PEEK) {
             peekTotal += get<2>(entry) - get<1>(entry);
         } else if (get<0>(entry) == PROCESS) {
             processTotal += get<2>(entry) - get<1>(entry);
+        } else if (get<0>(entry) == COMMIT_WORKER) {
+            commitWorkerTotal += get<2>(entry) - get<1>(entry);
+        } else if (get<0>(entry) == COMMIT_SYNC) {
+            commitSyncTotal += get<2>(entry) - get<1>(entry);
+        } else if (get<0>(entry) == QUEUE_WORKER) {
+            queueWorkerTotal += get<2>(entry) - get<1>(entry);
+        } else if (get<0>(entry) == QUEUE_SYNC) {
+            queueSyncTotal += get<2>(entry) - get<1>(entry);
         }
     }
 
+    // The lifespan of the object up until now.
+    uint64_t totalTime = STimeNow() - creationTime;
+
+    // Time that wasn't accounted for in all the other metrics.
+    uint64_t unaccountedTime = totalTime - (peekTotal + processTotal + commitWorkerTotal + commitSyncTotal +
+                                            queueWorkerTotal + queueSyncTotal);
+
+    // Log all this info.
+    SINFO("command '" << request.methodLine << "' timing info (us): "
+          << peekTotal << " (" << peekCount << "), "
+          << processTotal << " (" << processCount << "), "
+          << commitWorkerTotal << ", "
+          << commitSyncTotal << ", "
+          << queueWorkerTotal << ", "
+          << queueSyncTotal << ", "
+          << totalTime << ", "
+          << unaccountedTime << "."
+    );
+
     // Build a map of the values we care about.
     map<string, uint64_t> valuePairs = {
         {"peekTime",       peekTotal},
         {"processTime",    processTotal},
-        {"totalTime",      STimeNow() - creationTime},
+        {"totalTime",      totalTime},
         {"escalationTime", escalationTimeUS},
     };
 
@@ -142,3 +207,28 @@ void BedrockCommand::finalizeTimingInfo() {
         }
     }
 }
+
+// pop and push specializations for SSynchronizedQueue that record timing info.
+template<>
+BedrockCommand SSynchronizedQueue<BedrockCommand>::pop() {
+    SAUTOLOCK(_queueMutex);
+    if (!_queue.empty()) {
+        BedrockCommand item = move(_queue.front());
+        _queue.pop_front();
+        item.stopTiming(BedrockCommand::QUEUE_SYNC);
+        return item;
+    }
+    throw out_of_range("No commands");
+}
+
+template<>
+void SSynchronizedQueue<BedrockCommand>::push(BedrockCommand&& rhs) {
+    SAUTOLOCK(_queueMutex);
+    // Just add to the queue
+    _queue.push_back(move(rhs));
+    _queue.back().startTiming(BedrockCommand::QUEUE_SYNC);
+
+    // Write arbitrary buffer to the pipe so any subscribers will be awoken.
+    // **NOTE: 1 byte so write is atomic.
+    SASSERT(write(_pipeFD[1], "A", 1));
+}

BedrockCommand.h

@@ -12,8 +12,13 @@ class BedrockCommand : public SQLiteCommand {
     };
 
     enum TIMING_INFO {
+        INVALID,
         PEEK,
         PROCESS,
+        COMMIT_WORKER,
+        COMMIT_SYNC,
+        QUEUE_WORKER,
+        QUEUE_SYNC,
     };
 
     // Constructor to make an empty object.
@@ -37,6 +42,13 @@ class BedrockCommand : public SQLiteCommand {
     // Move assignment operator.
     BedrockCommand& operator=(BedrockCommand&& from);
 
+    // Start recording time for a given action type.
+    void startTiming(TIMING_INFO type);
+
+    // Finish recording time for a given action type. `type` must match what was passed to the most recent call to
+    // `startTiming`.
+    void stopTiming(TIMING_INFO type);
+
     // Add a summary of our timing info to our response object.
     void finalizeTimingInfo();
 
@@ -56,4 +68,7 @@ class BedrockCommand : public SQLiteCommand {
   private:
     // Set certain initial state on construction. Common functionality to several constructors.
     void _init();
+
+    // used as a temporary variable for startTiming and stopTiming.
+    tuple<TIMING_INFO, uint64_t, uint64_t> _inProgressTiming;
 };

BedrockCommandQueue.cpp

@@ -88,6 +88,7 @@ list<string> BedrockCommandQueue::getRequestMethodLines() {
 void BedrockCommandQueue::push(BedrockCommand&& item) {
     SAUTOLOCK(_queueMutex);
     auto& queue = _commandQueue[item.priority];
+    item.startTiming(BedrockCommand::QUEUE_WORKER);
     queue.emplace(item.request.calcU64("commandExecuteTime"), move(item));
     _queueCondition.notify_one();
 }
@@ -136,6 +137,7 @@ BedrockCommand BedrockCommandQueue::_dequeue() {
             }
 
             // Done!
+            command.stopTiming(BedrockCommand::QUEUE_WORKER);
             return command;
         }
     }

BedrockCore.h

@@ -7,6 +7,20 @@ class BedrockCore : public SQLiteCore {
   public:
     BedrockCore(SQLite& db, const BedrockServer& server);
 
+    // Automatic timing class that records an entry corresponding to its lifespan.
+    class AutoTimer {
+      public:
+        AutoTimer(BedrockCommand& command, BedrockCommand::TIMING_INFO type) :
+        _command(command), _type(type), _start(STimeNow()) { }
+        ~AutoTimer() {
+            _command.timingInfo.emplace_back(make_tuple(_type, _start, STimeNow()));
+        }
+      private:
+        BedrockCommand& _command;
+        BedrockCommand::TIMING_INFO _type;
+        uint64_t _start;
+    };
+
     // Peek lets you pre-process a command. It will be called on each command before `process` is called on the same
     // command, and it *may be called multiple times*. Preventing duplicate actions on calling peek multiple times is
     // up to the implementer, and may happen *across multiple servers*. I.e., a slave server may call `peek`, and on
@@ -29,20 +43,6 @@ class BedrockCore : public SQLiteCore {
     bool processCommand(BedrockCommand& command);
 
   private:
-
-    // Automatic timing class that records an entry corresponding to its lifespan.
-    class AutoTimer {
-      public:
-        AutoTimer(BedrockCommand& command, BedrockCommand::TIMING_INFO type) :
-        _command(command), _type(type), _start(STimeNow()) { }
-        ~AutoTimer() {
-            _command.timingInfo.emplace_back(make_tuple(_type, _start, STimeNow()));
-        }
-      private:
-        BedrockCommand& _command;
-        BedrockCommand::TIMING_INFO _type;
-        uint64_t _start;
-    };
     void _handleCommandException(BedrockCommand& command, const string& e, bool wasProcessing);
     const BedrockServer& _server;
 };

BedrockServer.cpp

@@ -210,6 +210,9 @@ void BedrockServer::sync(SData& args,
             // It should be impossible to get here if we're not mastering or standing down.
             SASSERT(nodeState == SQLiteNode::MASTERING || nodeState == SQLiteNode::STANDINGDOWN);
 
+            // Record the time spent.
+            command.stopTiming(BedrockCommand::COMMIT_SYNC);
+
             // We're done with the commit, we unlock our mutex and decrement our counter.
             server._syncThreadCommitMutex.unlock();
             committingCommand = false;
@@ -324,6 +327,8 @@ void BedrockServer::sync(SData& args,
                     committingCommand = true;
                     SINFO("[performance] Sync thread beginning committing command " << command.request.methodLine);
                     server._writableCommandsInProgress++;
+                    // START TIMING.
+                    command.startTiming(BedrockCommand::COMMIT_SYNC);
                     syncNode.startCommit(command.writeConsistency);
 
                     // And we'll start the next main loop.
@@ -566,7 +571,13 @@ void BedrockServer::worker(SData& args,
                                       << " during worker commit. Rolling back transaction!");
                                 core.rollback();
                             } else {
-                                if (core.commit()) {
+                                bool commitSuccess;
+                                {
+                                    // Scoped for auto-timer.
+                                    BedrockCore::AutoTimer(command, BedrockCommand::COMMIT_WORKER);
+                                    commitSuccess = core.commit();
+                                }
+                                if (commitSuccess) {
                                     BedrockConflictMetrics::recordSuccess(command.request.methodLine);
                                     SINFO("Successfully committed " << command.request.methodLine << " on worker thread.");
                                     // So we must still be mastering, and at this point our commit has succeeded, let's

Makefile

@@ -94,20 +94,14 @@ STUFFC = $(shell find libstuff -name '*.c')
 STUFFOBJ = $(STUFFCPP:%.cpp=$(INTERMEDIATEDIR)/%.o) $(STUFFC:%.c=$(INTERMEDIATEDIR)/%.o)
 STUFFDEP = $(STUFFCPP:%.cpp=$(INTERMEDIATEDIR)/%.d)
 
-$(info $$STUFFCPP is [${STUFFCPP}])
-
 LIBBEDROCKCPP = $(shell find * -name '*.cpp' -not -name main.cpp -not -path 'test*' -not -path 'libstuff*')
 LIBBEDROCKOBJ = $(LIBBEDROCKCPP:%.cpp=$(INTERMEDIATEDIR)/%.o)
 LIBBEDROCKDEP = $(LIBBEDROCKCPP:%.cpp=$(INTERMEDIATEDIR)/%.d)
 
-$(info $$LIBBEDROCKCPP is [${LIBBEDROCKCPP}])
-
 BEDROCKCPP = main.cpp
 BEDROCKOBJ = $(BEDROCKCPP:%.cpp=$(INTERMEDIATEDIR)/%.o)
 BEDROCKDEP = $(BEDROCKCPP:%.cpp=$(INTERMEDIATEDIR)/%.d)
 
-$(info $$BEDROCKCPP is [${BEDROCKCPP}])
-
 TESTCPP = $(shell find test -name '*.cpp' -not -path 'test/clustertest*')
 TESTOBJ = $(TESTCPP:%.cpp=$(INTERMEDIATEDIR)/%.o)
 TESTDEP = $(TESTCPP:%.cpp=$(INTERMEDIATEDIR)/%.d)

libstuff/libstuff.h

@@ -815,11 +815,11 @@ struct STestTimer {
 #include "STCPServer.h"
 #include "STCPNode.h"
 #include "SHTTPSManager.h"
-#include "SSynchronizedQueue.h"
 
 // Other libstuff headers.
 #include "SRandom.h"
 #include "SPerformanceTimer.h"
 #include "SLockTimer.h"
+#include "SSynchronizedQueue.h"
 
 #endif	// LIBSTUFF_H