From 156e78e149bb8291cfad47f3e1f7f920855af7b6 Mon Sep 17 00:00:00 2001 From: Tyler Karaszewski Date: Mon, 8 May 2023 11:49:11 -0700 Subject: [PATCH 01/14] Attempt to record tables accessed by command --- BedrockCommand.h | 2 ++ sqlitecluster/SQLite.cpp | 5 +++++ 2 files changed, 7 insertions(+) diff --git a/BedrockCommand.h b/BedrockCommand.h index 293efe6dd..8b9e20da4 100644 --- a/BedrockCommand.h +++ b/BedrockCommand.h @@ -192,6 +192,8 @@ class BedrockCommand : public SQLiteCommand { // This is a timestamp in *microseconds* for when this command should timeout. uint64_t _timeout; + set _tablesUsed; + static atomic _commandCount; static const string defaultPluginName; diff --git a/sqlitecluster/SQLite.cpp b/sqlitecluster/SQLite.cpp index 4e0654201..438b09dc7 100644 --- a/sqlitecluster/SQLite.cpp +++ b/sqlitecluster/SQLite.cpp @@ -854,6 +854,11 @@ int SQLite::_authorize(int actionCode, const char* detail1, const char* detail2, return SQLITE_DENY; } + // Record all tables touched. + if (set{SQLITE_INSERT, SQLITE_DELETE, SQLITE_READ, SQLITE_UPDATE}.count(actionCode)) { + SINFO("Touching " << detail2); + } + // Here's where we can check for non-deterministic functions for the cache. if (actionCode == SQLITE_FUNCTION && detail2) { if (!strcmp(detail2, "random") || From 0d656e4f82ed894cafbb3b0684b3340b084169e8 Mon Sep 17 00:00:00 2001 From: Tyler Karaszewski Date: Mon, 8 May 2023 12:25:21 -0700 Subject: [PATCH 02/14] Log tables used in transactions --- BedrockServer.cpp | 2 ++ sqlitecluster/SQLite.cpp | 7 ++++++- sqlitecluster/SQLite.h | 5 +++++ 3 files changed, 13 insertions(+), 1 deletion(-) diff --git a/BedrockServer.cpp b/BedrockServer.cpp index 9a00388d6..e41484e83 100644 --- a/BedrockServer.cpp +++ b/BedrockServer.cpp @@ -398,6 +398,7 @@ void BedrockServer::sync() if (_syncNode->commitSucceeded()) { if (command) { SINFO("[performance] Sync thread finished committing command " << command->request.methodLine); + SINFO("Tables used: " << SComposeList(db.getTablesUsed())); // Otherwise, save the commit count, mark this command as complete, and reply. command->response["commitCount"] = to_string(db.getCommitCount()); @@ -968,6 +969,7 @@ void BedrockServer::runCommand(unique_ptr&& _command, bool isBlo _syncNode->notifyCommit(); SINFO("Committed leader transaction #" << transactionID << "(" << transactionHash << "). Command: '" << command->request.methodLine << "', blocking: " << (isBlocking ? "true" : "false")); + SINFO("Tables used: " << SComposeList(db.getTablesUsed())); // So we must still be leading, and at this point our commit has succeeded, let's // mark it as complete. We add the currentCommit count here as well. command->response["commitCount"] = to_string(db.getCommitCount()); diff --git a/sqlitecluster/SQLite.cpp b/sqlitecluster/SQLite.cpp index 438b09dc7..f5bce6462 100644 --- a/sqlitecluster/SQLite.cpp +++ b/sqlitecluster/SQLite.cpp @@ -41,6 +41,10 @@ string SQLite::initializeFilename(const string& filename) { } } +const set& SQLite::getTablesUsed() const { + return _tablesUsed; +} + SQLite::SharedData& SQLite::initializeSharedData(sqlite3* db, const string& filename, const vector& journalNames, bool hctree) { static struct SharedDataLookupMapType { map m; @@ -342,6 +346,7 @@ bool SQLite::beginTransaction(TRANSACTION_TYPE type) { // the above `BEGIN CONCURRENT` and the `getCommitCount` call in a lock, which is worse. _dbCountAtStart = getCommitCount(); _queryCache.clear(); + _tablesUsed.clear(); _queryCount = 0; _cacheHits = 0; _beginElapsed = STimeNow() - before; @@ -856,7 +861,7 @@ int SQLite::_authorize(int actionCode, const char* detail1, const char* detail2, // Record all tables touched. if (set{SQLITE_INSERT, SQLITE_DELETE, SQLITE_READ, SQLITE_UPDATE}.count(actionCode)) { - SINFO("Touching " << detail2); + _tablesUsed.insert(detail1); } // Here's where we can check for non-deterministic functions for the cache. diff --git a/sqlitecluster/SQLite.h b/sqlitecluster/SQLite.h index 5b629321a..a0d451e1a 100644 --- a/sqlitecluster/SQLite.h +++ b/sqlitecluster/SQLite.h @@ -122,6 +122,8 @@ class SQLite { void setUpdateNoopMode(bool enabled); bool getUpdateNoopMode() const; + const set& getTablesUsed() const; + // Prepare to commit or rollback the transaction. This also inserts the current uncommitted query into the // journal; no additional writes are allowed until the next transaction has begun. // The transactionID and transactionHash, if passed, will be updated with the values prepared for this transaction. @@ -449,6 +451,9 @@ class SQLite { // write, rollback, or commit. map _queryCache; + // List of table names used during this transaction. + set _tablesUsed; + // Number of queries that have been attempted in this transaction (for metrics only). int64_t _queryCount = 0; From 209ee29aedb954b95ae1c17b4bf87881e20374f7 Mon Sep 17 00:00:00 2001 From: Tyler Karaszewski Date: Mon, 8 May 2023 12:55:49 -0700 Subject: [PATCH 03/14] Add manager --- BedrockServer.cpp | 4 ++-- BedrockServer.h | 3 +++ 2 files changed, 5 insertions(+), 2 deletions(-) diff --git a/BedrockServer.cpp b/BedrockServer.cpp index e41484e83..996333d57 100644 --- a/BedrockServer.cpp +++ b/BedrockServer.cpp @@ -398,7 +398,7 @@ void BedrockServer::sync() if (_syncNode->commitSucceeded()) { if (command) { SINFO("[performance] Sync thread finished committing command " << command->request.methodLine); - SINFO("Tables used: " << SComposeList(db.getTablesUsed())); + _conflictManager.recordTables(command->request.methodLine, db.getTablesUsed()); // Otherwise, save the commit count, mark this command as complete, and reply. command->response["commitCount"] = to_string(db.getCommitCount()); @@ -969,7 +969,7 @@ void BedrockServer::runCommand(unique_ptr&& _command, bool isBlo _syncNode->notifyCommit(); SINFO("Committed leader transaction #" << transactionID << "(" << transactionHash << "). Command: '" << command->request.methodLine << "', blocking: " << (isBlocking ? "true" : "false")); - SINFO("Tables used: " << SComposeList(db.getTablesUsed())); + _conflictManager.recordTables(command->request.methodLine, db.getTablesUsed()); // So we must still be leading, and at this point our commit has succeeded, let's // mark it as complete. We add the currentCommit count here as well. command->response["commitCount"] = to_string(db.getCommitCount()); diff --git a/BedrockServer.h b/BedrockServer.h index 689b29023..838e72aea 100644 --- a/BedrockServer.h +++ b/BedrockServer.h @@ -5,6 +5,7 @@ #include #include "BedrockPlugin.h" #include "BedrockCommandQueue.h" +#include "BedrockConflictManager.h" #include "BedrockTimeoutCommandQueue.h" class SQLitePeer; @@ -259,6 +260,8 @@ class BedrockServer : public SQLiteServer { // Commands that aren't currently being processed are kept here. BedrockCommandQueue _commandQueue; + BedrockConflictManager _conflictManager; + // These are commands that will be processed in a blacking fashion. BedrockCommandQueue _blockingCommandQueue; From 0160bc086dde6ca4bef6cefb8e1248cf71fdaf00 Mon Sep 17 00:00:00 2001 From: Tyler Karaszewski Date: Mon, 8 May 2023 13:09:51 -0700 Subject: [PATCH 04/14] Record table stats --- BedrockConflictManager.cpp | 37 +++++++++++++++++++++++++++++++++++++ BedrockConflictManager.h | 23 +++++++++++++++++++++++ 2 files changed, 60 insertions(+) create mode 100644 BedrockConflictManager.cpp create mode 100644 BedrockConflictManager.h diff --git a/BedrockConflictManager.cpp b/BedrockConflictManager.cpp new file mode 100644 index 000000000..a70c218bd --- /dev/null +++ b/BedrockConflictManager.cpp @@ -0,0 +1,37 @@ +#include "BedrockConflictManager.h" +#include + +BedrockConflictManager::BedrockConflictManager() { +} + +void BedrockConflictManager::recordTables(const string& commandName, const set& tables) { + { + lock_guard lock(m); + auto commandInfo = _commandInfo.find(commandName); + if (commandInfo == _commandInfo.end()) { + commandInfo = _commandInfo.emplace(make_pair(commandName, BedrockConflictManagerCommandInfo())).first; + } + + // Increase the count of the command in general. + commandInfo->second.count++; + + // And for each table (that's not a journal). + for (auto& t : tables) { + // Skip journal. + if (SStartsWith(t, "journal")) { + continue; + } + + // Does this command already have this table? + auto tableInfo = commandInfo->second.tableUseCounts.find(t); + if (tableInfo == commandInfo->second.tableUseCounts.end()) { + tableInfo = commandInfo->second.tableUseCounts.emplace(make_pair(t, 1)).first; + } else { + tableInfo->second++; + } + } + } + + // And increase the count for each used table. + SINFO("Command " << commandName << " used tables: " << SComposeList(tables)); +} diff --git a/BedrockConflictManager.h b/BedrockConflictManager.h new file mode 100644 index 000000000..96acb4040 --- /dev/null +++ b/BedrockConflictManager.h @@ -0,0 +1,23 @@ +#pragma once +#include +#include +#include +#include + +using namespace std; + +class BedrockConflictManagerCommandInfo { + public: + size_t count = 0; + map tableUseCounts; +}; + +class BedrockConflictManager { + public: + BedrockConflictManager(); + void recordTables(const string& commandName, const set& tables); + + private: + mutex m; + map _commandInfo; +}; From d04771c1a257728cb806fa030027cac729c1a0fc Mon Sep 17 00:00:00 2001 From: Aldo Canepa Date: Mon, 8 May 2023 13:13:22 -0700 Subject: [PATCH 05/14] Measure time spent in blocking queue --- BedrockBlockingCommandQueue.cpp | 13 +++++++++++++ BedrockBlockingCommandQueue.h | 13 +++++++++++++ BedrockCommand.cpp | 6 +++++- BedrockCommand.h | 1 + BedrockCommandQueue.cpp | 6 ++++++ BedrockCommandQueue.h | 4 ++++ BedrockServer.h | 3 ++- 7 files changed, 44 insertions(+), 2 deletions(-) create mode 100644 BedrockBlockingCommandQueue.cpp create mode 100644 BedrockBlockingCommandQueue.h diff --git a/BedrockBlockingCommandQueue.cpp b/BedrockBlockingCommandQueue.cpp new file mode 100644 index 000000000..e246119bc --- /dev/null +++ b/BedrockBlockingCommandQueue.cpp @@ -0,0 +1,13 @@ +#include + +void BedrockBlockingCommandQueue::startTiming(unique_ptr& command) { + command->startTiming(BedrockCommand::QUEUE_BLOCKING); +} + +void BedrockBlockingCommandQueue::stopTiming(unique_ptr& command) { + command->stopTiming(BedrockCommand::QUEUE_BLOCKING); +} + +BedrockBlockingCommandQueue::BedrockBlockingCommandQueue() : + BedrockCommandQueue(function&)>(startTiming), function&)>(stopTiming)) +{ } diff --git a/BedrockBlockingCommandQueue.h b/BedrockBlockingCommandQueue.h new file mode 100644 index 000000000..64d35c63b --- /dev/null +++ b/BedrockBlockingCommandQueue.h @@ -0,0 +1,13 @@ +#pragma once +#include +#include "BedrockCommandQueue.h" +#include "BedrockCommand.h" + +class BedrockBlockingCommandQueue : public BedrockCommandQueue { + public: + BedrockBlockingCommandQueue(); + + // Functions to start and stop timing on the commands when they're inserted/removed from the queue. + static void startTiming(unique_ptr& command); + static void stopTiming(unique_ptr& command); +}; diff --git a/BedrockCommand.cpp b/BedrockCommand.cpp index cb32af911..740af7c4f 100644 --- a/BedrockCommand.cpp +++ b/BedrockCommand.cpp @@ -126,6 +126,7 @@ void BedrockCommand::finalizeTimingInfo() { uint64_t commitSyncTotal = 0; uint64_t queueWorkerTotal = 0; uint64_t queueSyncTotal = 0; + uint64_t queueBlockingTotal = 0; for (const auto& entry: timingInfo) { if (get<0>(entry) == PEEK) { peekTotal += get<2>(entry) - get<1>(entry); @@ -137,6 +138,8 @@ void BedrockCommand::finalizeTimingInfo() { 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_BLOCKING) { + queueBlockingTotal += get<2>(entry) - get<1>(entry); } else if (get<0>(entry) == QUEUE_SYNC) { queueSyncTotal += get<2>(entry) - get<1>(entry); } @@ -147,7 +150,7 @@ void BedrockCommand::finalizeTimingInfo() { // Time that wasn't accounted for in all the other metrics. uint64_t unaccountedTime = totalTime - (peekTotal + processTotal + commitWorkerTotal + commitSyncTotal + - escalationTimeUS + queueWorkerTotal + queueSyncTotal); + escalationTimeUS + queueWorkerTotal + queueBlockingTotal + queueSyncTotal); // Build a map of the values we care about. map valuePairs = { @@ -210,6 +213,7 @@ void BedrockCommand::finalizeTimingInfo() { << commitSyncTotal/1000 << ", " << queueWorkerTotal/1000 << ", " << queueSyncTotal/1000 << ", " + << queueBlockingTotal/1000 << ", " << totalTime/1000 << ", " << unaccountedTime/1000 << ", " << escalationTimeUS/1000 << ". Upstream: " diff --git a/BedrockCommand.h b/BedrockCommand.h index 293efe6dd..72fd5895d 100644 --- a/BedrockCommand.h +++ b/BedrockCommand.h @@ -22,6 +22,7 @@ class BedrockCommand : public SQLiteCommand { COMMIT_SYNC, QUEUE_WORKER, QUEUE_SYNC, + QUEUE_BLOCKING, }; enum class STAGE { diff --git a/BedrockCommandQueue.cpp b/BedrockCommandQueue.cpp index b29b14622..409bbe2b2 100644 --- a/BedrockCommandQueue.cpp +++ b/BedrockCommandQueue.cpp @@ -12,6 +12,12 @@ BedrockCommandQueue::BedrockCommandQueue() : SScheduledPriorityQueue>(function&)>(startTiming), function&)>(stopTiming)) { } +BedrockCommandQueue::BedrockCommandQueue( + function& item)> startFunction, + function& item)> endFunction +) : SScheduledPriorityQueue>(startFunction, endFunction) +{ } + list BedrockCommandQueue::getRequestMethodLines() { list returnVal; SAUTOLOCK(_queueMutex); diff --git a/BedrockCommandQueue.h b/BedrockCommandQueue.h index d77f49165..59684acc0 100644 --- a/BedrockCommandQueue.h +++ b/BedrockCommandQueue.h @@ -6,6 +6,10 @@ class BedrockCommandQueue : public SScheduledPriorityQueue> { public: BedrockCommandQueue(); + BedrockCommandQueue( + function& item)> startFunction, + function& item)> endFunction + ); // Functions to start and stop timing on the commands when they're inserted/removed from the queue. static void startTiming(unique_ptr& command); diff --git a/BedrockServer.h b/BedrockServer.h index 689b29023..4782d6c2f 100644 --- a/BedrockServer.h +++ b/BedrockServer.h @@ -5,6 +5,7 @@ #include #include "BedrockPlugin.h" #include "BedrockCommandQueue.h" +#include "BedrockBlockingCommandQueue.h" #include "BedrockTimeoutCommandQueue.h" class SQLitePeer; @@ -260,7 +261,7 @@ class BedrockServer : public SQLiteServer { BedrockCommandQueue _commandQueue; // These are commands that will be processed in a blacking fashion. - BedrockCommandQueue _blockingCommandQueue; + BedrockBlockingCommandQueue _blockingCommandQueue; // Each time we read a new request from a client, we give it a unique ID. atomic _requestCount; From fc1b992798966335cb5bddc5d88cc4de9efd32d6 Mon Sep 17 00:00:00 2001 From: Tyler Karaszewski Date: Mon, 8 May 2023 13:16:00 -0700 Subject: [PATCH 06/14] report generation --- BedrockConflictManager.cpp | 22 ++++++++++++++++++++++ BedrockConflictManager.h | 1 + 2 files changed, 23 insertions(+) diff --git a/BedrockConflictManager.cpp b/BedrockConflictManager.cpp index a70c218bd..11ea49c02 100644 --- a/BedrockConflictManager.cpp +++ b/BedrockConflictManager.cpp @@ -35,3 +35,25 @@ void BedrockConflictManager::recordTables(const string& commandName, const set lock(m); + for (auto& p : _commandInfo) { + const string& commandName = p.first; + const BedrockConflictManagerCommandInfo& commandInfo = p.second; + + out << "Command: " << commandName << endl; + out << "Total Count: " << commandInfo.count << endl; + out << "Table usage:" << endl; + for (const auto& t : commandInfo.tableUseCounts) { + const string& tableName = t.first; + const size_t& count = t.second; + out << tableName << ": " << count << endl; + out << endl; + } + } + } + return out.str(); +} diff --git a/BedrockConflictManager.h b/BedrockConflictManager.h index 96acb4040..7131d193c 100644 --- a/BedrockConflictManager.h +++ b/BedrockConflictManager.h @@ -16,6 +16,7 @@ class BedrockConflictManager { public: BedrockConflictManager(); void recordTables(const string& commandName, const set& tables); + string generateReport(); private: mutex m; From f8848b3439efbdaa5d486bfbfc6f53e8efcc8032 Mon Sep 17 00:00:00 2001 From: Tyler Karaszewski Date: Mon, 8 May 2023 13:18:03 -0700 Subject: [PATCH 07/14] Allow getting report --- BedrockServer.cpp | 3 +++ 1 file changed, 3 insertions(+) diff --git a/BedrockServer.cpp b/BedrockServer.cpp index 996333d57..2ba46879e 100644 --- a/BedrockServer.cpp +++ b/BedrockServer.cpp @@ -1690,6 +1690,7 @@ bool BedrockServer::_isControlCommand(const unique_ptr& command) SIEquals(command->request.methodLine, "SuppressCommandPort") || SIEquals(command->request.methodLine, "ClearCommandPort") || SIEquals(command->request.methodLine, "ClearCrashCommands") || + SIEquals(command->request.methodLine, "ConflictReport") || SIEquals(command->request.methodLine, "Detach") || SIEquals(command->request.methodLine, "Attach") || SIEquals(command->request.methodLine, "SetConflictParams") || @@ -1723,6 +1724,8 @@ void BedrockServer::_control(unique_ptr& command) { } else if (SIEquals(command->request.methodLine, "ClearCrashCommands")) { unique_lock lock(_crashCommandMutex); _crashCommands.clear(); + } else if (SIEquals(command->request.methodLine, "ConflictReport")) { + response.content = _conflictManager.generateReport(); } else if (SIEquals(command->request.methodLine, "Detach")) { response.methodLine = "203 DETACHING"; _beginShutdown("Detach", true); From 7369c9dae137499a6b714ea4eb1d1df06a4080d4 Mon Sep 17 00:00:00 2001 From: Tyler Karaszewski Date: Mon, 8 May 2023 13:39:34 -0700 Subject: [PATCH 08/14] Formatting --- BedrockConflictManager.cpp | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) diff --git a/BedrockConflictManager.cpp b/BedrockConflictManager.cpp index 11ea49c02..f1db32bbd 100644 --- a/BedrockConflictManager.cpp +++ b/BedrockConflictManager.cpp @@ -22,6 +22,10 @@ void BedrockConflictManager::recordTables(const string& commandName, const setsecond.tableUseCounts.find(t); if (tableInfo == commandInfo->second.tableUseCounts.end()) { @@ -46,13 +50,13 @@ string BedrockConflictManager::generateReport() { out << "Command: " << commandName << endl; out << "Total Count: " << commandInfo.count << endl; - out << "Table usage:" << endl; + out << "Table usage" << endl; for (const auto& t : commandInfo.tableUseCounts) { const string& tableName = t.first; const size_t& count = t.second; - out << tableName << ": " << count << endl; - out << endl; + out << " " << tableName << ": " << count << endl; } + out << endl; } } return out.str(); From 9d402b6506e8cf08c3ec515b51d454c7cc9e270c Mon Sep 17 00:00:00 2001 From: Aldo Canepa Date: Tue, 9 May 2023 17:09:41 -0700 Subject: [PATCH 09/14] Use forward declaration --- BedrockBlockingCommandQueue.h | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/BedrockBlockingCommandQueue.h b/BedrockBlockingCommandQueue.h index 64d35c63b..ecb72edce 100644 --- a/BedrockBlockingCommandQueue.h +++ b/BedrockBlockingCommandQueue.h @@ -1,7 +1,8 @@ #pragma once #include #include "BedrockCommandQueue.h" -#include "BedrockCommand.h" + +class BedrockCommand; class BedrockBlockingCommandQueue : public BedrockCommandQueue { public: From a37616d096d8f77667f344edfc60ea0b7e84217f Mon Sep 17 00:00:00 2001 From: Tyler Karaszewski Date: Tue, 9 May 2023 17:37:06 -0700 Subject: [PATCH 10/14] Remove one unreliable case from statusHandlingCommandsTest --- .../tests/StatusHandlingCommandsTest.cpp | 44 +++++-------------- 1 file changed, 12 insertions(+), 32 deletions(-) diff --git a/test/clustertest/tests/StatusHandlingCommandsTest.cpp b/test/clustertest/tests/StatusHandlingCommandsTest.cpp index 6ed934a99..43ed95dd0 100644 --- a/test/clustertest/tests/StatusHandlingCommandsTest.cpp +++ b/test/clustertest/tests/StatusHandlingCommandsTest.cpp @@ -3,25 +3,15 @@ struct StatusHandlingCommandsTest : tpunit::TestFixture { StatusHandlingCommandsTest() - : tpunit::TestFixture("StatusHandlingCommands", - BEFORE_CLASS(StatusHandlingCommandsTest::setup), - AFTER_CLASS(StatusHandlingCommandsTest::teardown), - TEST(StatusHandlingCommandsTest::test)) { } - - BedrockClusterTester* tester; - - void setup () { - tester = new BedrockClusterTester(); - } - - void teardown() { - delete tester; - } + : tpunit::TestFixture("StatusHandlingCommands", TEST(StatusHandlingCommandsTest::test)) { } void test() { - vector results(3); - BedrockTester& leader = tester->getTester(0); - BedrockTester& follower = tester->getTester(1); + BedrockClusterTester tester; + BedrockTester& leader = tester.getTester(0); + BedrockTester& follower = tester.getTester(1); + vector results(2); + + leader.stopServer(); thread healthCheckThread([this, &results, &follower](){ SData cmd("GET /status/handlingCommands HTTP/1.1"); @@ -39,30 +29,20 @@ struct StatusHandlingCommandsTest : tpunit::TestFixture { } else if (result == "HTTP/1.1 200 FOLLOWING") { results[1] = result; foundFollower = true; - } else if (result == "HTTP/1.1 200 STANDINGDOWN") { - results[2] = result; - foundStandingdown = true; + + // If we get here, it's not going back to leading/standingdown. + break; } } }); - leader.stopServer(); - - // Execute a slow query while the follower is leading so when the - // leader is brought back up, it will be STANDINGDOWN until it finishes - thread slowQueryThread([this, &follower](){ - SData slow("slowquery"); - slow["timeout"] = "5000"; // 5s - follower.executeWaitVerifyContent(slow, "555 Timeout peeking command"); - }); - + sleep(1); leader.startServer(false); - slowQueryThread.join(); healthCheckThread.join(); ASSERT_EQUAL(results[0], "HTTP/1.1 200 LEADING") ASSERT_EQUAL(results[1], "HTTP/1.1 200 FOLLOWING") - ASSERT_EQUAL(results[2], "HTTP/1.1 200 STANDINGDOWN") + // We don't test STANDINGDOWN because it's unreliable to get it to show up in the status, we can move straight through it too quickly. } } __StatusHandlingCommandsTest; From 78e92e2c289314d6b2703dfb4341e9e199274fde Mon Sep 17 00:00:00 2001 From: Aldo Canepa Date: Thu, 11 May 2023 11:24:33 -0700 Subject: [PATCH 11/14] WIP updated time logs --- BedrockBlockingCommandQueue.h | 1 - BedrockCommand.cpp | 23 +++++++++++++++++++++-- 2 files changed, 21 insertions(+), 3 deletions(-) diff --git a/BedrockBlockingCommandQueue.h b/BedrockBlockingCommandQueue.h index ecb72edce..ba4bab910 100644 --- a/BedrockBlockingCommandQueue.h +++ b/BedrockBlockingCommandQueue.h @@ -1,5 +1,4 @@ #pragma once -#include #include "BedrockCommandQueue.h" class BedrockCommand; diff --git a/BedrockCommand.cpp b/BedrockCommand.cpp index 740af7c4f..8d015c370 100644 --- a/BedrockCommand.cpp +++ b/BedrockCommand.cpp @@ -205,7 +205,7 @@ void BedrockCommand::finalizeTimingInfo() { } } - // Log all this info. + // TODO: I'll remove the next SINFO at the end, I'll keep it while testing logsToStatsd.pl SINFO("command '" << methodName << "' timing info (ms): " << peekTotal/1000 << " (" << peekCount << "), " << processTotal/1000 << " (" << processCount << "), " @@ -213,7 +213,6 @@ void BedrockCommand::finalizeTimingInfo() { << commitSyncTotal/1000 << ", " << queueWorkerTotal/1000 << ", " << queueSyncTotal/1000 << ", " - << queueBlockingTotal/1000 << ", " << totalTime/1000 << ", " << unaccountedTime/1000 << ", " << escalationTimeUS/1000 << ". Upstream: " @@ -223,6 +222,26 @@ void BedrockCommand::finalizeTimingInfo() { << upstreamUnaccountedTime/1000 << "." ); + SINFO("command '" << methodName << "' timing info (ms): " + "peek:" << peekTotal/1000 << " (count:" << peekCount << "), " + "process:" << processTotal/1000 << " (count:" << processCount << "), " + "total:" << totalTime/1000 << ", " + "unaccounted:" << unaccountedTime/1000 << + ". Commit: " + "worker:" << commitWorkerTotal/1000 << ", " + "sync:"<< commitSyncTotal/1000 << + ". Queue: " + "worker:" << queueWorkerTotal/1000 << ", " + "sync:" << queueSyncTotal/1000 << ", " + "blocking:" << queueBlockingTotal/1000 << ", " + "escalation:" << escalationTimeUS/1000 << + ". Upstream: " + "peek:" << upstreamPeekTime/1000 << ", " + "process:"<< upstreamProcessTime/1000 << ", " + "total:" << upstreamTotalTime/1000 << ", " + "unaccounted:" << upstreamUnaccountedTime/1000 << "." + ); + // And here's where we set our own values. for (const auto& p : valuePairs) { if (p.second) { From abfbcc5f66f602b83d76475e3207a40545c92418 Mon Sep 17 00:00:00 2001 From: Aldo Canepa Date: Thu, 11 May 2023 19:37:42 -0700 Subject: [PATCH 12/14] Remove old timing format --- BedrockCommand.cpp | 17 ----------------- 1 file changed, 17 deletions(-) diff --git a/BedrockCommand.cpp b/BedrockCommand.cpp index 8d015c370..79bd2913c 100644 --- a/BedrockCommand.cpp +++ b/BedrockCommand.cpp @@ -205,23 +205,6 @@ void BedrockCommand::finalizeTimingInfo() { } } - // TODO: I'll remove the next SINFO at the end, I'll keep it while testing logsToStatsd.pl - SINFO("command '" << methodName << "' timing info (ms): " - << peekTotal/1000 << " (" << peekCount << "), " - << processTotal/1000 << " (" << processCount << "), " - << commitWorkerTotal/1000 << ", " - << commitSyncTotal/1000 << ", " - << queueWorkerTotal/1000 << ", " - << queueSyncTotal/1000 << ", " - << totalTime/1000 << ", " - << unaccountedTime/1000 << ", " - << escalationTimeUS/1000 << ". Upstream: " - << upstreamPeekTime/1000 << ", " - << upstreamProcessTime/1000 << ", " - << upstreamTotalTime/1000 << ", " - << upstreamUnaccountedTime/1000 << "." - ); - SINFO("command '" << methodName << "' timing info (ms): " "peek:" << peekTotal/1000 << " (count:" << peekCount << "), " "process:" << processTotal/1000 << " (count:" << processCount << "), " From 99633b79393223bb516e526df23038f746722f72 Mon Sep 17 00:00:00 2001 From: Tyler Karaszewski Date: Fri, 12 May 2023 15:06:47 -0700 Subject: [PATCH 13/14] Clearer names --- BedrockConflictManager.cpp | 31 +++++++++++++++++-------------- 1 file changed, 17 insertions(+), 14 deletions(-) diff --git a/BedrockConflictManager.cpp b/BedrockConflictManager.cpp index f1db32bbd..ceb312654 100644 --- a/BedrockConflictManager.cpp +++ b/BedrockConflictManager.cpp @@ -7,31 +7,34 @@ BedrockConflictManager::BedrockConflictManager() { void BedrockConflictManager::recordTables(const string& commandName, const set& tables) { { lock_guard lock(m); - auto commandInfo = _commandInfo.find(commandName); - if (commandInfo == _commandInfo.end()) { - commandInfo = _commandInfo.emplace(make_pair(commandName, BedrockConflictManagerCommandInfo())).first; + auto commandInfoIt = _commandInfo.find(commandName); + if (commandInfoIt == _commandInfo.end()) { + commandInfoIt = _commandInfo.emplace(make_pair(commandName, BedrockConflictManagerCommandInfo())).first; } + BedrockConflictManagerCommandInfo& commandInfo = commandInfoIt->second; // Increase the count of the command in general. - commandInfo->second.count++; + commandInfo.count++; // And for each table (that's not a journal). - for (auto& t : tables) { + for (auto& table : tables) { // Skip journal. - if (SStartsWith(t, "journal")) { + if (SStartsWith(table, "journal")) { continue; } - if (t == "json_each") { + if (table == "json_each") { continue; } // Does this command already have this table? - auto tableInfo = commandInfo->second.tableUseCounts.find(t); - if (tableInfo == commandInfo->second.tableUseCounts.end()) { - tableInfo = commandInfo->second.tableUseCounts.emplace(make_pair(t, 1)).first; + auto tableInfoIt = commandInfo.tableUseCounts.find(table); + if (tableInfoIt == commandInfo.tableUseCounts.end()) { + tableInfoIt = commandInfo.tableUseCounts.emplace(make_pair(table, 1)).first; } else { - tableInfo->second++; + // tableInfoIt is an iterator into a map (tableUseCounts), where the key is the table name and the value is the count of uses for this command. + // Incrementing `second` increases the count. + tableInfoIt->second++; } } } @@ -51,9 +54,9 @@ string BedrockConflictManager::generateReport() { out << "Command: " << commandName << endl; out << "Total Count: " << commandInfo.count << endl; out << "Table usage" << endl; - for (const auto& t : commandInfo.tableUseCounts) { - const string& tableName = t.first; - const size_t& count = t.second; + for (const auto& table : commandInfo.tableUseCounts) { + const string& tableName = table.first; + const size_t& count = table.second; out << " " << tableName << ": " << count << endl; } out << endl; From 1bf8c1e8318cc5c28618bdce8c83dbb953056821 Mon Sep 17 00:00:00 2001 From: Tyler Karaszewski Date: Tue, 16 May 2023 11:32:24 -0700 Subject: [PATCH 14/14] Better comment --- BedrockConflictManager.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/BedrockConflictManager.cpp b/BedrockConflictManager.cpp index ceb312654..fa845b7ef 100644 --- a/BedrockConflictManager.cpp +++ b/BedrockConflictManager.cpp @@ -18,7 +18,7 @@ void BedrockConflictManager::recordTables(const string& commandName, const set