From 0815d448052d7fb8b6cd6217c1a3130e7a87b4d9 Mon Sep 17 00:00:00 2001 From: Tyler Karaszewski Date: Fri, 20 Mar 2020 12:43:58 -0700 Subject: [PATCH 1/7] Builds with basic structure in place --- BedrockServer.cpp | 2 +- sqlitecluster/SQLite.cpp | 30 +++++++++++++++++++++++++++--- sqlitecluster/SQLite.h | 7 ++++++- 3 files changed, 34 insertions(+), 5 deletions(-) diff --git a/BedrockServer.cpp b/BedrockServer.cpp index b7eadbb8f..192b3f74a 100644 --- a/BedrockServer.cpp +++ b/BedrockServer.cpp @@ -684,7 +684,7 @@ void BedrockServer::worker(const SData& args, // Worker 0 is the "blockingCommit" thread. SInitialize(threadId ? "worker" + to_string(threadId) : "blockingCommit"); int64_t mmapSizeGB = args.isSet("-mmapSizeGB") ? stoll(args["-mmapSizeGB"]) : 0; - SQLite db(args["-db"], args.calc("-cacheSize"), false, args.calc("-maxJournalSize"), threadId, threadCount - 1, args["-synchronous"], mmapSizeGB); + SQLite db(args["-db"], args.calc("-cacheSize"), false, args.calc("-maxJournalSize"), threadId, threadCount - 1, args["-synchronous"], mmapSizeGB, args.test("-pageLogging")); BedrockCore core(db, server); // Command to work on. This default command is replaced when we find work to do. diff --git a/sqlitecluster/SQLite.cpp b/sqlitecluster/SQLite.cpp index 3095f0711..dafb3fe76 100644 --- a/sqlitecluster/SQLite.cpp +++ b/sqlitecluster/SQLite.cpp @@ -6,6 +6,9 @@ // Globally shared mutex for locking around commits and creating/destroying instances. recursive_mutex SQLite::_commitLock; +atomic SQLite::_transactionAttemptCount(0); +mutex SQLite::_pageLogMutex; + // Global map for looking up shared data by file when creating new instances. map SQLite::_sharedDataLookupMap; @@ -19,7 +22,7 @@ atomic SQLite::fullCheckpointPageMin(25000); // Approx 100mb (pages are ass atomic SQLite::enableTrace(false); SQLite::SQLite(const string& filename, int cacheSize, bool enableFullCheckpoints, int maxJournalSize, int journalTable, - int maxRequiredJournalTableID, const string& synchronous, int64_t mmapSizeGB) : + int maxRequiredJournalTableID, const string& synchronous, int64_t mmapSizeGB, bool pageLoggingEnabled) : whitelist(nullptr), _maxJournalSize(maxJournalSize), _insideTransaction(false), @@ -38,7 +41,9 @@ SQLite::SQLite(const string& filename, int cacheSize, bool enableFullCheckpoints _queryCount(0), _cacheHits(0), _useCache(false), - _isDeterministicQuery(false) + _isDeterministicQuery(false), + _pageLoggingEnabled(pageLoggingEnabled), + _currentTransactionAttemptCount(-1) { // Perform sanity checks. SASSERT(!filename.empty()); @@ -113,6 +118,11 @@ SQLite::SQLite(const string& filename, int cacheSize, bool enableFullCheckpoints const int DB_WRITE_OPEN_FLAGS = SQLITE_OPEN_READWRITE | SQLITE_OPEN_CREATE | SQLITE_OPEN_NOMUTEX; SASSERT(!sqlite3_open_v2(filename.c_str(), &_db, DB_WRITE_OPEN_FLAGS, NULL)); + // Turn on page logging if specified. + if (_pageLoggingEnabled) { + sqlite3_begin_concurrent_report_enable(_db, 1); + } + // WAL is what allows simultaneous read/writing. SASSERT(!SQuery(_db, "enabling write ahead logging", "PRAGMA journal_mode = WAL;")); @@ -431,6 +441,7 @@ bool SQLite::beginConcurrentTransaction(bool useCache, const string& transaction _sharedData->blockNewTransactionsCV.notify_one(); SDEBUG("[concurrent] Beginning transaction"); uint64_t before = STimeNow(); + _currentTransactionAttemptCount = -1; _insideTransaction = !SQuery(_db, "starting db transaction", "BEGIN CONCURRENT"); _queryCache.clear(); _transactionName = transactionName; @@ -716,7 +727,15 @@ int SQLite::commit() { uint64_t before = STimeNow(); uint64_t beforeCommit = STimeNow(); - result = SQuery(_db, "committing db transaction", "COMMIT"); + if (_pageLoggingEnabled) { + { + lock_guard lock(_pageLogMutex); + _currentTransactionAttemptCount = _transactionAttemptCount.fetch_add(1); + result = SQuery(_db, "committing db transaction", "COMMIT"); + } + } else { + result = SQuery(_db, "committing db transaction", "COMMIT"); + } SINFO("SQuery 'COMMIT' took " << ((STimeNow() - beforeCommit)/1000) << "ms."); // And record pages after the commit. @@ -735,6 +754,7 @@ int SQLite::commit() { // If there were conflicting commits, will return SQLITE_BUSY_SNAPSHOT SASSERT(result == SQLITE_OK || result == SQLITE_BUSY_SNAPSHOT); if (result == SQLITE_OK) { + SINFO("Successful commit logging here."); _commitElapsed += STimeNow() - before; _journalSize = newJournalSize; _sharedData->_commitCount++; @@ -807,6 +827,10 @@ void SQLite::rollback() { _rollbackElapsed += STimeNow() - before; } + if (_currentTransactionAttemptCount != -1) { + SINFO("Page logging goes here."); + } + // Finally done with this. _insideTransaction = false; _uncommittedHash.clear(); diff --git a/sqlitecluster/SQLite.h b/sqlitecluster/SQLite.h index 280d6f6a8..f05ae0735 100644 --- a/sqlitecluster/SQLite.h +++ b/sqlitecluster/SQLite.h @@ -38,7 +38,7 @@ class SQLite { // // mmapSizeGB: address space to use for memory-mapped IO, in GB. SQLite(const string& filename, int cacheSize, bool enableFullCheckpoints, int maxJournalSize, int journalTable, - int maxRequiredJournalTableID, const string& synchronous = "", int64_t mmapSizeGB = 0); + int maxRequiredJournalTableID, const string& synchronous = "", int64_t mmapSizeGB = 0, bool pageLoggingEnabled = false); ~SQLite(); // Returns the canonicalized filename for this database @@ -426,4 +426,9 @@ class SQLite { // Will be set to false while running a non-deterministic query to prevent it's result being cached. bool _isDeterministicQuery; + + bool _pageLoggingEnabled; + static atomic _transactionAttemptCount; + static mutex _pageLogMutex; + int64_t _currentTransactionAttemptCount; }; From 91452beb5ca4dd96245028cad0252375464c23f3 Mon Sep 17 00:00:00 2001 From: Tyler Karaszewski Date: Fri, 20 Mar 2020 16:04:05 -0700 Subject: [PATCH 2/7] Does logging, not tested yet --- sqlitecluster/SQLite.cpp | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/sqlitecluster/SQLite.cpp b/sqlitecluster/SQLite.cpp index dafb3fe76..017842378 100644 --- a/sqlitecluster/SQLite.cpp +++ b/sqlitecluster/SQLite.cpp @@ -754,7 +754,7 @@ int SQLite::commit() { // If there were conflicting commits, will return SQLITE_BUSY_SNAPSHOT SASSERT(result == SQLITE_OK || result == SQLITE_BUSY_SNAPSHOT); if (result == SQLITE_OK) { - SINFO("Successful commit logging here."); + SINFO("[row-level-locking] transaction attempt: " << _currentTransactionAttemptCount << " committed. report: " << sqlite3_begin_concurrent_report(_db)); _commitElapsed += STimeNow() - before; _journalSize = newJournalSize; _sharedData->_commitCount++; @@ -828,7 +828,8 @@ void SQLite::rollback() { } if (_currentTransactionAttemptCount != -1) { - SINFO("Page logging goes here."); + SINFO("[row-level-locking] transaction attempt: " << _currentTransactionAttemptCount << " rolled back. report: " << sqlite3_begin_concurrent_report(_db)); + } // Finally done with this. From 2c74be76efe516c99bbbc77fe4737ed02031b8ac Mon Sep 17 00:00:00 2001 From: Tyler Karaszewski Date: Fri, 20 Mar 2020 16:34:45 -0700 Subject: [PATCH 3/7] Don't log non-concurrent commits --- sqlitecluster/SQLite.cpp | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/sqlitecluster/SQLite.cpp b/sqlitecluster/SQLite.cpp index 017842378..eaf77d79a 100644 --- a/sqlitecluster/SQLite.cpp +++ b/sqlitecluster/SQLite.cpp @@ -754,7 +754,9 @@ int SQLite::commit() { // If there were conflicting commits, will return SQLITE_BUSY_SNAPSHOT SASSERT(result == SQLITE_OK || result == SQLITE_BUSY_SNAPSHOT); if (result == SQLITE_OK) { - SINFO("[row-level-locking] transaction attempt: " << _currentTransactionAttemptCount << " committed. report: " << sqlite3_begin_concurrent_report(_db)); + if (_currentTransactionAttemptCount != -1) { + SINFO("[row-level-locking] transaction attempt: " << _currentTransactionAttemptCount << " committed. report: " << sqlite3_begin_concurrent_report(_db)); + } _commitElapsed += STimeNow() - before; _journalSize = newJournalSize; _sharedData->_commitCount++; @@ -779,6 +781,7 @@ int SQLite::commit() { _queryCount = 0; _cacheHits = 0; } else { + SINFO("[row-level-locking] transaction attempt: " << _currentTransactionAttemptCount << " conflict, will roll back."); SINFO("Commit failed, waiting for rollback."); } From f45fe940be8bffdb86f9a75a80d59c49afdafdab Mon Sep 17 00:00:00 2001 From: Tyler Karaszewski Date: Tue, 31 Mar 2020 13:16:33 -0700 Subject: [PATCH 4/7] Remove blank line. --- sqlitecluster/SQLite.cpp | 1 - 1 file changed, 1 deletion(-) diff --git a/sqlitecluster/SQLite.cpp b/sqlitecluster/SQLite.cpp index 2e471904c..5c3271bca 100644 --- a/sqlitecluster/SQLite.cpp +++ b/sqlitecluster/SQLite.cpp @@ -857,7 +857,6 @@ void SQLite::rollback() { if (_currentTransactionAttemptCount != -1) { SINFO("[row-level-locking] transaction attempt: " << _currentTransactionAttemptCount << " rolled back. report: " << sqlite3_begin_concurrent_report(_db)); - } // Finally done with this. From 4c089b000f4c8f01bda42448a4df9ffeff5ab4ef Mon Sep 17 00:00:00 2001 From: Tyler Karaszewski Date: Tue, 31 Mar 2020 14:17:00 -0700 Subject: [PATCH 5/7] Use syslog directly for debug logging --- sqlitecluster/SQLite.cpp | 18 ++++++++++++++---- 1 file changed, 14 insertions(+), 4 deletions(-) diff --git a/sqlitecluster/SQLite.cpp b/sqlitecluster/SQLite.cpp index 5c3271bca..7ba1fb20f 100644 --- a/sqlitecluster/SQLite.cpp +++ b/sqlitecluster/SQLite.cpp @@ -780,7 +780,10 @@ int SQLite::commit() { SASSERT(result == SQLITE_OK || result == SQLITE_BUSY_SNAPSHOT); if (result == SQLITE_OK) { if (_currentTransactionAttemptCount != -1) { - SINFO("[row-level-locking] transaction attempt: " << _currentTransactionAttemptCount << " committed. report: " << sqlite3_begin_concurrent_report(_db)); + string logLine = SWHEREAMI + "[row-level-locking] transaction attempt:" + + to_string(_currentTransactionAttemptCount) + " committed. report: " + + sqlite3_begin_concurrent_report(_db); + syslog(LOG_DEBUG, "%s", logLine.c_str()); } _commitElapsed += STimeNow() - before; _journalSize = newJournalSize; @@ -806,8 +809,12 @@ int SQLite::commit() { _queryCount = 0; _cacheHits = 0; } else { - SINFO("[row-level-locking] transaction attempt: " << _currentTransactionAttemptCount << " conflict, will roll back."); - SINFO("Commit failed, waiting for rollback."); + if (_currentTransactionAttemptCount != -1) { + string logLine = SWHEREAMI + "[row-level-locking] transaction attempt:" + + to_string(_currentTransactionAttemptCount) + " conflict, will roll back."; + syslog(LOG_DEBUG, "%s", logLine.c_str()); + SINFO("Commit failed, waiting for rollback."); + } } // if we got SQLITE_BUSY_SNAPSHOT, then we're *still* holding commitLock, and it will need to be unlocked by @@ -856,7 +863,10 @@ void SQLite::rollback() { } if (_currentTransactionAttemptCount != -1) { - SINFO("[row-level-locking] transaction attempt: " << _currentTransactionAttemptCount << " rolled back. report: " << sqlite3_begin_concurrent_report(_db)); + string logLine = SWHEREAMI + "[row-level-locking] transaction attempt:" + + to_string(_currentTransactionAttemptCount) + " rolled back. report: " + + sqlite3_begin_concurrent_report(_db); + syslog(LOG_DEBUG, "%s", logLine.c_str()); } // Finally done with this. From 6300c44f6674d1ea34ab8756d2f31f4485f263c3 Mon Sep 17 00:00:00 2001 From: Rafe Colton Date: Thu, 16 Apr 2020 17:30:04 -0700 Subject: [PATCH 6/7] Do GitHub Pre-Releases on tagged builds --- .travis.yml | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/.travis.yml b/.travis.yml index 3a4477f48..44a8a20ad 100644 --- a/.travis.yml +++ b/.travis.yml @@ -14,3 +14,14 @@ notifications: before_install: script: ./travis.sh dist: xenial +deploy: + provider: releases + # `api_key` is an encrypted oauth token for rafecolton. See https://docs.travis-ci.com/user/deployment/releases + api_key: + secure: jW0XqsVQ7TH3qtgPoDIV6YbcH0RITL/oAnCNXhUHnlr2f4vstIN7Izpef4MTrGFf6QszlEYmSVKGtpNbpiH+KpVqc8UTW1oGjh5b3FHShGvLggwe1GtApVyN21tW9jsScTNjs3nu2kXjPSz9UfLSNi/seRhSH8+TqStG3B31ItyJQmhs4YOX+uCKQLHxCjQMeAUz7BHhvWWfmd80gmjioX9D8hXfKIPTVDgBRlC0asnSXuILicM6TSFDDhtCIvKHnH7MIF/M+0J76OYPIeSK6KkYjCDMO1Ik9E6V7eDWCFIDq5zKarOuMktOKZ9KzMEDWKK+3zxVg4VjMyHTPDJeKaDzRRcyx2Dlk1fSX3gRJfcrbTeg3lrBwdlLbYMNo3Y2sJYhIp0sn4ZTDTSmrD25qVIg3pRaXj1PSZju5PU8SZN8b1xFyPFJJPhADSuD2gQTU88hBFA12d1/2UElStDt3UnyQlTZSmm8DeJ3HtDuQ3W2e4E64fzeXDW85SxBx3ecdSL5J0gBhQIcoHg6FuxTmXOOB71nTYmJb8OVZzVlFYiWIkIm0FlPTY8QGqUXhbScp4D/mLqTWlnllLsTcVKCe8lwzRBpFMkfbLWQy4EAvqjpAAmcWxHfTH39ORrO/J5ipZX+LQAAPwF8qDoedBYsZhUf4Duj1c/U++PNbF3mDM4= + file: + - bedrock + skip_cleanup: true + prerelease: true + on: + tags: true From 919d4875a57ec6d066388e2f5b9636a61b192946 Mon Sep 17 00:00:00 2001 From: Tyler Karaszewski Date: Mon, 20 Apr 2020 12:28:02 -0700 Subject: [PATCH 7/7] Log in sync thread, too --- BedrockServer.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/BedrockServer.cpp b/BedrockServer.cpp index e05563698..42203c0ff 100644 --- a/BedrockServer.cpp +++ b/BedrockServer.cpp @@ -163,7 +163,7 @@ void BedrockServer::sync(const SData& args, // Initialize the DB. int64_t mmapSizeGB = args.isSet("-mmapSizeGB") ? stoll(args["-mmapSizeGB"]) : 0; - SQLite db(args["-db"], args.calc("-cacheSize"), true, args.calc("-maxJournalSize"), -1, workerThreads - 1, args["-synchronous"], mmapSizeGB); + SQLite db(args["-db"], args.calc("-cacheSize"), true, args.calc("-maxJournalSize"), -1, workerThreads - 1, args["-synchronous"], mmapSizeGB, args.test("-pageLogging")); // And the command processor. BedrockCore core(db, server);