From c8505cb6ce1b44e0e4e381e915010a70de5dc25e Mon Sep 17 00:00:00 2001 From: lzydmxy <13126752315@163.com> Date: Tue, 3 Sep 2024 20:08:25 +0800 Subject: [PATCH 1/2] Fix error max latency # Conflicts: # src/Service/Metrics.h --- src/Service/ConnectionHandler.cpp | 34 +++++++++++++++++++++--------- src/Service/KeeperDispatcher.cpp | 8 +++---- src/Service/Metrics.h | 2 +- src/Service/NuRaftStateMachine.cpp | 2 +- 4 files changed, 30 insertions(+), 16 deletions(-) diff --git a/src/Service/ConnectionHandler.cpp b/src/Service/ConnectionHandler.cpp index 02f2614e70..ed767f26cc 100644 --- a/src/Service/ConnectionHandler.cpp +++ b/src/Service/ConnectionHandler.cpp @@ -687,20 +687,34 @@ void ConnectionHandler::updateStats(const Coordination::ZooKeeperResponsePtr & r if (response->xid != Coordination::WATCH_XID && response->getOpNum() != Coordination::OpNum::Heartbeat && response->getOpNum() != Coordination::OpNum::SetWatches && response->getOpNum() != Coordination::OpNum::Close) { - Int64 elapsed = Poco::Timestamp().epochMicroseconds() / 1000 - response->request_created_time_ms; + auto current_time = getCurrentTimeMilliseconds(); + Int64 elapsed = current_time - response->request_created_time_ms; + if (elapsed < 0) { - conn_stats.updateLatency(elapsed); - if (unlikely(elapsed > 10000)) - LOG_WARNING( - log, - "Slow request detected #{}#{}#{}, time costs {}ms, please take care.", - toHexString(session_id.load()), - response->xid, - Coordination::toString(response->getOpNum()), - elapsed); + LOG_WARNING( + log, + "Request #{}#{}#{} finish time {} is before than created time {}, please take care.", + toHexString(session_id.load()), + response->xid, + Coordination::toString(response->getOpNum()), + current_time, + response->request_created_time_ms); + elapsed = 0; } + + conn_stats.updateLatency(elapsed); + if (unlikely(elapsed > 10000)) + LOG_WARNING( + log, + "Slow request detected #{}#{}#{}, time costs {}ms, please take care.", + toHexString(session_id.load()), + response->xid, + Coordination::toString(response->getOpNum()), + elapsed); + keeper_dispatcher->updateKeeperStatLatency(elapsed); + last_op.set(std::make_unique(LastOp{ .name = Coordination::toString(response->getOpNum()), .last_cxid = response->xid, diff --git a/src/Service/KeeperDispatcher.cpp b/src/Service/KeeperDispatcher.cpp index 7ef3bb4418..783084dd87 100644 --- a/src/Service/KeeperDispatcher.cpp +++ b/src/Service/KeeperDispatcher.cpp @@ -170,7 +170,7 @@ bool KeeperDispatcher::pushSessionRequest(const Coordination::ZooKeeperRequestPt request_info.session_id = internal_id; using namespace std::chrono; - request_info.create_time = duration_cast(system_clock::now().time_since_epoch()).count(); + request_info.create_time = getCurrentTimeMilliseconds(); LOG_TRACE( log, @@ -198,7 +198,7 @@ bool KeeperDispatcher::pushRequest(const Coordination::ZooKeeperRequestPtr & req request_info.session_id = session_id; using namespace std::chrono; - request_info.create_time = duration_cast(system_clock::now().time_since_epoch()).count(); + request_info.create_time = getCurrentTimeMilliseconds(); LOG_TRACE(log, "Push user request #{}#{}#{}", toHexString(session_id), request->xid, Coordination::toString(request->getOpNum())); /// Put close requests without timeouts @@ -220,7 +220,7 @@ bool KeeperDispatcher::pushForwardRequest(size_t server_id, size_t client_id, Fo RequestForSession && request_info = request->requestForSession(); using namespace std::chrono; - request_info.create_time = duration_cast(system_clock::now().time_since_epoch()).count(); + request_info.create_time = getCurrentTimeMilliseconds(); request_info.server_id = server_id; request_info.client_id = client_id; @@ -460,7 +460,7 @@ void KeeperDispatcher::deadSessionCleanThread() request_info.session_id = dead_session; // request_info.is_internal = true; using namespace std::chrono; - request_info.create_time = duration_cast(system_clock::now().time_since_epoch()).count(); + request_info.create_time = getCurrentTimeMilliseconds(); { std::lock_guard lock(push_request_mutex); if (!requests_queue->push(std::move(request_info))) diff --git a/src/Service/Metrics.h b/src/Service/Metrics.h index a55ded4060..cf07b8b420 100644 --- a/src/Service/Metrics.h +++ b/src/Service/Metrics.h @@ -15,7 +15,7 @@ namespace RK inline UInt64 getCurrentTimeMilliseconds() { - return duration_cast(std::chrono::system_clock::now().time_since_epoch()).count(); + return duration_cast(std::chrono::steady_clock::now().time_since_epoch()).count(); }; diff --git a/src/Service/NuRaftStateMachine.cpp b/src/Service/NuRaftStateMachine.cpp index c44775ff3e..01eea466be 100644 --- a/src/Service/NuRaftStateMachine.cpp +++ b/src/Service/NuRaftStateMachine.cpp @@ -147,7 +147,7 @@ ptr NuRaftStateMachine::createRequestSession(ptr & request_for_session->request->readImpl(buffer); if (buffer.eof()) - request_for_session->create_time = std::chrono::system_clock::now().time_since_epoch() / std::chrono::milliseconds(1); + request_for_session->create_time = getCurrentTimeMilliseconds(); else Coordination::read(request_for_session->create_time, buffer); From 63e5833d0a1d1ded724d30fb92a556746ae4b66a Mon Sep 17 00:00:00 2001 From: lzydmxy <13126752315@163.com> Date: Wed, 4 Sep 2024 17:18:17 +0800 Subject: [PATCH 2/2] Add comment for request elapsed --- src/Service/ConnectionHandler.cpp | 23 +++++++---------------- 1 file changed, 7 insertions(+), 16 deletions(-) diff --git a/src/Service/ConnectionHandler.cpp b/src/Service/ConnectionHandler.cpp index ed767f26cc..69ba7d5fbf 100644 --- a/src/Service/ConnectionHandler.cpp +++ b/src/Service/ConnectionHandler.cpp @@ -1,9 +1,9 @@ -#include "ConnectionHandler.h" +#include #include - #include +#include #include #include #include @@ -687,20 +687,11 @@ void ConnectionHandler::updateStats(const Coordination::ZooKeeperResponsePtr & r if (response->xid != Coordination::WATCH_XID && response->getOpNum() != Coordination::OpNum::Heartbeat && response->getOpNum() != Coordination::OpNum::SetWatches && response->getOpNum() != Coordination::OpNum::Close) { - auto current_time = getCurrentTimeMilliseconds(); - Int64 elapsed = current_time - response->request_created_time_ms; - if (elapsed < 0) - { - LOG_WARNING( - log, - "Request #{}#{}#{} finish time {} is before than created time {}, please take care.", - toHexString(session_id.load()), - response->xid, - Coordination::toString(response->getOpNum()), - current_time, - response->request_created_time_ms); - elapsed = 0; - } + const auto current_time = getCurrentTimeMilliseconds(); + // Use std::chrono::steady_clock to calculate elapsed time. + // If current_time is earlier than create_time, assume current_time is incorrect and set elapsed to zero. + // Otherwise, calculate the elapsed time. + Int64 elapsed = current_time < response->request_created_time_ms ? 0 : current_time - response->request_created_time_ms; conn_stats.updateLatency(elapsed); if (unlikely(elapsed > 10000))