From c971a0157c6c5d489ae219af576d6303ef99a68a Mon Sep 17 00:00:00 2001 From: Justin Persaud Date: Wed, 2 Oct 2024 13:24:25 -0400 Subject: [PATCH 01/26] Log new thread process IDs --- libstuff/libstuff.cpp | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/libstuff/libstuff.cpp b/libstuff/libstuff.cpp index 6b9e2bf59..49ae4980a 100644 --- a/libstuff/libstuff.cpp +++ b/libstuff/libstuff.cpp @@ -5,6 +5,7 @@ #include #include #include +#include #include #include #include @@ -129,6 +130,10 @@ void SInitialize(string threadName, const char* processName) { SLogSetThreadName(threadName); SLogSetThreadPrefix("xxxxxx "); SInitializeSignals(); + + // Get the native OS thread process ID and log it + pid_t tid = syscall(SYS_gettid); + SINFO("Initializing new thread with PID: " << tid); } // Thread-local log prefix @@ -3200,4 +3205,3 @@ SString& SString::operator=(const bool from) { string::operator=(from ? "true" : "false"); return *this; } - From 30165d4eeba989598663e06c91e92e755dc627d2 Mon Sep 17 00:00:00 2001 From: danieldoglas Date: Wed, 2 Oct 2024 20:35:44 +0000 Subject: [PATCH 02/26] adding getCPUUserTime for libstuff --- libstuff/libstuff.cpp | 8 ++++++++ libstuff/libstuff.h | 2 ++ 2 files changed, 10 insertions(+) diff --git a/libstuff/libstuff.cpp b/libstuff/libstuff.cpp index 49ae4980a..874c2bd91 100644 --- a/libstuff/libstuff.cpp +++ b/libstuff/libstuff.cpp @@ -4,6 +4,7 @@ // C library #include #include +#include #include #include #include @@ -3205,3 +3206,10 @@ SString& SString::operator=(const bool from) { string::operator=(from ? "true" : "false"); return *this; } + +double SGetCPUUserTime() { + struct rusage usage; + getrusage(RUSAGE_THREAD, &usage); + // Returns the current threads CPU user time in microseconds + return static_cast(usage.ru_utime.tv_sec) * 1e6 + static_cast(usage.ru_utime.tv_usec); +} \ No newline at end of file diff --git a/libstuff/libstuff.h b/libstuff/libstuff.h index e05efd4d6..fb4a55e66 100644 --- a/libstuff/libstuff.h +++ b/libstuff/libstuff.h @@ -629,4 +629,6 @@ string SGUnzip(const string& content); // Command-line helpers STable SParseCommandLine(int argc, char* argv[]); +// Returns the current CPU usage inside the current process +double SGetCPUUserTime(); #endif // LIBSTUFF_H From d926f2db431867eed99724592abae391b5b32bdb Mon Sep 17 00:00:00 2001 From: danieldoglas Date: Wed, 2 Oct 2024 20:37:40 +0000 Subject: [PATCH 03/26] line break --- libstuff/libstuff.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/libstuff/libstuff.cpp b/libstuff/libstuff.cpp index 874c2bd91..b2e190a91 100644 --- a/libstuff/libstuff.cpp +++ b/libstuff/libstuff.cpp @@ -3212,4 +3212,4 @@ double SGetCPUUserTime() { getrusage(RUSAGE_THREAD, &usage); // Returns the current threads CPU user time in microseconds return static_cast(usage.ru_utime.tv_sec) * 1e6 + static_cast(usage.ru_utime.tv_usec); -} \ No newline at end of file +} From a0b0412a3d6f241317a753aaa1ba21cb1648b7e3 Mon Sep 17 00:00:00 2001 From: Daniel Silva Date: Wed, 2 Oct 2024 18:40:01 -0300 Subject: [PATCH 04/26] wip new thread --- libstuff/ResourceMonitorThread.cpp | 18 ++++++++++++++++++ libstuff/ResourceMonitorThread.h | 18 ++++++++++++++++++ 2 files changed, 36 insertions(+) create mode 100644 libstuff/ResourceMonitorThread.cpp create mode 100644 libstuff/ResourceMonitorThread.h diff --git a/libstuff/ResourceMonitorThread.cpp b/libstuff/ResourceMonitorThread.cpp new file mode 100644 index 000000000..5590e3703 --- /dev/null +++ b/libstuff/ResourceMonitorThread.cpp @@ -0,0 +1,18 @@ +#include "ResourceMonitorThread.h" +#include "libstuff/libstuff.h" +#include "format" +#include "thread" + +ResourceMonitorThread::ResourceMonitorThread(_Callable&& __f, _Args&&... __args) : thread(__f, __args) +{ + startTime = STimeNow(); + cpuStartTime = SGetCPUUserTime(); +}; + +ResourceMonitorThread::~ResourceMonitorThread(){ + const uint64_t threadEndTime = STimeNow() - startTime; + const double CPUUserTime = SGetCPUUserTime() - cpuStartTime; + const double cpuUserPercentage = (CPUUserTime / static_cast(threadEndTime)) * 100; + const pid_t tid = syscall(SYS_gettid); + SINFO(format("Thread finished. pID: '{}', CPUTime: '{}µs', CPUPercentage: '{}%' ", tid, cpuUserPercentage, CPUUserTime)); +} \ No newline at end of file diff --git a/libstuff/ResourceMonitorThread.h b/libstuff/ResourceMonitorThread.h new file mode 100644 index 000000000..c9a4c3770 --- /dev/null +++ b/libstuff/ResourceMonitorThread.h @@ -0,0 +1,18 @@ +#include + +using namespace std; + +class ResourceMonitorThread: public thread +{ +public: + template, thread>>>> + explicit + ResourceMonitorThread(_Callable&& __f, _Args&&... __args); + + virtual ~ResourceMonitorThread(); + +private: + uint64_t startTime = 0; + double cpuStartTime = 0; +}; From 659c46a6c2f900d5841fcd779ca00bb945217427 Mon Sep 17 00:00:00 2001 From: danieldoglas Date: Thu, 3 Oct 2024 15:51:17 +0000 Subject: [PATCH 05/26] fixing thread class --- libstuff/ResourceMonitorThread.cpp | 7 ------- libstuff/ResourceMonitorThread.h | 6 +++++- 2 files changed, 5 insertions(+), 8 deletions(-) diff --git a/libstuff/ResourceMonitorThread.cpp b/libstuff/ResourceMonitorThread.cpp index 5590e3703..026d55e30 100644 --- a/libstuff/ResourceMonitorThread.cpp +++ b/libstuff/ResourceMonitorThread.cpp @@ -1,13 +1,6 @@ #include "ResourceMonitorThread.h" #include "libstuff/libstuff.h" #include "format" -#include "thread" - -ResourceMonitorThread::ResourceMonitorThread(_Callable&& __f, _Args&&... __args) : thread(__f, __args) -{ - startTime = STimeNow(); - cpuStartTime = SGetCPUUserTime(); -}; ResourceMonitorThread::~ResourceMonitorThread(){ const uint64_t threadEndTime = STimeNow() - startTime; diff --git a/libstuff/ResourceMonitorThread.h b/libstuff/ResourceMonitorThread.h index c9a4c3770..29887b3e1 100644 --- a/libstuff/ResourceMonitorThread.h +++ b/libstuff/ResourceMonitorThread.h @@ -1,3 +1,4 @@ +#include "libstuff/libstuff.h" #include using namespace std; @@ -8,7 +9,10 @@ class ResourceMonitorThread: public thread template, thread>>>> explicit - ResourceMonitorThread(_Callable&& __f, _Args&&... __args); + ResourceMonitorThread(_Callable&& __f, _Args&&... __args): thread(move(__f), move(__args...)){ + startTime = STimeNow(); + cpuStartTime = SGetCPUUserTime(); + }; virtual ~ResourceMonitorThread(); From cce5c77d260bf0ccea025f0a03019f0816736dce Mon Sep 17 00:00:00 2001 From: danieldoglas Date: Thu, 3 Oct 2024 16:10:02 +0000 Subject: [PATCH 06/26] fixing constructor to use forward instead of move --- libstuff/ResourceMonitorThread.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/libstuff/ResourceMonitorThread.h b/libstuff/ResourceMonitorThread.h index 29887b3e1..0c7f4be71 100644 --- a/libstuff/ResourceMonitorThread.h +++ b/libstuff/ResourceMonitorThread.h @@ -9,7 +9,7 @@ class ResourceMonitorThread: public thread template, thread>>>> explicit - ResourceMonitorThread(_Callable&& __f, _Args&&... __args): thread(move(__f), move(__args...)){ + ResourceMonitorThread(_Callable&& __f, _Args&&... __args): thread(forward<_Callable>(__f), forward<_Args>(__args)...){ startTime = STimeNow(); cpuStartTime = SGetCPUUserTime(); }; From f611c92c3a75622fdbc8d38440aa9bf267bd7ea3 Mon Sep 17 00:00:00 2001 From: danieldoglas Date: Thu, 3 Oct 2024 16:12:35 +0000 Subject: [PATCH 07/26] changing default thread to use the new thread object --- BedrockServer.cpp | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/BedrockServer.cpp b/BedrockServer.cpp index 544d3e5b2..aaa807be2 100644 --- a/BedrockServer.cpp +++ b/BedrockServer.cpp @@ -13,6 +13,7 @@ #include #include #include +#include #include #include @@ -1318,7 +1319,7 @@ BedrockServer::BedrockServer(const SData& args_) // Start the sync thread, which will start the worker threads. SINFO("Launching sync thread '" << _syncThreadName << "'"); - _syncThread = thread(&BedrockServer::syncWrapper, this); + _syncThread = ResourceMonitorThread(&BedrockServer::syncWrapper, this); } BedrockServer::~BedrockServer() { @@ -1867,7 +1868,7 @@ void BedrockServer::_control(unique_ptr& command) { if (__quiesceThread) { response.methodLine = "400 Already Blocked"; } else { - __quiesceThread = new thread([&]() { + __quiesceThread = new ResourceMonitorThread([&]() { shared_ptr dbPoolCopy = _dbPool; if (dbPoolCopy) { SQLiteScopedHandle dbScope(*_dbPool, _dbPool->getIndex()); @@ -2097,7 +2098,7 @@ void BedrockServer::_acceptSockets() { bool threadStarted = false; while (!threadStarted) { try { - t = thread(&BedrockServer::handleSocket, this, move(socket), port == _controlPort, port == _commandPortPublic, port == _commandPortPrivate); + t = ResourceMonitorThread(&BedrockServer::handleSocket, this, move(socket), port == _controlPort, port == _commandPortPublic, port == _commandPortPrivate); threadStarted = true; } catch (const system_error& e) { // We don't care about this lock here from a performance perspective, it only happens when we From 81213822a74cf5eec825b7cb0dbfab409bd3bcf7 Mon Sep 17 00:00:00 2001 From: danieldoglas Date: Thu, 3 Oct 2024 16:12:53 +0000 Subject: [PATCH 08/26] changing the default thread in the cluster to use the resource managed thread --- sqlitecluster/SQLiteNode.cpp | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/sqlitecluster/SQLiteNode.cpp b/sqlitecluster/SQLiteNode.cpp index 2003f57cc..872d6e574 100644 --- a/sqlitecluster/SQLiteNode.cpp +++ b/sqlitecluster/SQLiteNode.cpp @@ -4,6 +4,7 @@ #include #include +#include #include #include #include @@ -1485,7 +1486,7 @@ void SQLiteNode::_onMESSAGE(SQLitePeer* peer, const SData& message) { } else { _pendingSynchronizeResponses++; static atomic synchronizeCount(0); - thread([message, peer, currentSynchronizeCount = synchronizeCount++, this] () { + ResourceMonitorThread([message, peer, currentSynchronizeCount = synchronizeCount++, this] () { SInitialize("synchronize" + to_string(currentSynchronizeCount)); SData response("SYNCHRONIZE_RESPONSE"); SQLiteScopedHandle dbScope(*_dbPool, _dbPool->getIndex()); @@ -1648,7 +1649,7 @@ void SQLiteNode::_onMESSAGE(SQLitePeer* peer, const SData& message) { SDEBUG("Spawning concurrent replicate thread (blocks until DB handle available): " << threadID); try { uint64_t threadAttemptStartTimestamp = STimeNow(); - thread(&SQLiteNode::_replicate, this, peer, message, _dbPool->getIndex(false), threadAttemptStartTimestamp).detach(); + ResourceMonitorThread(&SQLiteNode::_replicate, this, peer, message, _dbPool->getIndex(false), threadAttemptStartTimestamp).detach(); } catch (const system_error& e) { // If the server is strugling and falling behind on replication, we might have too many threads // causing a resource exhaustion. If that happens, all the transactions that are already threaded From c1699d84b369f6b2be27833d7f1c4a1cc9b8f378 Mon Sep 17 00:00:00 2001 From: danieldoglas Date: Thu, 3 Oct 2024 16:14:06 +0000 Subject: [PATCH 09/26] replacing threds in more places --- BedrockServer.cpp | 2 +- sqlitecluster/SQLiteClusterMessenger.cpp | 3 ++- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/BedrockServer.cpp b/BedrockServer.cpp index aaa807be2..51ab5cefd 100644 --- a/BedrockServer.cpp +++ b/BedrockServer.cpp @@ -117,7 +117,7 @@ void BedrockServer::sync() // our worker threads now. We don't wait until the node is `LEADING` or `FOLLOWING`, as it's state can change while // it's running, and our workers will have to maintain awareness of that state anyway. SINFO("Starting " << workerThreads << " worker threads."); - list workerThreadList; + list workerThreadList; for (int threadId = 0; threadId < workerThreads; threadId++) { workerThreadList.emplace_back(&BedrockServer::worker, this, threadId); } diff --git a/sqlitecluster/SQLiteClusterMessenger.cpp b/sqlitecluster/SQLiteClusterMessenger.cpp index 9ad9b6f5a..67777ecbb 100644 --- a/sqlitecluster/SQLiteClusterMessenger.cpp +++ b/sqlitecluster/SQLiteClusterMessenger.cpp @@ -2,6 +2,7 @@ #include #include #include +#include #include #include @@ -69,7 +70,7 @@ SQLiteClusterMessenger::WaitForReadyResult SQLiteClusterMessenger::waitForReady( } vector SQLiteClusterMessenger::runOnAll(const SData& cmd) { - list threads; + list threads; const list peerInfo = _node->getPeerInfo(); vector results(peerInfo.size()); atomic index = 0; From 3882e71c5c35220979216a0fd8b40089c1054025 Mon Sep 17 00:00:00 2001 From: danieldoglas Date: Thu, 3 Oct 2024 16:22:53 +0000 Subject: [PATCH 10/26] removing unused log --- libstuff/ResourceMonitorThread.cpp | 4 ++-- libstuff/libstuff.cpp | 4 ---- 2 files changed, 2 insertions(+), 6 deletions(-) diff --git a/libstuff/ResourceMonitorThread.cpp b/libstuff/ResourceMonitorThread.cpp index 026d55e30..9b1a08672 100644 --- a/libstuff/ResourceMonitorThread.cpp +++ b/libstuff/ResourceMonitorThread.cpp @@ -6,6 +6,6 @@ ResourceMonitorThread::~ResourceMonitorThread(){ const uint64_t threadEndTime = STimeNow() - startTime; const double CPUUserTime = SGetCPUUserTime() - cpuStartTime; const double cpuUserPercentage = (CPUUserTime / static_cast(threadEndTime)) * 100; - const pid_t tid = syscall(SYS_gettid); - SINFO(format("Thread finished. pID: '{}', CPUTime: '{}µs', CPUPercentage: '{}%' ", tid, cpuUserPercentage, CPUUserTime)); + const pid_t tid = syscall(SYS_gettid); + SINFO(format("Thread finished. pID: '{}', CPUTime: '{}µs', CPUPercentage: '{}%' , start: {}, cpu start: {}", tid, CPUUserTime, cpuUserPercentage, startTime, cpuStartTime)); } \ No newline at end of file diff --git a/libstuff/libstuff.cpp b/libstuff/libstuff.cpp index b2e190a91..78ab7bcf5 100644 --- a/libstuff/libstuff.cpp +++ b/libstuff/libstuff.cpp @@ -131,10 +131,6 @@ void SInitialize(string threadName, const char* processName) { SLogSetThreadName(threadName); SLogSetThreadPrefix("xxxxxx "); SInitializeSignals(); - - // Get the native OS thread process ID and log it - pid_t tid = syscall(SYS_gettid); - SINFO("Initializing new thread with PID: " << tid); } // Thread-local log prefix From 645c26e2d90d8519fb2014da726b3cc43362c745 Mon Sep 17 00:00:00 2001 From: danieldoglas Date: Thu, 3 Oct 2024 17:24:08 +0000 Subject: [PATCH 11/26] wip --- libstuff/ResourceMonitorThread.cpp | 10 ++++++++-- libstuff/ResourceMonitorThread.h | 24 ++++++++++++++++-------- 2 files changed, 24 insertions(+), 10 deletions(-) diff --git a/libstuff/ResourceMonitorThread.cpp b/libstuff/ResourceMonitorThread.cpp index 9b1a08672..4e2ff1eab 100644 --- a/libstuff/ResourceMonitorThread.cpp +++ b/libstuff/ResourceMonitorThread.cpp @@ -2,10 +2,16 @@ #include "libstuff/libstuff.h" #include "format" -ResourceMonitorThread::~ResourceMonitorThread(){ + +void ResourceMonitorThread::before(){ + startTime = STimeNow(); + cpuStartTime = SGetCPUUserTime(); +} + +void ResourceMonitorThread::after(){ const uint64_t threadEndTime = STimeNow() - startTime; const double CPUUserTime = SGetCPUUserTime() - cpuStartTime; const double cpuUserPercentage = (CPUUserTime / static_cast(threadEndTime)) * 100; const pid_t tid = syscall(SYS_gettid); SINFO(format("Thread finished. pID: '{}', CPUTime: '{}µs', CPUPercentage: '{}%' , start: {}, cpu start: {}", tid, CPUUserTime, cpuUserPercentage, startTime, cpuStartTime)); -} \ No newline at end of file +} diff --git a/libstuff/ResourceMonitorThread.h b/libstuff/ResourceMonitorThread.h index 0c7f4be71..6167dd86b 100644 --- a/libstuff/ResourceMonitorThread.h +++ b/libstuff/ResourceMonitorThread.h @@ -6,17 +6,25 @@ using namespace std; class ResourceMonitorThread: public thread { public: - template, thread>>>> + template, thread>>>> explicit - ResourceMonitorThread(_Callable&& __f, _Args&&... __args): thread(forward<_Callable>(__f), forward<_Args>(__args)...){ - startTime = STimeNow(); - cpuStartTime = SGetCPUUserTime(); - }; + ResourceMonitorThread(F&& __f, Args&&... __args): thread(&wrapper, forward(__f), forward(__args)...){}; + string getThreadName(); virtual ~ResourceMonitorThread(); private: - uint64_t startTime = 0; - double cpuStartTime = 0; + static thread_local uint64_t startTime; + static thread_local double cpuStartTime; + + static void before(); + static void after(); + template + const static inline function wrapper = [](F&& f, Args&&... args){ + before(); + f(args...); + after(); + }; + }; From 6ebc14d92284c7d4d6e306f32ca0b2f9ab72753a Mon Sep 17 00:00:00 2001 From: danieldoglas Date: Thu, 3 Oct 2024 17:35:23 +0000 Subject: [PATCH 12/26] finding out why compile is failing, wip --- libstuff/ResourceMonitorThread.h | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/libstuff/ResourceMonitorThread.h b/libstuff/ResourceMonitorThread.h index 6167dd86b..2d152d5f5 100644 --- a/libstuff/ResourceMonitorThread.h +++ b/libstuff/ResourceMonitorThread.h @@ -9,7 +9,7 @@ class ResourceMonitorThread: public thread template, thread>>>> explicit - ResourceMonitorThread(F&& __f, Args&&... __args): thread(&wrapper, forward(__f), forward(__args)...){}; + ResourceMonitorThread(F&& __f, Args&&... __args): thread(wrapper, forward(__f), forward(__args)...){}; string getThreadName(); virtual ~ResourceMonitorThread(); @@ -28,3 +28,4 @@ class ResourceMonitorThread: public thread }; }; + From fdac10c0914bc53542d9873aec0de281ee57969b Mon Sep 17 00:00:00 2001 From: danieldoglas Date: Thu, 3 Oct 2024 18:01:49 +0000 Subject: [PATCH 13/26] removing unecessary things --- libstuff/ResourceMonitorThread.h | 10 +++------- 1 file changed, 3 insertions(+), 7 deletions(-) diff --git a/libstuff/ResourceMonitorThread.h b/libstuff/ResourceMonitorThread.h index 2d152d5f5..d46d57d15 100644 --- a/libstuff/ResourceMonitorThread.h +++ b/libstuff/ResourceMonitorThread.h @@ -9,10 +9,7 @@ class ResourceMonitorThread: public thread template, thread>>>> explicit - ResourceMonitorThread(F&& __f, Args&&... __args): thread(wrapper, forward(__f), forward(__args)...){}; - - string getThreadName(); - virtual ~ResourceMonitorThread(); + ResourceMonitorThread(F&& f, Args&&... args): thread(wrapper, forward(f), forward(args)...){}; private: static thread_local uint64_t startTime; @@ -21,11 +18,10 @@ class ResourceMonitorThread: public thread static void before(); static void after(); template - const static inline function wrapper = [](F&& f, Args&&... args){ + inline static function wrapper = [](F&& f, Args&&... args){ before(); - f(args...); + std::invoke(std::forward(f), std::forward(args)...); after(); }; - }; From 63c6f7bcb2f3275168da0d6cce0446207794e342 Mon Sep 17 00:00:00 2001 From: Daniel Silva Date: Thu, 3 Oct 2024 15:19:22 -0300 Subject: [PATCH 14/26] wip --- libstuff/ResourceMonitorThread.h | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/libstuff/ResourceMonitorThread.h b/libstuff/ResourceMonitorThread.h index d46d57d15..29d203a87 100644 --- a/libstuff/ResourceMonitorThread.h +++ b/libstuff/ResourceMonitorThread.h @@ -9,7 +9,7 @@ class ResourceMonitorThread: public thread template, thread>>>> explicit - ResourceMonitorThread(F&& f, Args&&... args): thread(wrapper, forward(f), forward(args)...){}; + ResourceMonitorThread(F&& f, Args&&... args): thread(&wrapper, forward(f), forward(args)...){}; private: static thread_local uint64_t startTime; @@ -20,7 +20,7 @@ class ResourceMonitorThread: public thread template inline static function wrapper = [](F&& f, Args&&... args){ before(); - std::invoke(std::forward(f), std::forward(args)...); + std::invoke(f, std::forward(args)...); after(); }; }; From 71d7941772bfc07cc6314d9869978becab97c88c Mon Sep 17 00:00:00 2001 From: Tyler Karaszewski Date: Thu, 3 Oct 2024 13:59:00 -0700 Subject: [PATCH 15/26] Make this compile --- BedrockServer.cpp | 2 +- libstuff/ResourceMonitorThread.cpp | 2 ++ libstuff/ResourceMonitorThread.h | 20 ++++++++++---------- sqlitecluster/SQLiteNode.cpp | 2 +- 4 files changed, 14 insertions(+), 12 deletions(-) diff --git a/BedrockServer.cpp b/BedrockServer.cpp index 51ab5cefd..2be29c123 100644 --- a/BedrockServer.cpp +++ b/BedrockServer.cpp @@ -119,7 +119,7 @@ void BedrockServer::sync() SINFO("Starting " << workerThreads << " worker threads."); list workerThreadList; for (int threadId = 0; threadId < workerThreads; threadId++) { - workerThreadList.emplace_back(&BedrockServer::worker, this, threadId); + workerThreadList.emplace_back([this, threadId](){this->worker(threadId);}); } // Now we jump into our main command processing loop. diff --git a/libstuff/ResourceMonitorThread.cpp b/libstuff/ResourceMonitorThread.cpp index 4e2ff1eab..c545df9c0 100644 --- a/libstuff/ResourceMonitorThread.cpp +++ b/libstuff/ResourceMonitorThread.cpp @@ -2,6 +2,8 @@ #include "libstuff/libstuff.h" #include "format" +thread_local uint64_t ResourceMonitorThread::startTime; +thread_local double ResourceMonitorThread::cpuStartTime; void ResourceMonitorThread::before(){ startTime = STimeNow(); diff --git a/libstuff/ResourceMonitorThread.h b/libstuff/ResourceMonitorThread.h index 29d203a87..b27fa85a5 100644 --- a/libstuff/ResourceMonitorThread.h +++ b/libstuff/ResourceMonitorThread.h @@ -5,23 +5,23 @@ using namespace std; class ResourceMonitorThread: public thread { + ResourceMonitorThread(const ResourceMonitorThread&) = delete; + ResourceMonitorThread(ResourceMonitorThread&&) = delete; public: - template, thread>>>> - explicit - ResourceMonitorThread(F&& f, Args&&... args): thread(&wrapper, forward(f), forward(args)...){}; - + template + ResourceMonitorThread(F&& f, Args&&... args): + thread(ResourceMonitorThread::wrapper, forward(f), forward(args)...){}; private: static thread_local uint64_t startTime; static thread_local double cpuStartTime; static void before(); static void after(); + template - inline static function wrapper = [](F&& f, Args&&... args){ + static void wrapper(F&& f, Args&&... args) { before(); - std::invoke(f, std::forward(args)...); + std::invoke(std::forward(f), std::forward(args)...); after(); - }; -}; - + } +}; \ No newline at end of file diff --git a/sqlitecluster/SQLiteNode.cpp b/sqlitecluster/SQLiteNode.cpp index 872d6e574..9a772b123 100644 --- a/sqlitecluster/SQLiteNode.cpp +++ b/sqlitecluster/SQLiteNode.cpp @@ -1649,7 +1649,7 @@ void SQLiteNode::_onMESSAGE(SQLitePeer* peer, const SData& message) { SDEBUG("Spawning concurrent replicate thread (blocks until DB handle available): " << threadID); try { uint64_t threadAttemptStartTimestamp = STimeNow(); - ResourceMonitorThread(&SQLiteNode::_replicate, this, peer, message, _dbPool->getIndex(false), threadAttemptStartTimestamp).detach(); + ResourceMonitorThread([=, this](){this->_replicate(peer, message, _dbPool->getIndex(false), threadAttemptStartTimestamp);}).detach(); } catch (const system_error& e) { // If the server is strugling and falling behind on replication, we might have too many threads // causing a resource exhaustion. If that happens, all the transactions that are already threaded From 717773dbd4a5e910489333efafea0c7f31279e02 Mon Sep 17 00:00:00 2001 From: danieldoglas Date: Fri, 4 Oct 2024 14:32:42 +0000 Subject: [PATCH 16/26] removing unused data --- libstuff/ResourceMonitorThread.h | 2 -- 1 file changed, 2 deletions(-) diff --git a/libstuff/ResourceMonitorThread.h b/libstuff/ResourceMonitorThread.h index b27fa85a5..037f6a487 100644 --- a/libstuff/ResourceMonitorThread.h +++ b/libstuff/ResourceMonitorThread.h @@ -5,8 +5,6 @@ using namespace std; class ResourceMonitorThread: public thread { - ResourceMonitorThread(const ResourceMonitorThread&) = delete; - ResourceMonitorThread(ResourceMonitorThread&&) = delete; public: template ResourceMonitorThread(F&& f, Args&&... args): From 78b70e9dce4ee430576e4849ecf52d9225086718 Mon Sep 17 00:00:00 2001 From: danieldoglas Date: Fri, 4 Oct 2024 14:41:36 +0000 Subject: [PATCH 17/26] adding some arbitrary filters so we don't spam the logs --- libstuff/ResourceMonitorThread.cpp | 13 ++++++++++--- 1 file changed, 10 insertions(+), 3 deletions(-) diff --git a/libstuff/ResourceMonitorThread.cpp b/libstuff/ResourceMonitorThread.cpp index c545df9c0..a64852ff0 100644 --- a/libstuff/ResourceMonitorThread.cpp +++ b/libstuff/ResourceMonitorThread.cpp @@ -1,6 +1,7 @@ #include "ResourceMonitorThread.h" #include "libstuff/libstuff.h" #include "format" +#include thread_local uint64_t ResourceMonitorThread::startTime; thread_local double ResourceMonitorThread::cpuStartTime; @@ -13,7 +14,13 @@ void ResourceMonitorThread::before(){ void ResourceMonitorThread::after(){ const uint64_t threadEndTime = STimeNow() - startTime; const double CPUUserTime = SGetCPUUserTime() - cpuStartTime; - const double cpuUserPercentage = (CPUUserTime / static_cast(threadEndTime)) * 100; - const pid_t tid = syscall(SYS_gettid); - SINFO(format("Thread finished. pID: '{}', CPUTime: '{}µs', CPUPercentage: '{}%' , start: {}, cpu start: {}", tid, CPUUserTime, cpuUserPercentage, startTime, cpuStartTime)); + const double cpuUserPercentage = round((CPUUserTime / static_cast(threadEndTime)) * 100 * 1000) / 1000; + + // Any thread that takes more than 100ms and uses more than 50% CPU during it's lifetime will be logged. These parameters + // are completely arbitrary, and might need some fine-tuning in the future based on our future investigations. + // If we don't add this, we'll log millions log log lines per hour that won't be useful to investigate anything. + if (CPUUserTime > 100'000 && cpuUserPercentage > 50) { + const pid_t tid = syscall(SYS_gettid); + SINFO(format("Thread finished. pID: '{}', CPUTime: '{}µs', CPUPercentage: '{}%'", tid, CPUUserTime, cpuUserPercentage, startTime, cpuStartTime)); + } } From 6275f2b63807ac0427d5cd467da1de873f2fd026 Mon Sep 17 00:00:00 2001 From: danieldoglas Date: Fri, 4 Oct 2024 14:47:58 +0000 Subject: [PATCH 18/26] adding comments --- libstuff/ResourceMonitorThread.h | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/libstuff/ResourceMonitorThread.h b/libstuff/ResourceMonitorThread.h index 037f6a487..cead977f6 100644 --- a/libstuff/ResourceMonitorThread.h +++ b/libstuff/ResourceMonitorThread.h @@ -3,9 +3,15 @@ using namespace std; +// This class is a wrapper around the default thread. We use it to collect the thread CPU usage. That allows us +// to investigate if we have any threads using more resources than it should, which can cause CPU usage peaks in +// the cluster. class ResourceMonitorThread: public thread { public: + // When calling this constructor, if you're passing a class member function as the `f` parameter and that + // function receives parameters, you will need to wrap your function call in a lambda, doing something like: + // ResourceMonitorThread([=, this]{ this->memberFunction(param1, param2);}); template ResourceMonitorThread(F&& f, Args&&... args): thread(ResourceMonitorThread::wrapper, forward(f), forward(args)...){}; From 0b60286374eb91709386d3dd9b2ea9ace6da0766 Mon Sep 17 00:00:00 2001 From: danieldoglas Date: Fri, 4 Oct 2024 14:53:50 +0000 Subject: [PATCH 19/26] adding check so we don't divide by 0 --- libstuff/ResourceMonitorThread.cpp | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/libstuff/ResourceMonitorThread.cpp b/libstuff/ResourceMonitorThread.cpp index a64852ff0..19887a87d 100644 --- a/libstuff/ResourceMonitorThread.cpp +++ b/libstuff/ResourceMonitorThread.cpp @@ -14,6 +14,12 @@ void ResourceMonitorThread::before(){ void ResourceMonitorThread::after(){ const uint64_t threadEndTime = STimeNow() - startTime; const double CPUUserTime = SGetCPUUserTime() - cpuStartTime; + + // This shouldn't happen since the time to start/finish a thread should take more than a microsecond, but to be + // sure we're not dividing by 0 and causing crashes, let's add an if here and return if threadEndTime is 0. + if (threadEndTime == 0) { + return; + } const double cpuUserPercentage = round((CPUUserTime / static_cast(threadEndTime)) * 100 * 1000) / 1000; // Any thread that takes more than 100ms and uses more than 50% CPU during it's lifetime will be logged. These parameters From 2337fd3a7cdd52a2bb0bd222750e6239f69385b4 Mon Sep 17 00:00:00 2001 From: danieldoglas Date: Fri, 4 Oct 2024 16:32:19 +0000 Subject: [PATCH 20/26] removing limiter on logs --- libstuff/ResourceMonitorThread.cpp | 10 ++-------- 1 file changed, 2 insertions(+), 8 deletions(-) diff --git a/libstuff/ResourceMonitorThread.cpp b/libstuff/ResourceMonitorThread.cpp index 19887a87d..59f9ba04b 100644 --- a/libstuff/ResourceMonitorThread.cpp +++ b/libstuff/ResourceMonitorThread.cpp @@ -21,12 +21,6 @@ void ResourceMonitorThread::after(){ return; } const double cpuUserPercentage = round((CPUUserTime / static_cast(threadEndTime)) * 100 * 1000) / 1000; - - // Any thread that takes more than 100ms and uses more than 50% CPU during it's lifetime will be logged. These parameters - // are completely arbitrary, and might need some fine-tuning in the future based on our future investigations. - // If we don't add this, we'll log millions log log lines per hour that won't be useful to investigate anything. - if (CPUUserTime > 100'000 && cpuUserPercentage > 50) { - const pid_t tid = syscall(SYS_gettid); - SINFO(format("Thread finished. pID: '{}', CPUTime: '{}µs', CPUPercentage: '{}%'", tid, CPUUserTime, cpuUserPercentage, startTime, cpuStartTime)); - } + const pid_t tid = syscall(SYS_gettid); + SINFO(format("Thread finished. pID: '{}', CPUTime: '{}µs', CPUPercentage: '{}%'", tid, CPUUserTime, cpuUserPercentage, startTime, cpuStartTime)); } From f64776022aabc74b0bb431730d4777d73ed98816 Mon Sep 17 00:00:00 2001 From: Tyler Karaszewski Date: Mon, 7 Oct 2024 11:45:13 -0700 Subject: [PATCH 21/26] Release DB handle on follower when escalating command --- BedrockServer.cpp | 1 + sqlitecluster/SQLitePool.cpp | 11 +++++++++-- sqlitecluster/SQLitePool.h | 2 ++ 3 files changed, 12 insertions(+), 2 deletions(-) diff --git a/BedrockServer.cpp b/BedrockServer.cpp index 544d3e5b2..105b90f20 100644 --- a/BedrockServer.cpp +++ b/BedrockServer.cpp @@ -953,6 +953,7 @@ void BedrockServer::runCommand(unique_ptr&& _command, bool isBlo if (!canWriteParallel) { // Roll back the transaction, it'll get re-run in the sync thread. core.rollback(); + dbScope.release(); auto _clusterMessengerCopy = _clusterMessenger; if (getState() == SQLiteNodeState::LEADING) { // Limit the command timeout to 20s to avoid blocking the sync thread long enough to cause the cluster to give up and elect a new leader (causing a fork), which happens diff --git a/sqlitecluster/SQLitePool.cpp b/sqlitecluster/SQLitePool.cpp index bb1937a9b..1a93148fc 100644 --- a/sqlitecluster/SQLitePool.cpp +++ b/sqlitecluster/SQLitePool.cpp @@ -87,11 +87,18 @@ void SQLitePool::returnToPool(size_t index) { _wait.notify_one(); } -SQLiteScopedHandle::SQLiteScopedHandle(SQLitePool& pool, size_t index) : _pool(pool), _index(index) +SQLiteScopedHandle::SQLiteScopedHandle(SQLitePool& pool, size_t index) : _pool(pool), _index(index), _released(true) {} +void SQLiteScopedHandle::release() { + if (!_released) { + _pool.returnToPool(_index); + _released = true; + } +} + SQLiteScopedHandle::~SQLiteScopedHandle() { - _pool.returnToPool(_index); + release(); } SQLite& SQLiteScopedHandle::db() { diff --git a/sqlitecluster/SQLitePool.h b/sqlitecluster/SQLitePool.h index 42e27dd45..24637893b 100644 --- a/sqlitecluster/SQLitePool.h +++ b/sqlitecluster/SQLitePool.h @@ -53,8 +53,10 @@ class SQLiteScopedHandle { SQLiteScopedHandle(SQLitePool& pool, size_t index); ~SQLiteScopedHandle(); SQLite& db(); + void release(); private: SQLitePool& _pool; size_t _index; + bool _released; }; From 89a3505d437fa90076ff04c7deeac2bc78e05eb3 Mon Sep 17 00:00:00 2001 From: Tyler Karaszewski Date: Mon, 7 Oct 2024 14:25:39 -0700 Subject: [PATCH 22/26] Wrong default value --- sqlitecluster/SQLitePool.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sqlitecluster/SQLitePool.cpp b/sqlitecluster/SQLitePool.cpp index 1a93148fc..7c0e0cec6 100644 --- a/sqlitecluster/SQLitePool.cpp +++ b/sqlitecluster/SQLitePool.cpp @@ -87,7 +87,7 @@ void SQLitePool::returnToPool(size_t index) { _wait.notify_one(); } -SQLiteScopedHandle::SQLiteScopedHandle(SQLitePool& pool, size_t index) : _pool(pool), _index(index), _released(true) +SQLiteScopedHandle::SQLiteScopedHandle(SQLitePool& pool, size_t index) : _pool(pool), _index(index), _released(false) {} void SQLiteScopedHandle::release() { From 631b9f512e0efc6630531a873ee0f255725cf7a6 Mon Sep 17 00:00:00 2001 From: danieldoglas Date: Tue, 8 Oct 2024 14:16:15 +0000 Subject: [PATCH 23/26] addressing PR comments --- libstuff/ResourceMonitorThread.cpp | 22 +++++++++++----------- libstuff/ResourceMonitorThread.h | 8 ++++---- libstuff/libstuff.cpp | 1 + libstuff/libstuff.h | 3 ++- 4 files changed, 18 insertions(+), 16 deletions(-) diff --git a/libstuff/ResourceMonitorThread.cpp b/libstuff/ResourceMonitorThread.cpp index 59f9ba04b..08b0cecbb 100644 --- a/libstuff/ResourceMonitorThread.cpp +++ b/libstuff/ResourceMonitorThread.cpp @@ -1,26 +1,26 @@ #include "ResourceMonitorThread.h" #include "libstuff/libstuff.h" -#include "format" +#include #include -thread_local uint64_t ResourceMonitorThread::startTime; -thread_local double ResourceMonitorThread::cpuStartTime; +uint64_t ResourceMonitorThread::threadStartTime; +double ResourceMonitorThread::cpuStartTime; -void ResourceMonitorThread::before(){ - startTime = STimeNow(); +void ResourceMonitorThread::before() { + threadStartTime = STimeNow(); cpuStartTime = SGetCPUUserTime(); } -void ResourceMonitorThread::after(){ - const uint64_t threadEndTime = STimeNow() - startTime; - const double CPUUserTime = SGetCPUUserTime() - cpuStartTime; +void ResourceMonitorThread::after() { + const uint64_t threadUserTime = STimeNow() - threadStartTime; + const double cpuUserTime = SGetCPUUserTime() - cpuStartTime; // This shouldn't happen since the time to start/finish a thread should take more than a microsecond, but to be // sure we're not dividing by 0 and causing crashes, let's add an if here and return if threadEndTime is 0. - if (threadEndTime == 0) { + if (threadUserTime == 0) { return; } - const double cpuUserPercentage = round((CPUUserTime / static_cast(threadEndTime)) * 100 * 1000) / 1000; + const double cpuUserPercentage = round((cpuUserTime / static_cast(threadUserTime)) * 100 * 1000) / 1000; const pid_t tid = syscall(SYS_gettid); - SINFO(format("Thread finished. pID: '{}', CPUTime: '{}µs', CPUPercentage: '{}%'", tid, CPUUserTime, cpuUserPercentage, startTime, cpuStartTime)); + SINFO(format("Thread finished. pID: '{}', CPUTime: '{}µs', CPUPercentage: '{}%'", tid, cpuUserTime, cpuUserPercentage)); } diff --git a/libstuff/ResourceMonitorThread.h b/libstuff/ResourceMonitorThread.h index cead977f6..54729f504 100644 --- a/libstuff/ResourceMonitorThread.h +++ b/libstuff/ResourceMonitorThread.h @@ -6,7 +6,7 @@ using namespace std; // This class is a wrapper around the default thread. We use it to collect the thread CPU usage. That allows us // to investigate if we have any threads using more resources than it should, which can cause CPU usage peaks in // the cluster. -class ResourceMonitorThread: public thread +class ResourceMonitorThread : public thread { public: // When calling this constructor, if you're passing a class member function as the `f` parameter and that @@ -16,8 +16,8 @@ class ResourceMonitorThread: public thread ResourceMonitorThread(F&& f, Args&&... args): thread(ResourceMonitorThread::wrapper, forward(f), forward(args)...){}; private: - static thread_local uint64_t startTime; - static thread_local double cpuStartTime; + static uint64_t threadStartTime; + static double cpuStartTime; static void before(); static void after(); @@ -25,7 +25,7 @@ class ResourceMonitorThread: public thread template static void wrapper(F&& f, Args&&... args) { before(); - std::invoke(std::forward(f), std::forward(args)...); + invoke(forward(f), forward(args)...); after(); } }; \ No newline at end of file diff --git a/libstuff/libstuff.cpp b/libstuff/libstuff.cpp index 78ab7bcf5..5dd682d10 100644 --- a/libstuff/libstuff.cpp +++ b/libstuff/libstuff.cpp @@ -3206,6 +3206,7 @@ SString& SString::operator=(const bool from) { double SGetCPUUserTime() { struct rusage usage; getrusage(RUSAGE_THREAD, &usage); + // Returns the current threads CPU user time in microseconds return static_cast(usage.ru_utime.tv_sec) * 1e6 + static_cast(usage.ru_utime.tv_usec); } diff --git a/libstuff/libstuff.h b/libstuff/libstuff.h index fb4a55e66..13a158179 100644 --- a/libstuff/libstuff.h +++ b/libstuff/libstuff.h @@ -629,6 +629,7 @@ string SGUnzip(const string& content); // Command-line helpers STable SParseCommandLine(int argc, char* argv[]); -// Returns the current CPU usage inside the current process +// Returns the CPU usage inside the current thread double SGetCPUUserTime(); + #endif // LIBSTUFF_H From be2295fa8e816960679d2ca7489101326ae62826 Mon Sep 17 00:00:00 2001 From: danieldoglas Date: Tue, 8 Oct 2024 14:19:52 +0000 Subject: [PATCH 24/26] renaming resource threads --- libstuff/ResourceMonitorThread.cpp | 4 ++-- libstuff/ResourceMonitorThread.h | 8 ++++---- 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/libstuff/ResourceMonitorThread.cpp b/libstuff/ResourceMonitorThread.cpp index 08b0cecbb..afc743ed1 100644 --- a/libstuff/ResourceMonitorThread.cpp +++ b/libstuff/ResourceMonitorThread.cpp @@ -6,12 +6,12 @@ uint64_t ResourceMonitorThread::threadStartTime; double ResourceMonitorThread::cpuStartTime; -void ResourceMonitorThread::before() { +void ResourceMonitorThread::beforeProcessStart() { threadStartTime = STimeNow(); cpuStartTime = SGetCPUUserTime(); } -void ResourceMonitorThread::after() { +void ResourceMonitorThread::afterProcessFinished() { const uint64_t threadUserTime = STimeNow() - threadStartTime; const double cpuUserTime = SGetCPUUserTime() - cpuStartTime; diff --git a/libstuff/ResourceMonitorThread.h b/libstuff/ResourceMonitorThread.h index 54729f504..793cfb87c 100644 --- a/libstuff/ResourceMonitorThread.h +++ b/libstuff/ResourceMonitorThread.h @@ -19,13 +19,13 @@ class ResourceMonitorThread : public thread static uint64_t threadStartTime; static double cpuStartTime; - static void before(); - static void after(); + static void beforeProcessStart(); + static void afterProcessFinished(); template static void wrapper(F&& f, Args&&... args) { - before(); + beforeProcessStart(); invoke(forward(f), forward(args)...); - after(); + afterProcessFinished(); } }; \ No newline at end of file From ff324a1b19b1d961566877f92b3b4e0e0512c0d0 Mon Sep 17 00:00:00 2001 From: Florent De Neve Date: Tue, 8 Oct 2024 14:54:41 -0400 Subject: [PATCH 25/26] Update SQLite to new version which includes logging --- libstuff/sqlite3.c | 171 ++++++++++++++++++++++++++++++++++++++++++++- libstuff/sqlite3.h | 2 +- 2 files changed, 169 insertions(+), 4 deletions(-) diff --git a/libstuff/sqlite3.c b/libstuff/sqlite3.c index 8290aa033..d14ab53f6 100644 --- a/libstuff/sqlite3.c +++ b/libstuff/sqlite3.c @@ -18,7 +18,7 @@ ** separate file. This file contains only code for the core SQLite library. ** ** The content in this amalgamation comes from Fossil check-in -** cf8f155280100c1a5b79b118875a93686a55. +** cd6f585cadfe40778c3bf59dfbfa5f02c50c. */ #define SQLITE_CORE 1 #define SQLITE_AMALGAMATION 1 @@ -465,7 +465,7 @@ extern "C" { */ #define SQLITE_VERSION "3.47.0" #define SQLITE_VERSION_NUMBER 3047000 -#define SQLITE_SOURCE_ID "2024-09-04 16:54:56 cf8f155280100c1a5b79b118875a93686a554d8be55114277f4f7b20cfd7835a" +#define SQLITE_SOURCE_ID "2024-10-08 15:08:04 cd6f585cadfe40778c3bf59dfbfa5f02c50cf5e10af1bd553cad4dfa56ea2249" /* ** CAPI3REF: Run-Time Library Version Numbers @@ -16331,6 +16331,8 @@ SQLITE_PRIVATE void sqlite3PagerRefdump(Pager*); SQLITE_PRIVATE int sqlite3PagerWalSystemErrno(Pager*); #endif +SQLITE_PRIVATE void sqlite3PagerSetCommitTime(Pager *pPager, u64 *aCommitTime); + #endif /* SQLITE_PAGER_H */ /************** End of pager.h ***********************************************/ @@ -17433,6 +17435,31 @@ SQLITE_PRIVATE void sqlite3VdbePrintOp(FILE*, int, VdbeOp*); SQLITE_PRIVATE int sqlite3CursorRangeHintExprCheck(Walker *pWalker, Expr *pExpr); #endif + +#define COMMIT_TIME_START 0 +#define COMMIT_TIME_BEFORE_HALT 1 +#define COMMIT_TIME_BEFORE_VDBECOMMIT 2 + +#define COMMIT_TIME_BEFORE_PHASEONE 3 +#define COMMIT_TIME_AFTER_FIXUNLOCKED 4 +#define COMMIT_TIME_AFTER_WALFRAMES 5 + +#define COMMIT_TIME_BEFORE_PHASETWO 6 +#define COMMIT_TIME_AFTER_PHASETWO 7 + +#define COMMIT_TIME_AFTER_VDBECOMMIT 8 +#define COMMIT_TIME_AFTER_HALT 9 +#define COMMIT_TIME_FINISH 10 + +#define COMMIT_TIME_N 11 + +/* #define COMMIT_TIME_TIMEOUT (2*1000*1000) */ +#define COMMIT_TIME_TIMEOUT (10*1000) /* 10ms threshold */ + +SQLITE_PRIVATE void sqlite3CommitTimeLog(u64*); +SQLITE_PRIVATE u64 sqlite3STimeNow(); +SQLITE_PRIVATE void sqlite3CommitTimeSet(u64*, int); + #endif /* SQLITE_VDBE_H */ /************** End of vdbe.h ************************************************/ @@ -18128,8 +18155,29 @@ struct sqlite3 { */ u32 aCommit[5]; #endif + + u64 *aPrepareTime; }; +#define PREPARE_TIME_START 0 +#define PREPARE_TIME_BEGINPARSE 1 +#define PREPARE_TIME_BEGINPRAGMA 2 +#define PREPARE_TIME_BEGINCACHESIZE 3 +#define PREPARE_TIME_BEGINSETCACHESIZE 4 +#define PREPARE_TIME_ENDSETCACHESIZE 5 +#define PREPARE_TIME_ENDCACHESIZE 6 +#define PREPARE_TIME_ENDPRAGMA 7 +#define PREPARE_TIME_ENDPARSE 8 +#define PREPARE_TIME_FINISH 9 + +#define PREPARE_TIME_N 10 + +#define sqlite3PrepareTimeSet(x,y) sqlite3CommitTimeSet(x,y) +SQLITE_PRIVATE void sqlite3PrepareTimeLog(const char *zSql, int nSql, u64 *aPrepareTime); + +#define PREPARE_TIME_TIMEOUT (2 * 1000 * 1000) /* 2 second timeout */ + + /* ** Candidate values for sqlite3.eConcurrent */ @@ -23650,6 +23698,8 @@ struct VdbeCursor { ** static element declared in the structure. nField total array slots for ** aType[] and nField+1 array slots for aOffset[] */ u32 aType[1]; /* Type values record decode. MUST BE LAST */ + + u8 *aCommit; }; /* Return true if P is a null-only cursor @@ -24027,6 +24077,7 @@ struct Vdbe { int nScan; /* Entries in aScan[] */ ScanStatus *aScan; /* Scan definitions for sqlite3_stmt_scanstatus() */ #endif + u64 *aCommitTime; }; /* @@ -57811,6 +57862,8 @@ SQLITE_PRIVATE int sqlite3WalInfo(Wal *pWal, u32 *pnPrior, u32 *pnFrame); /* sqlite3_wal_info() data */ SQLITE_PRIVATE int sqlite3WalInfo(Wal *pWal, u32 *pnPrior, u32 *pnFrame); +SQLITE_PRIVATE void sqlite3WalSetCommitTime(Wal *pWal, u64 *aCommitTime); + #endif /* ifndef SQLITE_OMIT_WAL */ #endif /* SQLITE_WAL_H */ @@ -58498,6 +58551,7 @@ struct Pager { Wal *pWal; /* Write-ahead log used by "journal_mode=wal" */ char *zWal; /* File name for write-ahead log */ #endif + u64 *aCommitTime; }; /* @@ -64449,6 +64503,7 @@ SQLITE_PRIVATE int sqlite3PagerCommitPhaseOne( assert( rc==SQLITE_OK ); if( ALWAYS(pList) ){ rc = pagerWalFrames(pPager, pList, pPager->dbSize, 1); + sqlite3CommitTimeSet(pPager->aCommitTime, COMMIT_TIME_AFTER_WALFRAMES); } sqlite3PagerUnref(pPageOne); if( rc==SQLITE_OK ){ @@ -64622,6 +64677,10 @@ SQLITE_PRIVATE int sqlite3PagerCommitPhaseOne( return rc; } +SQLITE_PRIVATE void sqlite3PagerSetCommitTime(Pager *pPager, u64 *aCommitTime){ + pPager->aCommitTime = aCommitTime; + sqlite3WalSetCommitTime(pPager->pWal, aCommitTime); +} /* ** When this function is called, the database file has been completely @@ -66592,6 +66651,7 @@ struct Wal { #ifdef SQLITE_ENABLE_SETLK_TIMEOUT sqlite3 *db; #endif + u64 *aCommitTime; }; /* @@ -71604,6 +71664,12 @@ SQLITE_PRIVATE int sqlite3WalJournalMode(Wal *pWal){ return (isWalMode2(pWal) ? PAGER_JOURNALMODE_WAL2 : PAGER_JOURNALMODE_WAL); } +SQLITE_PRIVATE void sqlite3WalSetCommitTime(Wal *pWal, u64 *aCommitTime){ + if( pWal ){ + pWal->aCommitTime = aCommitTime; + } +} + #endif /* #ifndef SQLITE_OMIT_WAL */ /************** End of wal.c *************************************************/ @@ -72099,6 +72165,8 @@ struct BtShared { BtreePtrmap *pMap; #endif int nPreformatSize; /* Size of last cell written by TransferRow() */ + + u64 *aCommitTime; }; /* @@ -75908,7 +75976,9 @@ SQLITE_PRIVATE int sqlite3BtreeSetCacheSize(Btree *p, int mxPage){ BtShared *pBt = p->pBt; assert( sqlite3_mutex_held(p->db->mutex) ); sqlite3BtreeEnter(p); + sqlite3PrepareTimeSet(p->db->aPrepareTime, PREPARE_TIME_BEGINSETCACHESIZE); sqlite3PagerSetCachesize(pBt->pPager, mxPage); + sqlite3PrepareTimeSet(p->db->aPrepareTime, PREPARE_TIME_ENDSETCACHESIZE); sqlite3BtreeLeave(p); return SQLITE_OK; } @@ -77412,9 +77482,12 @@ SQLITE_PRIVATE int sqlite3BtreeCommitPhaseOne(Btree *p, const char *zSuperJrnl){ #endif if( rc==SQLITE_OK && ISCONCURRENT && p->db->eConcurrent==CONCURRENT_OPEN ){ rc = btreeFixUnlocked(p); + sqlite3CommitTimeSet(p->pBt->aCommitTime, COMMIT_TIME_AFTER_FIXUNLOCKED); } if( rc==SQLITE_OK ){ + sqlite3PagerSetCommitTime(pBt->pPager, p->pBt->aCommitTime); rc = sqlite3PagerCommitPhaseOne(pBt->pPager, zSuperJrnl, 0); + sqlite3PagerSetCommitTime(pBt->pPager, 0); } #ifndef SQLITE_OMIT_CONCURRENT if( rc==SQLITE_OK ){ @@ -77519,7 +77592,9 @@ SQLITE_PRIVATE int sqlite3BtreeCommitPhaseTwo(Btree *p, int bCleanup){ BtShared *pBt = p->pBt; assert( pBt->inTransaction==TRANS_WRITE ); assert( pBt->nTransaction>0 ); + sqlite3PagerSetCommitTime(pBt->pPager, p->pBt->aCommitTime); rc = sqlite3PagerCommitPhaseTwo(pBt->pPager); + sqlite3PagerSetCommitTime(pBt->pPager, 0); if( rc!=SQLITE_OK && bCleanup==0 ){ sqlite3BtreeLeave(p); return rc; @@ -87639,6 +87714,8 @@ SQLITE_PRIVATE int sqlite3ValueBytes(sqlite3_value *pVal, u8 enc){ /* #include "sqliteInt.h" */ /* #include "vdbeInt.h" */ +/* #include "btreeInt.h" */ + /* Forward references */ static void freeEphemeralFunction(sqlite3 *db, FuncDef *pDef); static void vdbeFreeOpArray(sqlite3 *, Op *, int); @@ -90624,13 +90701,18 @@ static int vdbeCommit(sqlite3 *db, Vdbe *p){ if( 0==sqlite3Strlen30(sqlite3BtreeGetFilename(db->aDb[0].pBt)) || nTrans<=1 ){ + sqlite3CommitTimeSet(p->aCommitTime, COMMIT_TIME_BEFORE_PHASEONE); for(i=0; rc==SQLITE_OK && inDb; i++){ Btree *pBt = db->aDb[i].pBt; if( pBt ){ + pBt->pBt->aCommitTime = p->aCommitTime; rc = sqlite3BtreeCommitPhaseOne(pBt, 0); + pBt->pBt->aCommitTime = 0; } } + sqlite3CommitTimeSet(p->aCommitTime, COMMIT_TIME_BEFORE_PHASETWO); + /* Do the commit only if all databases successfully complete phase 1. ** If one of the BtreeCommitPhaseOne() calls fails, this indicates an ** IO error while deleting or truncating a journal file. It is unlikely, @@ -90639,9 +90721,13 @@ static int vdbeCommit(sqlite3 *db, Vdbe *p){ for(i=0; rc==SQLITE_OK && inDb; i++){ Btree *pBt = db->aDb[i].pBt; if( pBt ){ + pBt->pBt->aCommitTime = p->aCommitTime; rc = sqlite3BtreeCommitPhaseTwo(pBt, 0); + pBt->pBt->aCommitTime = 0; } } + + sqlite3CommitTimeSet(p->aCommitTime, COMMIT_TIME_AFTER_PHASETWO); if( rc==SQLITE_OK ){ sqlite3VtabCommit(db); } @@ -91038,7 +91124,9 @@ SQLITE_PRIVATE int sqlite3VdbeHalt(Vdbe *p){ ** or hit an 'OR FAIL' constraint and there are no deferred foreign ** key constraints to hold up the transaction. This means a commit ** is required. */ + sqlite3CommitTimeSet(p->aCommitTime, COMMIT_TIME_BEFORE_VDBECOMMIT); rc = vdbeCommit(db, p); + sqlite3CommitTimeSet(p->aCommitTime, COMMIT_TIME_AFTER_VDBECOMMIT); } if( (rc & 0xFF)==SQLITE_BUSY && p->readOnly ){ sqlite3VdbeLeave(p); @@ -93070,6 +93158,53 @@ SQLITE_PRIVATE int sqlite3CursorRangeHintExprCheck(Walker *pWalker, Expr *pExpr) } #endif /* SQLITE_ENABLE_CURSOR_HINTS && SQLITE_DEBUG */ +/* #include */ +SQLITE_PRIVATE void sqlite3CommitTimeLog(u64 *aCommit){ + u64 i1 = aCommit[COMMIT_TIME_START]; + assert( COMMIT_TIME_START==0 && COMMIT_TIME_FINISH==COMMIT_TIME_N-1 ); + if( aCommit[COMMIT_TIME_FINISH]>(i1+COMMIT_TIME_TIMEOUT) ){ + char *zStr = 0; + int ii; + for(ii=1; ii(i1+PREPARE_TIME_TIMEOUT) ){ + int nByte = nSql; + char *zStr = 0; + int ii; + for(ii=1; iibIsReader ); if( desiredAutoCommit!=db->autoCommit ){ + + u64 aCommit[COMMIT_TIME_N]; + memset(aCommit, 0, sizeof(aCommit)); + sqlite3CommitTimeSet(aCommit, COMMIT_TIME_START); + if( iRollback ){ assert( desiredAutoCommit==1 ); sqlite3RollbackAll(db, SQLITE_ABORT_ROLLBACK); @@ -99911,7 +100051,11 @@ case OP_AutoCommit: { }else{ db->autoCommit = (u8)desiredAutoCommit; } + sqlite3CommitTimeSet(aCommit, COMMIT_TIME_BEFORE_HALT); + p->aCommitTime = aCommit; hrc = sqlite3VdbeHalt(p); + p->aCommitTime = 0; + sqlite3CommitTimeSet(aCommit, COMMIT_TIME_AFTER_HALT); if( (hrc & 0xFF)==SQLITE_BUSY ){ p->pc = (int)(pOp - aOp); db->autoCommit = (u8)(1-desiredAutoCommit); @@ -99927,6 +100071,8 @@ case OP_AutoCommit: { }else{ rc = SQLITE_ERROR; } + sqlite3CommitTimeSet(aCommit, COMMIT_TIME_FINISH); + if( desiredAutoCommit ) sqlite3CommitTimeLog(aCommit); goto vdbe_return; }else{ sqlite3VdbeError(p, @@ -142360,6 +142506,7 @@ SQLITE_PRIVATE void sqlite3Pragma( Vdbe *v = sqlite3GetVdbe(pParse); /* Prepared statement */ const PragmaName *pPragma; /* The pragma */ + sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_BEGINPRAGMA); if( v==0 ) return; sqlite3VdbeRunOnlyOnce(v); pParse->nMem = 2; @@ -142800,6 +142947,7 @@ SQLITE_PRIVATE void sqlite3Pragma( */ case PragTyp_CACHE_SIZE: { assert( sqlite3SchemaMutexHeld(db, iDb, 0) ); + sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_BEGINCACHESIZE); if( !zRight ){ returnSingleInt(v, pDb->pSchema->cache_size); }else{ @@ -142807,6 +142955,7 @@ SQLITE_PRIVATE void sqlite3Pragma( pDb->pSchema->cache_size = size; sqlite3BtreeSetCacheSize(pDb->pBt, pDb->pSchema->cache_size); } + sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_ENDCACHESIZE); break; } @@ -144693,6 +144842,7 @@ SQLITE_PRIVATE void sqlite3Pragma( pragma_out: sqlite3DbFree(db, zLeft); sqlite3DbFree(db, zRight); + sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_ENDPRAGMA); } #ifndef SQLITE_OMIT_VIRTUALTABLE /***************************************************************************** @@ -145796,14 +145946,18 @@ static int sqlite3Prepare( } zSqlCopy = sqlite3DbStrNDup(db, zSql, nBytes); if( zSqlCopy ){ + sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_BEGINPARSE); sqlite3RunParser(&sParse, zSqlCopy); + sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_ENDPARSE); sParse.zTail = &zSql[sParse.zTail-zSqlCopy]; sqlite3DbFree(db, zSqlCopy); }else{ sParse.zTail = &zSql[nBytes]; } }else{ + sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_BEGINPARSE); sqlite3RunParser(&sParse, zSql); + sqlite3PrepareTimeSet(db->aPrepareTime, PREPARE_TIME_ENDPARSE); } assert( 0==sParse.nQueryLoop ); @@ -145864,6 +146018,12 @@ static int sqlite3LockAndPrepare( ){ int rc; int cnt = 0; + u64 *aPrepareSave = db->aPrepareTime; + + u64 aPrepareTime[PREPARE_TIME_N]; + memset(aPrepareTime, 0, sizeof(aPrepareTime)); + sqlite3PrepareTimeSet(aPrepareTime, PREPARE_TIME_START); + db->aPrepareTime = aPrepareTime; #ifdef SQLITE_ENABLE_API_ARMOR if( ppStmt==0 ) return SQLITE_MISUSE_BKPT; @@ -145889,6 +146049,11 @@ static int sqlite3LockAndPrepare( db->busyHandler.nBusy = 0; sqlite3_mutex_leave(db->mutex); assert( rc==SQLITE_OK || (*ppStmt)==0 ); + + db->aPrepareTime = aPrepareSave; + sqlite3PrepareTimeSet(aPrepareTime, PREPARE_TIME_FINISH); + sqlite3PrepareTimeLog(zSql, nBytes, aPrepareTime); + return rc; } @@ -257384,7 +257549,7 @@ static void fts5SourceIdFunc( ){ assert( nArg==0 ); UNUSED_PARAM2(nArg, apUnused); - sqlite3_result_text(pCtx, "fts5: 2024-09-04 16:54:56 cf8f155280100c1a5b79b118875a93686a554d8be55114277f4f7b20cfd7835a", -1, SQLITE_TRANSIENT); + sqlite3_result_text(pCtx, "fts5: 2024-10-08 15:08:04 cd6f585cadfe40778c3bf59dfbfa5f02c50cf5e10af1bd553cad4dfa56ea2249", -1, SQLITE_TRANSIENT); } /* diff --git a/libstuff/sqlite3.h b/libstuff/sqlite3.h index 7175009bb..a67aa06aa 100644 --- a/libstuff/sqlite3.h +++ b/libstuff/sqlite3.h @@ -148,7 +148,7 @@ extern "C" { */ #define SQLITE_VERSION "3.47.0" #define SQLITE_VERSION_NUMBER 3047000 -#define SQLITE_SOURCE_ID "2024-09-04 16:54:56 cf8f155280100c1a5b79b118875a93686a554d8be55114277f4f7b20cfd7835a" +#define SQLITE_SOURCE_ID "2024-10-08 15:08:04 cd6f585cadfe40778c3bf59dfbfa5f02c50cf5e10af1bd553cad4dfa56ea2249" /* ** CAPI3REF: Run-Time Library Version Numbers From 656aa302746f39052e4af13b96ad5dde58041bf7 Mon Sep 17 00:00:00 2001 From: Daniel Silva Date: Tue, 8 Oct 2024 16:23:02 -0300 Subject: [PATCH 26/26] changing the variables back to thread_local --- libstuff/ResourceMonitorThread.cpp | 4 ++-- libstuff/ResourceMonitorThread.h | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/libstuff/ResourceMonitorThread.cpp b/libstuff/ResourceMonitorThread.cpp index afc743ed1..a9963892a 100644 --- a/libstuff/ResourceMonitorThread.cpp +++ b/libstuff/ResourceMonitorThread.cpp @@ -3,8 +3,8 @@ #include #include -uint64_t ResourceMonitorThread::threadStartTime; -double ResourceMonitorThread::cpuStartTime; +thread_local uint64_t ResourceMonitorThread::threadStartTime; +thread_local double ResourceMonitorThread::cpuStartTime; void ResourceMonitorThread::beforeProcessStart() { threadStartTime = STimeNow(); diff --git a/libstuff/ResourceMonitorThread.h b/libstuff/ResourceMonitorThread.h index 793cfb87c..5bb7e6896 100644 --- a/libstuff/ResourceMonitorThread.h +++ b/libstuff/ResourceMonitorThread.h @@ -16,8 +16,8 @@ class ResourceMonitorThread : public thread ResourceMonitorThread(F&& f, Args&&... args): thread(ResourceMonitorThread::wrapper, forward(f), forward(args)...){}; private: - static uint64_t threadStartTime; - static double cpuStartTime; + thread_local static uint64_t threadStartTime; + thread_local static double cpuStartTime; static void beforeProcessStart(); static void afterProcessFinished();