From b2193b43bbf8604ff72f4fdf66e2b33fa73a871c Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Mon, 25 Mar 2024 01:30:01 +0300 Subject: [PATCH 01/33] Fix proxy processing time for pinned connections [http]::clearError(); - request->hier.startPeerClock(); - const auto callback = asyncCallback(17, 5, FwdState::noteConnection, this); HttpRequest::Pointer cause = request; const auto cs = new HappyConnOpener(destinations, callback, cause, start_t, n_tries, al); diff --git a/src/FwdState.h b/src/FwdState.h index c435609e3bc..dbe76168cee 100644 --- a/src/FwdState.h +++ b/src/FwdState.h @@ -184,6 +184,7 @@ class FwdState: public RefCountable, public PeerSelectionInitiator bool dont_retry; bool forward_completed; bool destinationsFound; ///< at least one candidate path found + bool tunneled; ///< \copydoc Security::EncryptorAnswer::tunneled } flags; /// waits for a transport connection to the peer to be established/opened diff --git a/src/cf.data.pre b/src/cf.data.pre index 48e40882ab1..74c1d433682 100644 --- a/src/cf.data.pre +++ b/src/cf.data.pre @@ -4980,8 +4980,7 @@ DOC_START when the last request byte is sent to the next hop and stops when the last response byte is received. [http::]server.setDelayId(DelayId::DelayClient(http)); #endif + + request->hier.startPeerClock(); + tunnelState->startSelectingDestinations(request, http->al, nullptr); } @@ -1430,9 +1433,6 @@ TunnelStateData::cancelStep(const char *reason) void TunnelStateData::startConnecting() { - if (request) - request->hier.startPeerClock(); - assert(!destinations->empty()); assert(!transporting()); From 2313710b061cc5f7079d75f75c4a583b39538083 Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Mon, 25 Mar 2024 17:49:42 +0300 Subject: [PATCH 02/33] Moved startPeerClock()/stopPeerClock() into constructor/destructor --- src/FwdState.cc | 6 +++--- src/FwdState.h | 3 ++- src/tunnel.cc | 4 ++-- 3 files changed, 7 insertions(+), 6 deletions(-) diff --git a/src/FwdState.cc b/src/FwdState.cc index 23c7cfbff1f..e905b5b5416 100644 --- a/src/FwdState.cc +++ b/src/FwdState.cc @@ -189,6 +189,9 @@ FwdState::stopAndDestroy(const char *reason) cancelStep(reason); + if (!flags.tunneled) + request->hier.stopPeerClock(false); + PeerSelectionInitiator::subscribed = false; // may already be false self = nullptr; // we hope refcounting destroys us soon; may already be nil /* do not place any code here as this object may be gone by now */ @@ -262,9 +265,6 @@ FwdState::completed() flags.forward_completed = true; - if (!flags.tunneled) - request->hier.stopPeerClock(false); - if (EBIT_TEST(entry->flags, ENTRY_ABORTED)) { debugs(17, 3, "entry aborted"); return ; diff --git a/src/FwdState.h b/src/FwdState.h index dbe76168cee..c50546d9975 100644 --- a/src/FwdState.h +++ b/src/FwdState.h @@ -184,7 +184,8 @@ class FwdState: public RefCountable, public PeerSelectionInitiator bool dont_retry; bool forward_completed; bool destinationsFound; ///< at least one candidate path found - bool tunneled; ///< \copydoc Security::EncryptorAnswer::tunneled + /// Security::PeerConnector dispatched this request (instead of returning control to us) + bool tunneled; } flags; /// waits for a transport connection to the peer to be established/opened diff --git a/src/tunnel.cc b/src/tunnel.cc index e0a037ebfe2..63dfec213dc 100644 --- a/src/tunnel.cc +++ b/src/tunnel.cc @@ -416,6 +416,8 @@ TunnelStateData::TunnelStateData(ClientHttpRequest *clientRequest) : AsyncCall::Pointer timeoutCall = commCbCall(5, 4, "tunnelTimeout", CommTimeoutCbPtrFun(tunnelTimeout, this)); commSetConnTimeout(client.conn, Config.Timeout.lifetime, timeoutCall); + + request->hier.startPeerClock(); } TunnelStateData::~TunnelStateData() @@ -1212,8 +1214,6 @@ tunnelStart(ClientHttpRequest * http) tunnelState->server.setDelayId(DelayId::DelayClient(http)); #endif - request->hier.startPeerClock(); - tunnelState->startSelectingDestinations(request, http->al, nullptr); } From 8688bb5bff41c35167c0b3c4f7bd0a461612d309 Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Tue, 26 Mar 2024 01:28:40 +0300 Subject: [PATCH 03/33] Removed an excessive stopPeerClock() from FwdState::retryOrBail() and a couple of polishing changes. --- src/FwdState.cc | 3 +-- src/tunnel.cc | 8 ++++---- 2 files changed, 5 insertions(+), 6 deletions(-) diff --git a/src/FwdState.cc b/src/FwdState.cc index e905b5b5416..91f41dc0dd1 100644 --- a/src/FwdState.cc +++ b/src/FwdState.cc @@ -163,6 +163,7 @@ void FwdState::start(Pointer aSelf) // just in case; should already be initialized to false request->flags.pinned = false; + // start the clock just before any peer communication request->hier.startPeerClock(); #if STRICT_ORIGINAL_DST @@ -780,8 +781,6 @@ FwdState::retryOrBail() // TODO: should we call completed() here and move doneWithRetries there? doneWithRetries(); - request->hier.stopPeerClock(false); - if (self != nullptr && !err && shutting_down && entry->isEmpty()) { const auto anErr = new ErrorState(ERR_SHUTTING_DOWN, Http::scServiceUnavailable, request, al); errorAppendEntry(entry, anErr); diff --git a/src/tunnel.cc b/src/tunnel.cc index 63dfec213dc..f4ffa8b392b 100644 --- a/src/tunnel.cc +++ b/src/tunnel.cc @@ -417,6 +417,7 @@ TunnelStateData::TunnelStateData(ClientHttpRequest *clientRequest) : CommTimeoutCbPtrFun(tunnelTimeout, this)); commSetConnTimeout(client.conn, Config.Timeout.lifetime, timeoutCall); + // could have been started already request->hier.startPeerClock(); } @@ -479,9 +480,6 @@ TunnelStateData::retryOrBail(const char *context) /* bail */ - if (request) - request->hier.stopPeerClock(false); - // TODO: Add sendSavedErrorOr(err_type type, Http::StatusCode, context). // Then, the remaining method code (below) should become the common part of // sendNewError() and sendSavedErrorOr(), used in "error detected" cases. @@ -493,6 +491,9 @@ TunnelStateData::retryOrBail(const char *context) return sendError(savedError, bailDescription ? bailDescription : context); *status_ptr = savedError->httpStatus; + if (request) + request->hier.stopPeerClock(false); + finishWritingAndDelete(client); } @@ -1213,7 +1214,6 @@ tunnelStart(ClientHttpRequest * http) #if USE_DELAY_POOLS tunnelState->server.setDelayId(DelayId::DelayClient(http)); #endif - tunnelState->startSelectingDestinations(request, http->al, nullptr); } From 9ee4c5aad03dee5c5952aca872606d43b10b5f7c Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Thu, 28 Mar 2024 15:06:00 +0300 Subject: [PATCH 04/33] Drop nil checks for always-present TunnelStateData::request and a couple of polishing changes. --- src/cf.data.pre | 3 ++- src/tunnel.cc | 12 +++++------- 2 files changed, 7 insertions(+), 8 deletions(-) diff --git a/src/cf.data.pre b/src/cf.data.pre index 74c1d433682..66ddddeb44a 100644 --- a/src/cf.data.pre +++ b/src/cf.data.pre @@ -4981,7 +4981,8 @@ DOC_START and stops when the last response byte is received. [http::]hier.startPeerClock(); + request->hier.startPeerClock(); // could have been started already } TunnelStateData::~TunnelStateData() @@ -480,6 +479,9 @@ TunnelStateData::retryOrBail(const char *context) /* bail */ + if (request) + request->hier.stopPeerClock(false); + // TODO: Add sendSavedErrorOr(err_type type, Http::StatusCode, context). // Then, the remaining method code (below) should become the common part of // sendNewError() and sendSavedErrorOr(), used in "error detected" cases. @@ -491,9 +493,6 @@ TunnelStateData::retryOrBail(const char *context) return sendError(savedError, bailDescription ? bailDescription : context); *status_ptr = savedError->httpStatus; - if (request) - request->hier.stopPeerClock(false); - finishWritingAndDelete(client); } @@ -1398,8 +1397,7 @@ TunnelStateData::sendError(ErrorState *finalError, const char *reason) { debugs(26, 3, "aborting transaction for " << reason); - if (request) - request->hier.stopPeerClock(false); + request->hier.stopPeerClock(false); cancelStep(reason); From c83433111d173ed22dd02c40079fb5cbc8c539b9 Mon Sep 17 00:00:00 2001 From: Alex Rousskov Date: Thu, 28 Mar 2024 09:56:55 -0400 Subject: [PATCH 05/33] Documented the effects of secondary activities and re-forwarding Also documented what should happen when the %code is used before the timer stops. XXX: That is not what happens right now. --- src/cf.data.pre | 30 ++++++++++++++++++++++++++---- 1 file changed, 26 insertions(+), 4 deletions(-) diff --git a/src/cf.data.pre b/src/cf.data.pre index 66ddddeb44a..9674dbed6ff 100644 --- a/src/cf.data.pre +++ b/src/cf.data.pre @@ -4979,10 +4979,32 @@ DOC_START [http::] Date: Thu, 4 Apr 2024 17:57:34 +0300 Subject: [PATCH 06/33] Using Stopwatch for totalResponseTime() calculation --- src/FwdState.cc | 2 +- src/HierarchyLogEntry.h | 9 ++++---- src/clients/Client.cc | 2 +- src/format/Format.cc | 8 ++++--- src/log/access_log.cc | 41 +++++++++++------------------------- src/tests/stub_access_log.cc | 3 ++- src/tunnel.cc | 6 +++--- 7 files changed, 28 insertions(+), 43 deletions(-) diff --git a/src/FwdState.cc b/src/FwdState.cc index 91f41dc0dd1..a090d4901fd 100644 --- a/src/FwdState.cc +++ b/src/FwdState.cc @@ -191,7 +191,7 @@ FwdState::stopAndDestroy(const char *reason) cancelStep(reason); if (!flags.tunneled) - request->hier.stopPeerClock(false); + request->hier.stopPeerClock(); PeerSelectionInitiator::subscribed = false; // may already be false self = nullptr; // we hope refcounting destroys us soon; may already be nil diff --git a/src/HierarchyLogEntry.h b/src/HierarchyLogEntry.h index 5f5d8b13f41..b65f9fdfaf7 100644 --- a/src/HierarchyLogEntry.h +++ b/src/HierarchyLogEntry.h @@ -9,6 +9,7 @@ #ifndef SQUID_SRC_HIERARCHYLOGENTRY_H #define SQUID_SRC_HIERARCHYLOGENTRY_H +#include "base/Stopwatch.h" #include "comm/Connection.h" #include "enums.h" #include "hier_code.h" @@ -43,15 +44,14 @@ class HierarchyLogEntry * Record total time spent communicating with peers * \param force whether to overwrite old recorded value if any */ - void stopPeerClock(const bool force); + void stopPeerClock(); /// Estimates response generation and sending delay at the last peer. /// \returns whether the estimate (stored in `responseTime`) is available. bool peerResponseTime(struct timeval &responseTime); /// Estimates the total time spent communicating with peers. - /// \returns whether the estimate (stored in `responseTime`) is available. - bool totalResponseTime(struct timeval &responseTime); + const Stopwatch &totalResponseTime() const { return peerTimer; } public: hier_code code; @@ -73,10 +73,9 @@ class HierarchyLogEntry private: void clearPeerNotes(); - timeval firstConnStart_; ///< first connection use among all peers struct timeval peer_last_read_; ///< time of the last read from the last peer struct timeval peer_last_write_; ///< time of the last write to the last peer - struct timeval totalResponseTime_; ///< cumulative for all peers + Stopwatch peerTimer; ///< cumulative for all peers }; #endif /* SQUID_SRC_HIERARCHYLOGENTRY_H */ diff --git a/src/clients/Client.cc b/src/clients/Client.cc index 60ab7d08781..c21319c8d2c 100644 --- a/src/clients/Client.cc +++ b/src/clients/Client.cc @@ -187,7 +187,7 @@ Client::serverComplete() } completed = true; - originalRequest()->hier.stopPeerClock(true); + originalRequest()->hier.stopPeerClock(); if (requestBodySource != nullptr) stopConsumingFrom(requestBodySource); diff --git a/src/format/Format.cc b/src/format/Format.cc index abd919c5aae..28b3eab2a48 100644 --- a/src/format/Format.cc +++ b/src/format/Format.cc @@ -635,9 +635,11 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS break; case LFT_TOTAL_SERVER_SIDE_RESPONSE_TIME: { - struct timeval totalResponseTime; - if (al->hier.totalResponseTime(totalResponseTime)) { - outtv = totalResponseTime; + const auto &timer = al->hier.totalResponseTime(); + if (timer.ran()) { + const auto ms = std::chrono::duration_cast(timer.total()); + outtv.tv_sec = ms.count() / 1000; + outtv.tv_usec = (ms.count() % 1000) * 1000; doMsec = 1; } } diff --git a/src/log/access_log.cc b/src/log/access_log.cc index 4dcc6f659a9..bf24a94b3c3 100644 --- a/src/log/access_log.cc +++ b/src/log/access_log.cc @@ -187,12 +187,6 @@ HierarchyLogEntry::HierarchyLogEntry() : store_complete_stop.tv_usec =0; clearPeerNotes(); - - totalResponseTime_.tv_sec = -1; - totalResponseTime_.tv_usec = 0; - - firstConnStart_.tv_sec = 0; - firstConnStart_.tv_usec = 0; } void @@ -244,21 +238,23 @@ HierarchyLogEntry::notePeerWrite() void HierarchyLogEntry::startPeerClock() { - if (!firstConnStart_.tv_sec) - firstConnStart_ = current_time; + if (peerTimer.running()) { + debugs(46, 5, "already running"); + return; + } + peerTimer.resume(); } void -HierarchyLogEntry::stopPeerClock(const bool force) +HierarchyLogEntry::stopPeerClock() { - debugs(46, 5, "First connection started: " << firstConnStart_ << - ", current total response time value: " << (totalResponseTime_.tv_sec * 1000 + totalResponseTime_.tv_usec/1000) << - (force ? ", force fixing" : "")); - if (!force && totalResponseTime_.tv_sec != -1) + if (!peerTimer.running()) { + debugs(46, 5, "already stopped"); return; - - if (firstConnStart_.tv_sec) - tvSub(totalResponseTime_, firstConnStart_, current_time); + } + peerTimer.pause(); + const auto elapsed = std::chrono::duration_cast(peerTimer.total()); + debugs(46, 5, "elapsed " << elapsed.count() << "ms"); } bool @@ -288,19 +284,6 @@ HierarchyLogEntry::peerResponseTime(struct timeval &responseTime) return true; } -bool -HierarchyLogEntry::totalResponseTime(struct timeval &responseTime) -{ - // This should not really happen, but there may be rare code - // paths that lead to FwdState discarded (or transaction logged) - // without (or before) a stopPeerClock() call. - if (firstConnStart_.tv_sec && totalResponseTime_.tv_sec == -1) - stopPeerClock(false); - - responseTime = totalResponseTime_; - return responseTime.tv_sec >= 0 && responseTime.tv_usec >= 0; -} - static void accessLogRegisterWithCacheManager(void) { diff --git a/src/tests/stub_access_log.cc b/src/tests/stub_access_log.cc index 93bfd75174f..c06c0ec01a7 100644 --- a/src/tests/stub_access_log.cc +++ b/src/tests/stub_access_log.cc @@ -17,7 +17,8 @@ HierarchyLogEntry::HierarchyLogEntry() STUB void HierarchyLogEntry::notePeerRead() STUB void HierarchyLogEntry::notePeerWrite() STUB bool HierarchyLogEntry::peerResponseTime(struct timeval &) STUB_RETVAL(false) -bool HierarchyLogEntry::totalResponseTime(struct timeval &) STUB_RETVAL(false) +static Stopwatch static_Stopwatch; +const Stopwatch &HierarchyLogEntry::totalResponseTime() const STUB_RETVAL(static_Stopwatch) ping_data::ping_data() : n_sent(0), diff --git a/src/tunnel.cc b/src/tunnel.cc index 7c3958f280e..db40c9eac47 100644 --- a/src/tunnel.cc +++ b/src/tunnel.cc @@ -310,7 +310,7 @@ TunnelStateData::serverClosed() { server.noteClosure(); - request->hier.stopPeerClock(false); + request->hier.stopPeerClock(); finishWritingAndDelete(client); } @@ -480,7 +480,7 @@ TunnelStateData::retryOrBail(const char *context) /* bail */ if (request) - request->hier.stopPeerClock(false); + request->hier.stopPeerClock(); // TODO: Add sendSavedErrorOr(err_type type, Http::StatusCode, context). // Then, the remaining method code (below) should become the common part of @@ -1397,7 +1397,7 @@ TunnelStateData::sendError(ErrorState *finalError, const char *reason) { debugs(26, 3, "aborting transaction for " << reason); - request->hier.stopPeerClock(false); + request->hier.stopPeerClock(); cancelStep(reason); From 182b68266ae1a98e8d756b3adb7f2f5c04de6b64 Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Mon, 8 Apr 2024 16:38:23 +0300 Subject: [PATCH 07/33] Removed an excessive stopPeerClock() The only stopPeerClock() left is in FwdState::stopAndDestroy(), which covers all cases (sucess, error) when communication with the last peer terminates. --- src/clients/Client.cc | 1 - 1 file changed, 1 deletion(-) diff --git a/src/clients/Client.cc b/src/clients/Client.cc index c21319c8d2c..e517473c7de 100644 --- a/src/clients/Client.cc +++ b/src/clients/Client.cc @@ -187,7 +187,6 @@ Client::serverComplete() } completed = true; - originalRequest()->hier.stopPeerClock(); if (requestBodySource != nullptr) stopConsumingFrom(requestBodySource); From a2c176fb5fb0bd83dac464dc13a1e3534ecff9d0 Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Tue, 9 Apr 2024 17:43:47 +0300 Subject: [PATCH 08/33] Adjusted documentation --- src/cf.data.pre | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/src/cf.data.pre b/src/cf.data.pre index 9674dbed6ff..104d12e530b 100644 --- a/src/cf.data.pre +++ b/src/cf.data.pre @@ -5002,9 +5002,10 @@ DOC_START When Squid re-forwards the request (e.g., due to an HTTP 304 response indicating that the cached response is stale), the - timer may restart. When a stopped timer restarts, the time - passed since the timer was stopped is added to the - measurement, as if the timer has not stopped. + timer may restart. In this case, the new measurement is added + to the value accumulated from previous forwarding attempts. + The time interval between forwarding attempts is not added + to the final result. Squid handling related format codes: From c2637ca36034cbb67c5375fb90785494739b7e56 Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Tue, 9 Apr 2024 21:33:37 +0300 Subject: [PATCH 09/33] Fixed unit tests --- src/tests/stub_access_log.cc | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/tests/stub_access_log.cc b/src/tests/stub_access_log.cc index c06c0ec01a7..8dbed03787f 100644 --- a/src/tests/stub_access_log.cc +++ b/src/tests/stub_access_log.cc @@ -17,8 +17,6 @@ HierarchyLogEntry::HierarchyLogEntry() STUB void HierarchyLogEntry::notePeerRead() STUB void HierarchyLogEntry::notePeerWrite() STUB bool HierarchyLogEntry::peerResponseTime(struct timeval &) STUB_RETVAL(false) -static Stopwatch static_Stopwatch; -const Stopwatch &HierarchyLogEntry::totalResponseTime() const STUB_RETVAL(static_Stopwatch) ping_data::ping_data() : n_sent(0), From 94bb99b93618c33805f079fef17d62d1af221d5d Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Thu, 11 Apr 2024 17:58:26 +0300 Subject: [PATCH 10/33] Overcome the unassigned ALE totalResponseTime() In this temporary approach the time is taken from HttpRequest::hier. Also polished and simplified. --- src/HierarchyLogEntry.h | 8 ++++---- src/format/Format.cc | 13 +++++++++---- src/log/access_log.cc | 22 ---------------------- 3 files changed, 13 insertions(+), 30 deletions(-) diff --git a/src/HierarchyLogEntry.h b/src/HierarchyLogEntry.h index b65f9fdfaf7..c98276e52ca 100644 --- a/src/HierarchyLogEntry.h +++ b/src/HierarchyLogEntry.h @@ -39,19 +39,19 @@ class HierarchyLogEntry void notePeerWrite(); /// Start recording total time spent communicating with peers - void startPeerClock(); + void startPeerClock() { peeringTime_.resume(); } /** * Record total time spent communicating with peers * \param force whether to overwrite old recorded value if any */ - void stopPeerClock(); + void stopPeerClock() { peeringTime_.pause(); } /// Estimates response generation and sending delay at the last peer. /// \returns whether the estimate (stored in `responseTime`) is available. bool peerResponseTime(struct timeval &responseTime); /// Estimates the total time spent communicating with peers. - const Stopwatch &totalResponseTime() const { return peerTimer; } + const Stopwatch &totalResponseTime() const { return peeringTime_; } public: hier_code code; @@ -75,7 +75,7 @@ class HierarchyLogEntry struct timeval peer_last_read_; ///< time of the last read from the last peer struct timeval peer_last_write_; ///< time of the last write to the last peer - Stopwatch peerTimer; ///< cumulative for all peers + Stopwatch peeringTime_; ///< cumulative for all peers and any revalidations (see %hier.totalResponseTime(); + // al->hier.totalResponseTime() is unassigned before prepareLogWithRequestDetails() + // TODO: keep the total response time in one place. + const auto &timer = al->hier.totalResponseTime().ran() ? al->hier.totalResponseTime() : al->request->hier.totalResponseTime(); if (timer.ran()) { - const auto ms = std::chrono::duration_cast(timer.total()); - outtv.tv_sec = ms.count() / 1000; - outtv.tv_usec = (ms.count() % 1000) * 1000; + auto duration = timer.total(); + const auto seconds = std::chrono::duration_cast(timer.total()); + duration -= seconds; + const auto ms = std::chrono::duration_cast(duration); + outtv.tv_sec = seconds.count(); + outtv.tv_usec = ms.count(); doMsec = 1; } } diff --git a/src/log/access_log.cc b/src/log/access_log.cc index bf24a94b3c3..c93fd0cd809 100644 --- a/src/log/access_log.cc +++ b/src/log/access_log.cc @@ -235,28 +235,6 @@ HierarchyLogEntry::notePeerWrite() peer_last_write_ = current_time; } -void -HierarchyLogEntry::startPeerClock() -{ - if (peerTimer.running()) { - debugs(46, 5, "already running"); - return; - } - peerTimer.resume(); -} - -void -HierarchyLogEntry::stopPeerClock() -{ - if (!peerTimer.running()) { - debugs(46, 5, "already stopped"); - return; - } - peerTimer.pause(); - const auto elapsed = std::chrono::duration_cast(peerTimer.total()); - debugs(46, 5, "elapsed " << elapsed.count() << "ms"); -} - bool HierarchyLogEntry::peerResponseTime(struct timeval &responseTime) { From 0a2b9b484adf99f220a4e3098ab6aa78be7eccd1 Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Sun, 14 Apr 2024 22:46:34 +0300 Subject: [PATCH 11/33] A couple of fixes * do not dereference a possibly nil al->request * optimized %hier.totalResponseTime() is unassigned before prepareLogWithRequestDetails() // TODO: keep the total response time in one place. - const auto &timer = al->hier.totalResponseTime().ran() ? al->hier.totalResponseTime() : al->request->hier.totalResponseTime(); + const auto &timer = (!al->hier.totalResponseTime().ran() && al->request) ? + al->request->hier.totalResponseTime() : al->hier.totalResponseTime(); if (timer.ran()) { - auto duration = timer.total(); - const auto seconds = std::chrono::duration_cast(timer.total()); - duration -= seconds; - const auto ms = std::chrono::duration_cast(duration); - outtv.tv_sec = seconds.count(); - outtv.tv_usec = ms.count(); + const auto duration = timer.total(); + outtv.tv_sec = std::chrono::duration_cast(timer.total()).count(); + const auto totalMs = std::chrono::duration_cast(duration).count(); + outtv.tv_usec = outtv.tv_sec ? totalMs % outtv.tv_sec : totalMs; doMsec = 1; } } From 9e192dc07186fa78f2d55ee1923efb1366993955 Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Tue, 16 Apr 2024 15:40:19 +0300 Subject: [PATCH 12/33] Fixed LFT_TOTAL_SERVER_SIDE_RESPONSE_TIME calculation --- src/format/Format.cc | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/src/format/Format.cc b/src/format/Format.cc index 218267d594e..43a4cb23cf6 100644 --- a/src/format/Format.cc +++ b/src/format/Format.cc @@ -640,10 +640,12 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS const auto &timer = (!al->hier.totalResponseTime().ran() && al->request) ? al->request->hier.totalResponseTime() : al->hier.totalResponseTime(); if (timer.ran()) { + using namespace std::chrono_literals; const auto duration = timer.total(); - outtv.tv_sec = std::chrono::duration_cast(timer.total()).count(); - const auto totalMs = std::chrono::duration_cast(duration).count(); - outtv.tv_usec = outtv.tv_sec ? totalMs % outtv.tv_sec : totalMs; + outtv.tv_sec = std::chrono::duration_cast(duration).count(); + const auto totalUsec = std::chrono::duration_cast(duration); + static const std::chrono::microseconds secondUsec = 1s; + outtv.tv_usec = totalUsec.count() % secondUsec.count(); doMsec = 1; } } From c8ac2b71d5f202460579762b2242736198476aeb Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Tue, 16 Apr 2024 17:28:10 +0300 Subject: [PATCH 13/33] Renamed startPeerClock()/stopPeerClock() and adjused documentation --- src/FwdState.cc | 4 ++-- src/HierarchyLogEntry.h | 12 +++++------- src/tunnel.cc | 10 +++++----- 3 files changed, 12 insertions(+), 14 deletions(-) diff --git a/src/FwdState.cc b/src/FwdState.cc index a090d4901fd..239d38d9e0f 100644 --- a/src/FwdState.cc +++ b/src/FwdState.cc @@ -164,7 +164,7 @@ void FwdState::start(Pointer aSelf) request->flags.pinned = false; // start the clock just before any peer communication - request->hier.startPeerClock(); + request->hier.startPeering(); #if STRICT_ORIGINAL_DST // Bug 3243: CVE 2009-0801 @@ -191,7 +191,7 @@ FwdState::stopAndDestroy(const char *reason) cancelStep(reason); if (!flags.tunneled) - request->hier.stopPeerClock(); + request->hier.stopPeering(); PeerSelectionInitiator::subscribed = false; // may already be false self = nullptr; // we hope refcounting destroys us soon; may already be nil diff --git a/src/HierarchyLogEntry.h b/src/HierarchyLogEntry.h index c98276e52ca..c83c44efd22 100644 --- a/src/HierarchyLogEntry.h +++ b/src/HierarchyLogEntry.h @@ -38,13 +38,11 @@ class HierarchyLogEntry /// Call this after each peer socket write(2), including failed ones. void notePeerWrite(); - /// Start recording total time spent communicating with peers - void startPeerClock() { peeringTime_.resume(); } - /** - * Record total time spent communicating with peers - * \param force whether to overwrite old recorded value if any - */ - void stopPeerClock() { peeringTime_.pause(); } + /// Start or resume recording time spent on selecting and communicating with peers. + void startPeering() { peeringTime_.resume(); } + + /// Pause recording after a startPeering() call. + void stopPeering() { if (peeringTime_.running()) { peeringTime_.pause(); } } /// Estimates response generation and sending delay at the last peer. /// \returns whether the estimate (stored in `responseTime`) is available. diff --git a/src/tunnel.cc b/src/tunnel.cc index db40c9eac47..c135031a551 100644 --- a/src/tunnel.cc +++ b/src/tunnel.cc @@ -310,7 +310,7 @@ TunnelStateData::serverClosed() { server.noteClosure(); - request->hier.stopPeerClock(); + request->hier.stopPeering(); finishWritingAndDelete(client); } @@ -417,7 +417,7 @@ TunnelStateData::TunnelStateData(ClientHttpRequest *clientRequest) : CommTimeoutCbPtrFun(tunnelTimeout, this)); commSetConnTimeout(client.conn, Config.Timeout.lifetime, timeoutCall); - request->hier.startPeerClock(); // could have been started already + request->hier.startPeering(); // could have been started already } TunnelStateData::~TunnelStateData() @@ -480,7 +480,7 @@ TunnelStateData::retryOrBail(const char *context) /* bail */ if (request) - request->hier.stopPeerClock(); + request->hier.stopPeering(); // TODO: Add sendSavedErrorOr(err_type type, Http::StatusCode, context). // Then, the remaining method code (below) should become the common part of @@ -1397,7 +1397,7 @@ TunnelStateData::sendError(ErrorState *finalError, const char *reason) { debugs(26, 3, "aborting transaction for " << reason); - request->hier.stopPeerClock(); + request->hier.stopPeering(); cancelStep(reason); @@ -1436,7 +1436,7 @@ TunnelStateData::startConnecting() delete savedError; // may still be nil savedError = nullptr; - request->hier.peer_reply_status = Http::scNone; // TODO: Move to startPeerClock()? + request->hier.peer_reply_status = Http::scNone; // TODO: Move to startPeering()? const auto callback = asyncCallback(17, 5, TunnelStateData::noteConnection, this); const auto cs = new HappyConnOpener(destinations, callback, request, startTime, n_tries, al); From 5fb6a31118f96d636ca8174efa651c092e019b77 Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Tue, 16 Apr 2024 17:34:16 +0300 Subject: [PATCH 14/33] Removed the branch-added tunneled flag We do not need this flag anymore since Stopwatch can track multiple resumes and pauses. --- src/FwdState.cc | 5 +---- src/FwdState.h | 2 -- 2 files changed, 1 insertion(+), 6 deletions(-) diff --git a/src/FwdState.cc b/src/FwdState.cc index 239d38d9e0f..9a47839cf82 100644 --- a/src/FwdState.cc +++ b/src/FwdState.cc @@ -137,7 +137,6 @@ FwdState::FwdState(const Comm::ConnectionPointer &client, StoreEntry * e, HttpRe flags.dont_retry = false; flags.forward_completed = false; flags.destinationsFound = false; - flags.tunneled = false; debugs(17, 3, "FwdState constructed, this=" << this); } @@ -190,8 +189,7 @@ FwdState::stopAndDestroy(const char *reason) cancelStep(reason); - if (!flags.tunneled) - request->hier.stopPeering(); + request->hier.stopPeering(); PeerSelectionInitiator::subscribed = false; // may already be false self = nullptr; // we hope refcounting destroys us soon; may already be nil @@ -1021,7 +1019,6 @@ FwdState::connectedToPeer(Security::EncryptorAnswer &answer) answer.error.clear(); // preserve error for errorSendComplete() } else if (answer.tunneled) { assert(!answer.conn); - flags.tunneled = true; // TODO: When ConnStateData establishes tunnels, its state changes // [in ways that may affect logging?]. Consider informing // ConnStateData about our tunnel or otherwise unifying tunnel diff --git a/src/FwdState.h b/src/FwdState.h index c50546d9975..c435609e3bc 100644 --- a/src/FwdState.h +++ b/src/FwdState.h @@ -184,8 +184,6 @@ class FwdState: public RefCountable, public PeerSelectionInitiator bool dont_retry; bool forward_completed; bool destinationsFound; ///< at least one candidate path found - /// Security::PeerConnector dispatched this request (instead of returning control to us) - bool tunneled; } flags; /// waits for a transport connection to the peer to be established/opened From 86033b5c6832f4a4d52dc9354df91339a408837e Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Tue, 16 Apr 2024 17:42:03 +0300 Subject: [PATCH 15/33] Request is always non-nil in TunnelStateData::retryOrBail() --- src/tunnel.cc | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/src/tunnel.cc b/src/tunnel.cc index c135031a551..9889f9587db 100644 --- a/src/tunnel.cc +++ b/src/tunnel.cc @@ -412,7 +412,7 @@ TunnelStateData::TunnelStateData(ClientHttpRequest *clientRequest) : al->cache.code.update(LOG_TCP_TUNNEL); client.initConnection(clientRequest->getConn()->clientConnection, tunnelClientClosed, "tunnelClientClosed", this); - +re AsyncCall::Pointer timeoutCall = commCbCall(5, 4, "tunnelTimeout", CommTimeoutCbPtrFun(tunnelTimeout, this)); commSetConnTimeout(client.conn, Config.Timeout.lifetime, timeoutCall); @@ -479,8 +479,7 @@ TunnelStateData::retryOrBail(const char *context) /* bail */ - if (request) - request->hier.stopPeering(); + request->hier.stopPeering(); // TODO: Add sendSavedErrorOr(err_type type, Http::StatusCode, context). // Then, the remaining method code (below) should become the common part of From 9340dacffc03867246e02f8f185bb87c542d8a16 Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Tue, 16 Apr 2024 21:54:48 +0300 Subject: [PATCH 16/33] Removed a garbage line --- src/tunnel.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/tunnel.cc b/src/tunnel.cc index 9889f9587db..5eac80d74f5 100644 --- a/src/tunnel.cc +++ b/src/tunnel.cc @@ -412,7 +412,7 @@ TunnelStateData::TunnelStateData(ClientHttpRequest *clientRequest) : al->cache.code.update(LOG_TCP_TUNNEL); client.initConnection(clientRequest->getConn()->clientConnection, tunnelClientClosed, "tunnelClientClosed", this); -re + AsyncCall::Pointer timeoutCall = commCbCall(5, 4, "tunnelTimeout", CommTimeoutCbPtrFun(tunnelTimeout, this)); commSetConnTimeout(client.conn, Config.Timeout.lifetime, timeoutCall); From 80925651182d809bf3640e175d48ef9c2dd226bb Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Wed, 17 Apr 2024 15:59:41 +0300 Subject: [PATCH 17/33] Ensure that TunnelStateData calls hier.stopPeering() exactly once --- src/HierarchyLogEntry.h | 2 +- src/tunnel.cc | 19 +++++++++++++++---- 2 files changed, 16 insertions(+), 5 deletions(-) diff --git a/src/HierarchyLogEntry.h b/src/HierarchyLogEntry.h index c83c44efd22..882ee7b7330 100644 --- a/src/HierarchyLogEntry.h +++ b/src/HierarchyLogEntry.h @@ -42,7 +42,7 @@ class HierarchyLogEntry void startPeering() { peeringTime_.resume(); } /// Pause recording after a startPeering() call. - void stopPeering() { if (peeringTime_.running()) { peeringTime_.pause(); } } + void stopPeering() { peeringTime_.pause(); } /// Estimates response generation and sending delay at the last peer. /// \returns whether the estimate (stored in `responseTime`) is available. diff --git a/src/tunnel.cc b/src/tunnel.cc index 5eac80d74f5..fe93b472dff 100644 --- a/src/tunnel.cc +++ b/src/tunnel.cc @@ -127,6 +127,12 @@ class TunnelStateData: public PeerSelectionInitiator /// called when negotiations with the peer have been successfully completed void notePeerReadyToShovel(const Comm::ConnectionPointer &); + /// \copydoc HierarchyLogEntry::stopPeering() + void stopPeering() { + Assure(request->hier.totalResponseTime().running()); + request->hier.stopPeering(); + } + class Connection { @@ -310,7 +316,7 @@ TunnelStateData::serverClosed() { server.noteClosure(); - request->hier.stopPeering(); + stopPeering(); finishWritingAndDelete(client); } @@ -424,6 +430,10 @@ TunnelStateData::~TunnelStateData() { debugs(26, 3, "TunnelStateData destructed this=" << this); assert(noConnections()); + if (request->hier.totalResponseTime().running()) { + debugs(26, DBG_IMPORTANT, "WARNING: peer timer must have been stopped by now"); + stopPeering(); + } xfree(url); cancelStep("~TunnelStateData"); delete savedError; @@ -479,8 +489,6 @@ TunnelStateData::retryOrBail(const char *context) /* bail */ - request->hier.stopPeering(); - // TODO: Add sendSavedErrorOr(err_type type, Http::StatusCode, context). // Then, the remaining method code (below) should become the common part of // sendNewError() and sendSavedErrorOr(), used in "error detected" cases. @@ -490,6 +498,9 @@ TunnelStateData::retryOrBail(const char *context) clientExpectsConnectResponse(); if (canSendError) return sendError(savedError, bailDescription ? bailDescription : context); + + stopPeering(); + *status_ptr = savedError->httpStatus; finishWritingAndDelete(client); @@ -1396,7 +1407,7 @@ TunnelStateData::sendError(ErrorState *finalError, const char *reason) { debugs(26, 3, "aborting transaction for " << reason); - request->hier.stopPeering(); + stopPeering(); cancelStep(reason); From a6932194a458240c0ae984f85651e9ad31c72061 Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Wed, 17 Apr 2024 18:24:26 +0300 Subject: [PATCH 18/33] Removed the peeringTime_.running() assurance from TunnelStateData It turned out that we cannot guarantee that condition when switchToTunnel() was initiated by noteTakeServerConnectionControl(). In this case, FwdState is destroyed after TunnelStateData, and therefore the timer is still 'running' in TunnelStateData destructor. --- src/tunnel.cc | 4 ---- 1 file changed, 4 deletions(-) diff --git a/src/tunnel.cc b/src/tunnel.cc index fe93b472dff..688a661ec1d 100644 --- a/src/tunnel.cc +++ b/src/tunnel.cc @@ -430,10 +430,6 @@ TunnelStateData::~TunnelStateData() { debugs(26, 3, "TunnelStateData destructed this=" << this); assert(noConnections()); - if (request->hier.totalResponseTime().running()) { - debugs(26, DBG_IMPORTANT, "WARNING: peer timer must have been stopped by now"); - stopPeering(); - } xfree(url); cancelStep("~TunnelStateData"); delete savedError; From b9347ee770753095e8a4b8ac5d052d4163db2e0d Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Thu, 18 Apr 2024 12:20:16 +0300 Subject: [PATCH 19/33] Added an ActivityTimer wrapper for Stopwatch thus addressing problems outlined in a693219. --- src/FwdState.cc | 7 +++--- src/FwdState.h | 4 +++ src/HierarchyLogEntry.h | 8 +----- src/base/ActivityTimer.h | 54 ++++++++++++++++++++++++++++++++++++++++ src/base/Makefile.am | 1 + src/tunnel.cc | 26 +++++++++---------- 6 files changed, 76 insertions(+), 24 deletions(-) create mode 100644 src/base/ActivityTimer.h diff --git a/src/FwdState.cc b/src/FwdState.cc index 9a47839cf82..a5173bb1710 100644 --- a/src/FwdState.cc +++ b/src/FwdState.cc @@ -128,7 +128,8 @@ FwdState::FwdState(const Comm::ConnectionPointer &client, StoreEntry * e, HttpRe waitingForDispatched(false), destinations(new ResolvedPeers()), pconnRace(raceImpossible), - storedWholeReply_(nullptr) + storedWholeReply_(nullptr), + peeringTimer(((assert(r)), r->hier.totalResponseTime())) { debugs(17, 2, "Forwarding client request " << client << ", url=" << e->url()); HTTPMSGLOCK(request); @@ -163,7 +164,7 @@ void FwdState::start(Pointer aSelf) request->flags.pinned = false; // start the clock just before any peer communication - request->hier.startPeering(); + peeringTimer.start(); #if STRICT_ORIGINAL_DST // Bug 3243: CVE 2009-0801 @@ -189,7 +190,7 @@ FwdState::stopAndDestroy(const char *reason) cancelStep(reason); - request->hier.stopPeering(); + peeringTimer.stop(); PeerSelectionInitiator::subscribed = false; // may already be false self = nullptr; // we hope refcounting destroys us soon; may already be nil diff --git a/src/FwdState.h b/src/FwdState.h index c435609e3bc..10454229e57 100644 --- a/src/FwdState.h +++ b/src/FwdState.h @@ -9,6 +9,7 @@ #ifndef SQUID_SRC_FWDSTATE_H #define SQUID_SRC_FWDSTATE_H +#include "base/ActivityTimer.h" #include "base/forward.h" #include "base/JobWait.h" #include "base/RefCount.h" @@ -212,6 +213,9 @@ class FwdState: public RefCountable, public PeerSelectionInitiator /// Whether the entire reply (including any body) was written to Store. /// The string literal value is only used for debugging. const char *storedWholeReply_; + + /// Measures time spent on selecting and communicating with peers. + ActivityTimer peeringTimer; }; class acl_tos; diff --git a/src/HierarchyLogEntry.h b/src/HierarchyLogEntry.h index 882ee7b7330..fdd0b34c850 100644 --- a/src/HierarchyLogEntry.h +++ b/src/HierarchyLogEntry.h @@ -38,18 +38,12 @@ class HierarchyLogEntry /// Call this after each peer socket write(2), including failed ones. void notePeerWrite(); - /// Start or resume recording time spent on selecting and communicating with peers. - void startPeering() { peeringTime_.resume(); } - - /// Pause recording after a startPeering() call. - void stopPeering() { peeringTime_.pause(); } - /// Estimates response generation and sending delay at the last peer. /// \returns whether the estimate (stored in `responseTime`) is available. bool peerResponseTime(struct timeval &responseTime); /// Estimates the total time spent communicating with peers. - const Stopwatch &totalResponseTime() const { return peeringTime_; } + Stopwatch &totalResponseTime() { return peeringTime_; } public: hier_code code; diff --git a/src/base/ActivityTimer.h b/src/base/ActivityTimer.h new file mode 100644 index 00000000000..e2a2ac2d207 --- /dev/null +++ b/src/base/ActivityTimer.h @@ -0,0 +1,54 @@ +/* + * Copyright (C) 1996-2023 The Squid Software Foundation and contributors + * + * Squid software is distributed under GPLv2+ license and includes + * contributions from numerous individuals and organizations. + * Please see the COPYING and CONTRIBUTORS files for details. + */ + +#ifndef SQUID_SRC_BASE_ACTIVITYTIMER_H +#define SQUID_SRC_BASE_ACTIVITYTIMER_H + +#include "base/Stopwatch.h" + +/// Eliminates excessive Stopwatch resume() and pause() calls in a task with +/// multiple code locations that resume (or pause) a stopwatch. Ideally, there +/// would be just one such location per action (e.g., constructor resumes while +/// destructor pauses), but current code idiosyncrasies necessitate this state. +class ActivityTimer +{ +public: + // TODO: Call timer.resume() here if possible, eliminating `resumed` and + // adjusting class description to be exclusively about pause(). + ActivityTimer(Stopwatch &w): timer(w) {} + + ~ActivityTimer() { stop(); } + + void start() + { + if (!resumed) { + timer.resume(); + resumed = true; + } + } + + void stop() + { + if (!paused) { + timer.pause(); + paused = true; + } + } + +private: + Stopwatch &timer; + + // Do not be tempted to rely on timer.ran(): We are eliminating excessive + // calls within a single task (e.g., an AsyncJob) while the timer (and its + // ran() state) may be shared/affected by multiple concurrent tasks. + bool resumed = false; + bool paused = false; +}; + +#endif /* SQUID_SRC_BASE_ACTIVITYTIMER_H */ + diff --git a/src/base/Makefile.am b/src/base/Makefile.am index ba18de1f8cc..906aca7a986 100644 --- a/src/base/Makefile.am +++ b/src/base/Makefile.am @@ -10,6 +10,7 @@ include $(top_srcdir)/src/Common.am noinst_LTLIBRARIES = libbase.la libbase_la_SOURCES = \ + ActivityTimer.h \ Assure.cc \ Assure.h \ AsyncCall.cc \ diff --git a/src/tunnel.cc b/src/tunnel.cc index 688a661ec1d..296fede9b16 100644 --- a/src/tunnel.cc +++ b/src/tunnel.cc @@ -10,6 +10,7 @@ #include "squid.h" #include "acl/FilledChecklist.h" +#include "base/ActivityTimer.h" #include "base/AsyncCallbacks.h" #include "base/CbcPointer.h" #include "base/JobWait.h" @@ -127,12 +128,6 @@ class TunnelStateData: public PeerSelectionInitiator /// called when negotiations with the peer have been successfully completed void notePeerReadyToShovel(const Comm::ConnectionPointer &); - /// \copydoc HierarchyLogEntry::stopPeering() - void stopPeering() { - Assure(request->hier.totalResponseTime().running()); - request->hier.stopPeering(); - } - class Connection { @@ -217,6 +212,9 @@ class TunnelStateData: public PeerSelectionInitiator /// over the (encrypted, if needed) transport connection to that cache_peer JobWait peerWait; + /// Measures time spent on selecting and communicating with peers. + ActivityTimer peeringTimer; + void copyRead(Connection &from, IOCB *completion); /// continue to set up connection to a peer, going async for SSL peers @@ -316,7 +314,7 @@ TunnelStateData::serverClosed() { server.noteClosure(); - stopPeering(); + peeringTimer.stop(); finishWritingAndDelete(client); } @@ -399,16 +397,16 @@ TunnelStateData::TunnelStateData(ClientHttpRequest *clientRequest) : committedToServer(false), n_tries(0), banRetries(nullptr), - codeContext(CodeContext::Current()) + codeContext(CodeContext::Current()), + peeringTimer(((assert(clientRequest && clientRequest->request)), clientRequest->request->hier.totalResponseTime())) { debugs(26, 3, "TunnelStateData constructed this=" << this); client.readPendingFunc = &tunnelDelayedClientRead; server.readPendingFunc = &tunnelDelayedServerRead; - assert(clientRequest); url = xstrdup(clientRequest->uri); request = clientRequest->request; - Must(request); + server.size_ptr = &clientRequest->out.size; client.size_ptr = &clientRequest->al->http.clientRequestSz.payloadData; status_ptr = &clientRequest->al->http.code; @@ -423,7 +421,7 @@ TunnelStateData::TunnelStateData(ClientHttpRequest *clientRequest) : CommTimeoutCbPtrFun(tunnelTimeout, this)); commSetConnTimeout(client.conn, Config.Timeout.lifetime, timeoutCall); - request->hier.startPeering(); // could have been started already + peeringTimer.start(); } TunnelStateData::~TunnelStateData() @@ -485,6 +483,8 @@ TunnelStateData::retryOrBail(const char *context) /* bail */ + peeringTimer.stop(); + // TODO: Add sendSavedErrorOr(err_type type, Http::StatusCode, context). // Then, the remaining method code (below) should become the common part of // sendNewError() and sendSavedErrorOr(), used in "error detected" cases. @@ -495,8 +495,6 @@ TunnelStateData::retryOrBail(const char *context) if (canSendError) return sendError(savedError, bailDescription ? bailDescription : context); - stopPeering(); - *status_ptr = savedError->httpStatus; finishWritingAndDelete(client); @@ -1403,7 +1401,7 @@ TunnelStateData::sendError(ErrorState *finalError, const char *reason) { debugs(26, 3, "aborting transaction for " << reason); - stopPeering(); + peeringTimer.stop(); cancelStep(reason); From 8c865904e6383da5c56d62f68782f2b855d8eff5 Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Thu, 18 Apr 2024 14:45:13 +0300 Subject: [PATCH 20/33] Polished and removed a stale TODO The TODO looks irrelevant, since we do not (re)start peer clock in TunnelStateData::startConnecting(), but still need to reset hier.peer_reply_status there. --- src/base/ActivityTimer.h | 2 +- src/tunnel.cc | 4 +--- 2 files changed, 2 insertions(+), 4 deletions(-) diff --git a/src/base/ActivityTimer.h b/src/base/ActivityTimer.h index e2a2ac2d207..f43da299144 100644 --- a/src/base/ActivityTimer.h +++ b/src/base/ActivityTimer.h @@ -1,5 +1,5 @@ /* - * Copyright (C) 1996-2023 The Squid Software Foundation and contributors + * Copyright (C) 1996-2024 The Squid Software Foundation and contributors * * Squid software is distributed under GPLv2+ license and includes * contributions from numerous individuals and organizations. diff --git a/src/tunnel.cc b/src/tunnel.cc index 296fede9b16..e364d38e157 100644 --- a/src/tunnel.cc +++ b/src/tunnel.cc @@ -406,7 +406,6 @@ TunnelStateData::TunnelStateData(ClientHttpRequest *clientRequest) : url = xstrdup(clientRequest->uri); request = clientRequest->request; - server.size_ptr = &clientRequest->out.size; client.size_ptr = &clientRequest->al->http.clientRequestSz.payloadData; status_ptr = &clientRequest->al->http.code; @@ -494,7 +493,6 @@ TunnelStateData::retryOrBail(const char *context) clientExpectsConnectResponse(); if (canSendError) return sendError(savedError, bailDescription ? bailDescription : context); - *status_ptr = savedError->httpStatus; finishWritingAndDelete(client); @@ -1440,7 +1438,7 @@ TunnelStateData::startConnecting() delete savedError; // may still be nil savedError = nullptr; - request->hier.peer_reply_status = Http::scNone; // TODO: Move to startPeering()? + request->hier.peer_reply_status = Http::scNone; const auto callback = asyncCallback(17, 5, TunnelStateData::noteConnection, this); const auto cs = new HappyConnOpener(destinations, callback, request, startTime, n_tries, al); From 80eed218e331f486d16f11f566ddef584655b812 Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Fri, 19 Apr 2024 17:02:49 +0300 Subject: [PATCH 21/33] Addressed an ActivityTimer TODO --- src/FwdState.cc | 5 +---- src/base/ActivityTimer.h | 21 +++++---------------- src/format/Format.cc | 3 +-- src/tunnel.cc | 2 -- 4 files changed, 7 insertions(+), 24 deletions(-) diff --git a/src/FwdState.cc b/src/FwdState.cc index a5173bb1710..8a1d0fe0e4a 100644 --- a/src/FwdState.cc +++ b/src/FwdState.cc @@ -129,7 +129,7 @@ FwdState::FwdState(const Comm::ConnectionPointer &client, StoreEntry * e, HttpRe destinations(new ResolvedPeers()), pconnRace(raceImpossible), storedWholeReply_(nullptr), - peeringTimer(((assert(r)), r->hier.totalResponseTime())) + peeringTimer((r->hier.totalResponseTime())) { debugs(17, 2, "Forwarding client request " << client << ", url=" << e->url()); HTTPMSGLOCK(request); @@ -163,9 +163,6 @@ void FwdState::start(Pointer aSelf) // just in case; should already be initialized to false request->flags.pinned = false; - // start the clock just before any peer communication - peeringTimer.start(); - #if STRICT_ORIGINAL_DST // Bug 3243: CVE 2009-0801 // Bypass of browser same-origin access control in intercepted communication diff --git a/src/base/ActivityTimer.h b/src/base/ActivityTimer.h index f43da299144..aea2e603e0f 100644 --- a/src/base/ActivityTimer.h +++ b/src/base/ActivityTimer.h @@ -11,27 +11,17 @@ #include "base/Stopwatch.h" -/// Eliminates excessive Stopwatch resume() and pause() calls in a task with -/// multiple code locations that resume (or pause) a stopwatch. Ideally, there -/// would be just one such location per action (e.g., constructor resumes while -/// destructor pauses), but current code idiosyncrasies necessitate this state. +/// Eliminates excessive Stopwatch pause() calls in a task with +/// multiple code locations that pause a stopwatch. Ideally, there +/// would be just one such location (e.g., a destructor), +/// but current code idiosyncrasies necessitate this state. class ActivityTimer { public: - // TODO: Call timer.resume() here if possible, eliminating `resumed` and - // adjusting class description to be exclusively about pause(). - ActivityTimer(Stopwatch &w): timer(w) {} + ActivityTimer(Stopwatch &w): timer(w) { timer.resume(); } ~ActivityTimer() { stop(); } - void start() - { - if (!resumed) { - timer.resume(); - resumed = true; - } - } - void stop() { if (!paused) { @@ -46,7 +36,6 @@ class ActivityTimer // Do not be tempted to rely on timer.ran(): We are eliminating excessive // calls within a single task (e.g., an AsyncJob) while the timer (and its // ran() state) may be shared/affected by multiple concurrent tasks. - bool resumed = false; bool paused = false; }; diff --git a/src/format/Format.cc b/src/format/Format.cc index 43a4cb23cf6..109bb1139c5 100644 --- a/src/format/Format.cc +++ b/src/format/Format.cc @@ -644,8 +644,7 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS const auto duration = timer.total(); outtv.tv_sec = std::chrono::duration_cast(duration).count(); const auto totalUsec = std::chrono::duration_cast(duration); - static const std::chrono::microseconds secondUsec = 1s; - outtv.tv_usec = totalUsec.count() % secondUsec.count(); + outtv.tv_usec = totalUsec.count() % std::chrono::microseconds(1s).count(); doMsec = 1; } } diff --git a/src/tunnel.cc b/src/tunnel.cc index e364d38e157..0c70488067a 100644 --- a/src/tunnel.cc +++ b/src/tunnel.cc @@ -419,8 +419,6 @@ TunnelStateData::TunnelStateData(ClientHttpRequest *clientRequest) : AsyncCall::Pointer timeoutCall = commCbCall(5, 4, "tunnelTimeout", CommTimeoutCbPtrFun(tunnelTimeout, this)); commSetConnTimeout(client.conn, Config.Timeout.lifetime, timeoutCall); - - peeringTimer.start(); } TunnelStateData::~TunnelStateData() From a9c2c01a20dc031546dfbc03dadc05c06af27342 Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Fri, 19 Apr 2024 17:07:54 +0300 Subject: [PATCH 22/33] Use an overloaded chrono::duration operator % --- src/format/Format.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/format/Format.cc b/src/format/Format.cc index 109bb1139c5..0a2f42e3b0b 100644 --- a/src/format/Format.cc +++ b/src/format/Format.cc @@ -644,7 +644,7 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS const auto duration = timer.total(); outtv.tv_sec = std::chrono::duration_cast(duration).count(); const auto totalUsec = std::chrono::duration_cast(duration); - outtv.tv_usec = totalUsec.count() % std::chrono::microseconds(1s).count(); + outtv.tv_usec = (totalUsec % std::chrono::microseconds(1s)).count(); doMsec = 1; } } From d4b420d1c40916253efdd85673875771d5879fef Mon Sep 17 00:00:00 2001 From: Alex Rousskov Date: Fri, 31 May 2024 11:34:56 -0400 Subject: [PATCH 23/33] fixup: Polished ActivityTimer documentation --- src/base/ActivityTimer.h | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/base/ActivityTimer.h b/src/base/ActivityTimer.h index aea2e603e0f..42b5e00a8c5 100644 --- a/src/base/ActivityTimer.h +++ b/src/base/ActivityTimer.h @@ -11,10 +11,10 @@ #include "base/Stopwatch.h" -/// Eliminates excessive Stopwatch pause() calls in a task with -/// multiple code locations that pause a stopwatch. Ideally, there -/// would be just one such location (e.g., a destructor), -/// but current code idiosyncrasies necessitate this state. +/// Eliminates excessive Stopwatch pause() calls in a task with multiple code +/// locations that pause a stopwatch. Ideally, there would be just one such +/// location (e.g., a task class destructor), but current code idiosyncrasies +/// necessitate this state. class ActivityTimer { public: @@ -33,7 +33,7 @@ class ActivityTimer private: Stopwatch &timer; - // Do not be tempted to rely on timer.ran(): We are eliminating excessive + // Do not be tempted to rely on timer.ran(): This class eliminates excessive // calls within a single task (e.g., an AsyncJob) while the timer (and its // ran() state) may be shared/affected by multiple concurrent tasks. bool paused = false; From fe72ba953cc97bde39d4deb3ed2699e587d951bd Mon Sep 17 00:00:00 2001 From: Alex Rousskov Date: Fri, 31 May 2024 11:17:56 -0400 Subject: [PATCH 24/33] fixup: Simplified TunnelStateData::peeringTimer initialization --- src/tunnel.cc | 16 +++++++++++++++- 1 file changed, 15 insertions(+), 1 deletion(-) diff --git a/src/tunnel.cc b/src/tunnel.cc index 0c70488067a..618361d5628 100644 --- a/src/tunnel.cc +++ b/src/tunnel.cc @@ -390,6 +390,15 @@ TunnelStateData::deleteThis() delete this; } +/// safely extracts HttpRequest from a never-nil ClientHttpRequest pointer +static auto & +guaranteedRequest(const ClientHttpRequest * const cr) +{ + Assure(cr); + Assure(cr->request); + return *cr->request; +} + TunnelStateData::TunnelStateData(ClientHttpRequest *clientRequest) : startTime(squid_curtime), destinations(new ResolvedPeers()), @@ -398,7 +407,12 @@ TunnelStateData::TunnelStateData(ClientHttpRequest *clientRequest) : n_tries(0), banRetries(nullptr), codeContext(CodeContext::Current()), - peeringTimer(((assert(clientRequest && clientRequest->request)), clientRequest->request->hier.totalResponseTime())) + // XXX: clientRequest existence is guaranteed here and now, but the object + // is destroyed before TunnelStateData in some cases. Storing a reference to + // something clientRequest points to is very dangerous. It "works" today + // because we also store a refcounted pointer to clientRequest->request, but + // nothing guarantees preservation of that hidden dependency! + peeringTimer(guaranteedRequest(clientRequest).hier.totalResponseTime()) { debugs(26, 3, "TunnelStateData constructed this=" << this); client.readPendingFunc = &tunnelDelayedClientRead; From fa327521200dfd6849c0f18d1bc213d17f0d0631 Mon Sep 17 00:00:00 2001 From: Alex Rousskov Date: Fri, 31 May 2024 13:52:58 -0400 Subject: [PATCH 25/33] Addressed HierarchyLogEntry::totalPeeringTime lifetime concerns ... documented in the previous branch commit XXX. I am not sure this complexity is warranted, but storing a raw pointer to a disappearing object (for some definition of "disappearing") did not feel right either. This is the best solution I could find. --- src/FwdState.cc | 9 ++++++++- src/FwdState.h | 8 +++++++- src/HierarchyLogEntry.h | 7 +++---- src/base/ActivityTimer.h | 15 ++++++++++++--- src/base/forward.h | 1 + src/format/Format.cc | 6 +++--- src/tunnel.cc | 9 ++------- 7 files changed, 36 insertions(+), 19 deletions(-) diff --git a/src/FwdState.cc b/src/FwdState.cc index 8a1d0fe0e4a..9a0f519d660 100644 --- a/src/FwdState.cc +++ b/src/FwdState.cc @@ -129,7 +129,7 @@ FwdState::FwdState(const Comm::ConnectionPointer &client, StoreEntry * e, HttpRe destinations(new ResolvedPeers()), pconnRace(raceImpossible), storedWholeReply_(nullptr), - peeringTimer((r->hier.totalResponseTime())) + peeringTimer(r, &HierarchyLogEntry::totalPeeringTime) { debugs(17, 2, "Forwarding client request " << client << ", url=" << e->url()); HTTPMSGLOCK(request); @@ -1565,3 +1565,10 @@ ResetMarkingsToServer(HttpRequest * request, Comm::Connection &conn) Ip::Qos::setSockNfmark(&conn, conn.nfmark); } +template <> +Stopwatch & +PeeringActivityTimer::timer() +{ + return owner->hier.*location; +} + diff --git a/src/FwdState.h b/src/FwdState.h index 10454229e57..1d5c1fe0890 100644 --- a/src/FwdState.h +++ b/src/FwdState.h @@ -50,6 +50,12 @@ void ResetMarkingsToServer(HttpRequest *, Comm::Connection &); class HelperReply; +using PeeringActivityTimer = ActivityTimer; + +/// HttpRequest::hier is not referenced-counted. HttpRequest is. We specialize +/// ActivityTimer to extract HierarchyLogEntry timers from HttpRequest. +template <> Stopwatch &PeeringActivityTimer::timer(); + class FwdState: public RefCountable, public PeerSelectionInitiator { CBDATA_CHILD(FwdState); @@ -215,7 +221,7 @@ class FwdState: public RefCountable, public PeerSelectionInitiator const char *storedWholeReply_; /// Measures time spent on selecting and communicating with peers. - ActivityTimer peeringTimer; + PeeringActivityTimer peeringTimer; }; class acl_tos; diff --git a/src/HierarchyLogEntry.h b/src/HierarchyLogEntry.h index fdd0b34c850..053cf9b134a 100644 --- a/src/HierarchyLogEntry.h +++ b/src/HierarchyLogEntry.h @@ -42,9 +42,6 @@ class HierarchyLogEntry /// \returns whether the estimate (stored in `responseTime`) is available. bool peerResponseTime(struct timeval &responseTime); - /// Estimates the total time spent communicating with peers. - Stopwatch &totalResponseTime() { return peeringTime_; } - public: hier_code code; char host[SQUIDHOSTNAMELEN]; @@ -62,12 +59,14 @@ class HierarchyLogEntry Comm::ConnectionPointer tcpServer; ///< TCP/IP level details of the last peer/server connection int64_t bodyBytesRead; ///< number of body bytes received from the next hop or -1 + /// cumulative time spent (so far) communicating with all peers (see % class ActivityTimer { public: - ActivityTimer(Stopwatch &w): timer(w) { timer.resume(); } + ActivityTimer(const Owner &o, const Location &l): owner(o), location(l) { timer().resume(); } ~ActivityTimer() { stop(); } void stop() { if (!paused) { - timer.pause(); + timer().pause(); paused = true; } } private: - Stopwatch &timer; + /// extracts Stopwatch from the configured location + Stopwatch &timer() { return owner->*location; } + + /// Stopwatch owner; this is usually a strong pointer + Owner owner; + + /// The address of a managed Stopwatch within its Owner. This is usually a + /// pointer to Owner data member. + Location location; // Do not be tempted to rely on timer.ran(): This class eliminates excessive // calls within a single task (e.g., an AsyncJob) while the timer (and its diff --git a/src/base/forward.h b/src/base/forward.h index 4a5025974bf..5c67903b674 100644 --- a/src/base/forward.h +++ b/src/base/forward.h @@ -24,6 +24,7 @@ template class CbcPointer; template class RefCount; template class JobWait; template class AsyncCallback; +template class ActivityTimer; typedef CbcPointer AsyncJobPointer; typedef RefCount CodeContextPointer; diff --git a/src/format/Format.cc b/src/format/Format.cc index 0a2f42e3b0b..f7f467fd3df 100644 --- a/src/format/Format.cc +++ b/src/format/Format.cc @@ -635,10 +635,10 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS break; case LFT_TOTAL_SERVER_SIDE_RESPONSE_TIME: { - // al->hier.totalResponseTime() is unassigned before prepareLogWithRequestDetails() + // al->hier.totalPeeringTime is unassigned before prepareLogWithRequestDetails() // TODO: keep the total response time in one place. - const auto &timer = (!al->hier.totalResponseTime().ran() && al->request) ? - al->request->hier.totalResponseTime() : al->hier.totalResponseTime(); + const auto &timer = (!al->hier.totalPeeringTime.ran() && al->request) ? + al->request->hier.totalPeeringTime : al->hier.totalPeeringTime; if (timer.ran()) { using namespace std::chrono_literals; const auto duration = timer.total(); diff --git a/src/tunnel.cc b/src/tunnel.cc index 618361d5628..0ec8a3e5bb7 100644 --- a/src/tunnel.cc +++ b/src/tunnel.cc @@ -213,7 +213,7 @@ class TunnelStateData: public PeerSelectionInitiator JobWait peerWait; /// Measures time spent on selecting and communicating with peers. - ActivityTimer peeringTimer; + ActivityTimer peeringTimer; void copyRead(Connection &from, IOCB *completion); @@ -407,12 +407,7 @@ TunnelStateData::TunnelStateData(ClientHttpRequest *clientRequest) : n_tries(0), banRetries(nullptr), codeContext(CodeContext::Current()), - // XXX: clientRequest existence is guaranteed here and now, but the object - // is destroyed before TunnelStateData in some cases. Storing a reference to - // something clientRequest points to is very dangerous. It "works" today - // because we also store a refcounted pointer to clientRequest->request, but - // nothing guarantees preservation of that hidden dependency! - peeringTimer(guaranteedRequest(clientRequest).hier.totalResponseTime()) + peeringTimer(&guaranteedRequest(clientRequest), &HierarchyLogEntry::totalPeeringTime) { debugs(26, 3, "TunnelStateData constructed this=" << this); client.readPendingFunc = &tunnelDelayedClientRead; From 95c3e8a9e9a2b9511210ce1252b08c046fb6fb39 Mon Sep 17 00:00:00 2001 From: Alex Rousskov Date: Fri, 31 May 2024 13:56:52 -0400 Subject: [PATCH 26/33] fixup: Polished ActivityTimer::paused name/docs, added description --- src/base/ActivityTimer.h | 13 +++++++------ 1 file changed, 7 insertions(+), 6 deletions(-) diff --git a/src/base/ActivityTimer.h b/src/base/ActivityTimer.h index b6cfee60df9..82bb01fb818 100644 --- a/src/base/ActivityTimer.h +++ b/src/base/ActivityTimer.h @@ -25,9 +25,9 @@ class ActivityTimer void stop() { - if (!paused) { + if (!stopped) { timer().pause(); - paused = true; + stopped = true; } } @@ -42,10 +42,11 @@ class ActivityTimer /// pointer to Owner data member. Location location; - // Do not be tempted to rely on timer.ran(): This class eliminates excessive - // calls within a single task (e.g., an AsyncJob) while the timer (and its - // ran() state) may be shared/affected by multiple concurrent tasks. - bool paused = false; + // We cannot rely on timer().ran(): This class eliminates excessive calls + // within a single task (e.g., an AsyncJob) while the timer (and its ran() + // state) may be shared/affected by multiple concurrent tasks. + /// Whether the task is done participating in the managed activity. + bool stopped = false; }; #endif /* SQUID_SRC_BASE_ACTIVITYTIMER_H */ From 48b31b2701c581b125a4412e72869245c5721d34 Mon Sep 17 00:00:00 2001 From: Alex Rousskov Date: Fri, 31 May 2024 17:28:01 -0400 Subject: [PATCH 27/33] fixup: Simplified ActivityTimer code by making the class less general It is difficult to justify paying significant price for supporting future hypothetical use cases, especially when we can add support for other use cases (and make the class more complex) as needed instead. --- src/FwdState.cc | 21 +++++++++++++--- src/FwdState.h | 37 ++++++++++++++++++++++++---- src/base/ActivityTimer.h | 53 ---------------------------------------- src/base/Makefile.am | 1 - src/base/forward.h | 1 - src/tunnel.cc | 5 ++-- 6 files changed, 52 insertions(+), 66 deletions(-) delete mode 100644 src/base/ActivityTimer.h diff --git a/src/FwdState.cc b/src/FwdState.cc index 9a0f519d660..1c3721e9e74 100644 --- a/src/FwdState.cc +++ b/src/FwdState.cc @@ -129,7 +129,7 @@ FwdState::FwdState(const Comm::ConnectionPointer &client, StoreEntry * e, HttpRe destinations(new ResolvedPeers()), pconnRace(raceImpossible), storedWholeReply_(nullptr), - peeringTimer(r, &HierarchyLogEntry::totalPeeringTime) + peeringTimer(r) { debugs(17, 2, "Forwarding client request " << client << ", url=" << e->url()); HTTPMSGLOCK(request); @@ -1565,10 +1565,25 @@ ResetMarkingsToServer(HttpRequest * request, Comm::Connection &conn) Ip::Qos::setSockNfmark(&conn, conn.nfmark); } -template <> +/* PeeringActivityTimer */ + +// The simple methods below are not inlined to avoid exposing some of the +// current FwdState.h users to a full HttpRequest definition they do not need. + +PeeringActivityTimer::PeeringActivityTimer(const HttpRequestPointer &r): request(r) +{ + Assure(request); + timer().resume(); +} + +PeeringActivityTimer::~PeeringActivityTimer() +{ + stop(); +} + Stopwatch & PeeringActivityTimer::timer() { - return owner->hier.*location; + return request->hier.totalPeeringTime; } diff --git a/src/FwdState.h b/src/FwdState.h index 1d5c1fe0890..316243c9030 100644 --- a/src/FwdState.h +++ b/src/FwdState.h @@ -9,7 +9,6 @@ #ifndef SQUID_SRC_FWDSTATE_H #define SQUID_SRC_FWDSTATE_H -#include "base/ActivityTimer.h" #include "base/forward.h" #include "base/JobWait.h" #include "base/RefCount.h" @@ -50,11 +49,39 @@ void ResetMarkingsToServer(HttpRequest *, Comm::Connection &); class HelperReply; -using PeeringActivityTimer = ActivityTimer; +/// Eliminates excessive Stopwatch pause() calls in a task with multiple code +/// locations that pause a stopwatch. Ideally, there would be just one such +/// location (e.g., a task class destructor), but current code idiosyncrasies +/// necessitate this state. For simplicity sake, this class currently manages a +/// Stopwatch at a hard-coded location: HttpRequest::hier.totalPeeringTime. +class PeeringActivityTimer +{ +public: + PeeringActivityTimer(const HttpRequestPointer &); ///< resumes timer + ~PeeringActivityTimer(); ///< \copydoc stop() + + /// pauses timer if stop() has not been called + void stop() + { + if (!stopped) { + timer().pause(); + stopped = true; + } + } + +private: + /// managed Stopwatch object within HierarchyLogEntry + Stopwatch &timer(); + + /// the owner of managed HierarchyLogEntry + HttpRequestPointer request; -/// HttpRequest::hier is not referenced-counted. HttpRequest is. We specialize -/// ActivityTimer to extract HierarchyLogEntry timers from HttpRequest. -template <> Stopwatch &PeeringActivityTimer::timer(); + // We cannot rely on timer().ran(): This class eliminates excessive calls + // within a single task (e.g., an AsyncJob) while the timer (and its ran() + // state) may be shared/affected by multiple concurrent tasks. + /// Whether the task is done participating in the managed activity. + bool stopped = false; +}; class FwdState: public RefCountable, public PeerSelectionInitiator { diff --git a/src/base/ActivityTimer.h b/src/base/ActivityTimer.h deleted file mode 100644 index 82bb01fb818..00000000000 --- a/src/base/ActivityTimer.h +++ /dev/null @@ -1,53 +0,0 @@ -/* - * Copyright (C) 1996-2024 The Squid Software Foundation and contributors - * - * Squid software is distributed under GPLv2+ license and includes - * contributions from numerous individuals and organizations. - * Please see the COPYING and CONTRIBUTORS files for details. - */ - -#ifndef SQUID_SRC_BASE_ACTIVITYTIMER_H -#define SQUID_SRC_BASE_ACTIVITYTIMER_H - -#include "base/Stopwatch.h" - -/// Eliminates excessive Stopwatch pause() calls in a task with multiple code -/// locations that pause a stopwatch. Ideally, there would be just one such -/// location (e.g., a task class destructor), but current code idiosyncrasies -/// necessitate this state. -template -class ActivityTimer -{ -public: - ActivityTimer(const Owner &o, const Location &l): owner(o), location(l) { timer().resume(); } - - ~ActivityTimer() { stop(); } - - void stop() - { - if (!stopped) { - timer().pause(); - stopped = true; - } - } - -private: - /// extracts Stopwatch from the configured location - Stopwatch &timer() { return owner->*location; } - - /// Stopwatch owner; this is usually a strong pointer - Owner owner; - - /// The address of a managed Stopwatch within its Owner. This is usually a - /// pointer to Owner data member. - Location location; - - // We cannot rely on timer().ran(): This class eliminates excessive calls - // within a single task (e.g., an AsyncJob) while the timer (and its ran() - // state) may be shared/affected by multiple concurrent tasks. - /// Whether the task is done participating in the managed activity. - bool stopped = false; -}; - -#endif /* SQUID_SRC_BASE_ACTIVITYTIMER_H */ - diff --git a/src/base/Makefile.am b/src/base/Makefile.am index 906aca7a986..ba18de1f8cc 100644 --- a/src/base/Makefile.am +++ b/src/base/Makefile.am @@ -10,7 +10,6 @@ include $(top_srcdir)/src/Common.am noinst_LTLIBRARIES = libbase.la libbase_la_SOURCES = \ - ActivityTimer.h \ Assure.cc \ Assure.h \ AsyncCall.cc \ diff --git a/src/base/forward.h b/src/base/forward.h index 5c67903b674..4a5025974bf 100644 --- a/src/base/forward.h +++ b/src/base/forward.h @@ -24,7 +24,6 @@ template class CbcPointer; template class RefCount; template class JobWait; template class AsyncCallback; -template class ActivityTimer; typedef CbcPointer AsyncJobPointer; typedef RefCount CodeContextPointer; diff --git a/src/tunnel.cc b/src/tunnel.cc index 0ec8a3e5bb7..43c4b8deb6e 100644 --- a/src/tunnel.cc +++ b/src/tunnel.cc @@ -10,7 +10,6 @@ #include "squid.h" #include "acl/FilledChecklist.h" -#include "base/ActivityTimer.h" #include "base/AsyncCallbacks.h" #include "base/CbcPointer.h" #include "base/JobWait.h" @@ -213,7 +212,7 @@ class TunnelStateData: public PeerSelectionInitiator JobWait peerWait; /// Measures time spent on selecting and communicating with peers. - ActivityTimer peeringTimer; + PeeringActivityTimer peeringTimer; void copyRead(Connection &from, IOCB *completion); @@ -407,7 +406,7 @@ TunnelStateData::TunnelStateData(ClientHttpRequest *clientRequest) : n_tries(0), banRetries(nullptr), codeContext(CodeContext::Current()), - peeringTimer(&guaranteedRequest(clientRequest), &HierarchyLogEntry::totalPeeringTime) + peeringTimer(&guaranteedRequest(clientRequest)) { debugs(26, 3, "TunnelStateData constructed this=" << this); client.readPendingFunc = &tunnelDelayedClientRead; From f3ee47b5dc84b89ddd0e524b74d536e9c6d308b6 Mon Sep 17 00:00:00 2001 From: Alex Rousskov Date: Fri, 31 May 2024 17:31:12 -0400 Subject: [PATCH 28/33] fixup: Fixed % Date: Fri, 31 May 2024 18:14:45 -0400 Subject: [PATCH 29/33] fixup: Polished branch-added comments --- src/format/Format.cc | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/format/Format.cc b/src/format/Format.cc index f7f467fd3df..da85d9c1afc 100644 --- a/src/format/Format.cc +++ b/src/format/Format.cc @@ -635,8 +635,8 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS break; case LFT_TOTAL_SERVER_SIDE_RESPONSE_TIME: { - // al->hier.totalPeeringTime is unassigned before prepareLogWithRequestDetails() - // TODO: keep the total response time in one place. + // XXX: al->hier.totalPeeringTime is not updated until prepareLogWithRequestDetails(). + // TODO: Avoid the need for updates by keeping totalPeeringTime (or even ALE::hier) in one place. const auto &timer = (!al->hier.totalPeeringTime.ran() && al->request) ? al->request->hier.totalPeeringTime : al->hier.totalPeeringTime; if (timer.ran()) { From 87553441368dc34b172fca8b6b1a37c8b2da2541 Mon Sep 17 00:00:00 2001 From: Alex Rousskov Date: Fri, 31 May 2024 18:25:34 -0400 Subject: [PATCH 30/33] fixup: Restored branch-removed assertions They are no longer needed, but it is probably best to remove them when refactoring this code to replace member assignments with member initialization code. While at it, we should consider either adding RefCount and CbcPointer methods to guarantee object existence (similar to std::optional::value() and std::vector::at()) OR a global function providing that same guarantees for any pointer-like object. --- src/tunnel.cc | 3 +++ 1 file changed, 3 insertions(+) diff --git a/src/tunnel.cc b/src/tunnel.cc index 43c4b8deb6e..4dbe7655ba9 100644 --- a/src/tunnel.cc +++ b/src/tunnel.cc @@ -389,6 +389,7 @@ TunnelStateData::deleteThis() delete this; } +// TODO: Replace with a reusable API guaranteeing non-nil pointer forwarding. /// safely extracts HttpRequest from a never-nil ClientHttpRequest pointer static auto & guaranteedRequest(const ClientHttpRequest * const cr) @@ -412,8 +413,10 @@ TunnelStateData::TunnelStateData(ClientHttpRequest *clientRequest) : client.readPendingFunc = &tunnelDelayedClientRead; server.readPendingFunc = &tunnelDelayedServerRead; + assert(clientRequest); url = xstrdup(clientRequest->uri); request = clientRequest->request; + Must(request); server.size_ptr = &clientRequest->out.size; client.size_ptr = &clientRequest->al->http.clientRequestSz.payloadData; status_ptr = &clientRequest->al->http.code; From 02cf233b9197cfb9cfc18340336284d576dd53b0 Mon Sep 17 00:00:00 2001 From: Alex Rousskov Date: Mon, 10 Jun 2024 09:15:38 -0400 Subject: [PATCH 31/33] fixup: Avoid "peering" in % Date: Mon, 10 Jun 2024 09:30:07 -0400 Subject: [PATCH 32/33] fixup: Clarify special cases using paragraphs Context: https://github.com/squid-cache/squid/pull/1828#discussion_r1631879934 --- src/cf.data.pre | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/src/cf.data.pre b/src/cf.data.pre index 0a864a5af86..7ce6e434b21 100644 --- a/src/cf.data.pre +++ b/src/cf.data.pre @@ -5013,9 +5013,10 @@ DOC_START If this logformat %code is used before its timer starts, the corresponding measurement has no value (and the %code expands - to a single dash ("-") character). If this code is used while - its timer is running, the time spent so far is used as the - measurement value. + to a single dash ("-") character). + + If this code is used while its timer is running, the time + spent so far is used as the measurement value. When Squid re-forwards the request (e.g., due to an HTTP 304 response indicating that the cached response is stale), the From 4443bdfc08a8fe1b1ac817ae69c22964713025fa Mon Sep 17 00:00:00 2001 From: Alex Rousskov Date: Mon, 10 Jun 2024 09:56:54 -0400 Subject: [PATCH 33/33] fixup: Fix example in re-forwarding case docs Context: https://github.com/squid-cache/squid/pull/1828#discussion_r1631880941 --- src/cf.data.pre | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/src/cf.data.pre b/src/cf.data.pre index 7ce6e434b21..e2bb3a1a62a 100644 --- a/src/cf.data.pre +++ b/src/cf.data.pre @@ -5018,12 +5018,11 @@ DOC_START If this code is used while its timer is running, the time spent so far is used as the measurement value. - When Squid re-forwards the request (e.g., due to an HTTP 304 - response indicating that the cached response is stale), the - timer may restart. In this case, the new measurement is added - to the value accumulated from previous forwarding attempts. - The time interval between forwarding attempts is not added - to the final result. + When Squid re-forwards the request (e.g., after certain cache + revalidation failures), the timer may restart. In this case, + the new measurement is added to the value accumulated from + previous forwarding attempts. The time interval between + forwarding attempts is not added to the final result. Squid handling related format codes: