From: Christos Tsantilas Date: Tue, 2 Sep 2014 14:54:01 +0000 (+0300) Subject: %hier.stopPeerClock(false); + if (EBIT_TEST(entry->flags, ENTRY_ABORTED)) { debugs(17, 3, HERE << "entry aborted"); return ; @@ -643,6 +645,8 @@ FwdState::retryOrBail() // TODO: should we call completed() here and move doneWithRetries there? doneWithRetries(); + request->hier.stopPeerClock(false); + if (self != NULL && !err && shutting_down) { ErrorState *anErr = new ErrorState(ERR_SHUTTING_DOWN, Http::scServiceUnavailable, request); errorAppendEntry(entry, anErr); @@ -798,8 +802,7 @@ FwdState::connectStart() debugs(17, 3, "fwdConnectStart: " << entry->url()); - if (!request->hier.first_conn_start.tv_sec) // first attempt - request->hier.first_conn_start = current_time; + request->hier.startPeerClock(); if (serverDestinations[0]->getPeer() && request->flags.sslBumped) { debugs(50, 4, "fwdConnectStart: Ssl bumped connections through parent proxy are not allowed"); diff --git a/src/HierarchyLogEntry.h b/src/HierarchyLogEntry.h index 921eb07c5f..9091299cad 100644 --- a/src/HierarchyLogEntry.h +++ b/src/HierarchyLogEntry.h @@ -51,6 +51,17 @@ public: /// call this whenever the destination server changes. void note(const Comm::ConnectionPointer &server, const char *requestedHost); + /// Start recording total time spent communicating with peers + void startPeerClock(); + /** + * Record total time spent communicating with peers + * \param force whether to overwrite old recorded value if any + */ + void stopPeerClock(const bool force); + + /// Return the total time spent communicating with peers + int64_t totalResponseTime(); + public: hier_code code; char host[SQUIDHOSTNAMELEN]; @@ -67,10 +78,12 @@ public: Http::StatusCode peer_reply_status; ///< last HTTP status code received timeval peer_http_request_sent; ///< last peer finished writing req int64_t peer_response_time; ///< last peer response delay - timeval first_conn_start; ///< first connection use among all peers - int64_t total_response_time; ///< cumulative for all peers Comm::ConnectionPointer tcpServer; ///< TCP/IP level details of the last server-side connection int64_t bodyBytesRead; ///< number of body bytes received from the next hop or -1 + +private: + timeval firstConnStart_; ///< first connection use among all peers + int64_t totalResponseTime_; ///< cumulative for all peers }; #endif /* SQUID_HTTPHIERARCHYLOGENTRY_H */ diff --git a/src/Server.cc b/src/Server.cc index 712d5651fa..fd53fe9481 100644 --- a/src/Server.cc +++ b/src/Server.cc @@ -196,8 +196,7 @@ ServerStateData::serverComplete() completed = true; HttpRequest *r = originalRequest(); - r->hier.total_response_time = r->hier.first_conn_start.tv_sec ? - tvSubMsec(r->hier.first_conn_start, current_time) : -1; + r->hier.stopPeerClock(true); if (requestBodySource != NULL) stopConsumingFrom(requestBodySource); diff --git a/src/format/Format.cc b/src/format/Format.cc index fe2be648c0..c94f06a1af 100644 --- a/src/format/Format.cc +++ b/src/format/Format.cc @@ -517,14 +517,16 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS } break; - case LFT_TOTAL_SERVER_SIDE_RESPONSE_TIME: - if (al->hier.total_response_time < 0) { + case LFT_TOTAL_SERVER_SIDE_RESPONSE_TIME: { + const int64_t total_response_time = al->hier.totalResponseTime(); + if (total_response_time < 0) { out = "-"; } else { - outoff = al->hier.total_response_time; + outoff = total_response_time; dooff = 1; } - break; + } + break; case LFT_DNS_WAIT_TIME: if (al->request && al->request->dnsWait >= 0) { diff --git a/src/log/access_log.cc b/src/log/access_log.cc index 4c6853c6e9..bd5ae9a6cf 100644 --- a/src/log/access_log.cc +++ b/src/log/access_log.cc @@ -255,9 +255,9 @@ HierarchyLogEntry::HierarchyLogEntry() : n_ichoices(0), peer_reply_status(Http::scNone), peer_response_time(-1), - total_response_time(-1), tcpServer(NULL), - bodyBytesRead(-1) + bodyBytesRead(-1), + totalResponseTime_(-1) { memset(host, '\0', SQUIDHOSTNAMELEN); memset(cd_host, '\0', SQUIDHOSTNAMELEN); @@ -271,8 +271,8 @@ HierarchyLogEntry::HierarchyLogEntry() : peer_http_request_sent.tv_sec = 0; peer_http_request_sent.tv_usec = 0; - first_conn_start.tv_sec = 0; - first_conn_start.tv_usec = 0; + firstConnStart_.tv_sec = 0; + firstConnStart_.tv_usec = 0; } void @@ -294,6 +294,37 @@ HierarchyLogEntry::note(const Comm::ConnectionPointer &server, const char *reque } } +void +HierarchyLogEntry::startPeerClock() +{ + if (!firstConnStart_.tv_sec) + firstConnStart_ = current_time; +} + +void +HierarchyLogEntry::stopPeerClock(const bool force) { + debugs(46, 5, "First connection started: " << firstConnStart_.tv_sec << "." << + std::setfill('0') << std::setw(6) << firstConnStart_.tv_usec << + ", current total response time value: " << totalResponseTime_ << + (force ? ", force fixing" : "")); + if (!force && totalResponseTime_ >= 0) + return; + + totalResponseTime_ = firstConnStart_.tv_sec ? tvSubMsec(firstConnStart_, current_time) : -1; +} + +int64_t +HierarchyLogEntry::totalResponseTime() +{ + // 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_ < 0) + stopPeerClock(false); + + return totalResponseTime_; +} + static void accessLogRegisterWithCacheManager(void) { diff --git a/src/tunnel.cc b/src/tunnel.cc index 020749c713..d946df03dd 100644 --- a/src/tunnel.cc +++ b/src/tunnel.cc @@ -54,6 +54,7 @@ #include "MemBuf.h" #include "PeerSelectState.h" #include "SquidConfig.h" +#include "SquidTime.h" #include "StatCounters.h" #if USE_OPENSSL #include "ssl/bio.h" @@ -238,6 +239,9 @@ tunnelServerClosed(const CommCloseCbParams ¶ms) debugs(26, 3, HERE << tunnelState->server.conn); tunnelState->server.conn = NULL; + if (tunnelState->request != NULL) + tunnelState->request->hier.stopPeerClock(false); + if (tunnelState->noConnections()) { delete tunnelState; return; @@ -862,6 +866,8 @@ tunnelConnectDone(const Comm::ConnectionPointer &conn, Comm::Flag status, int xe err->callback = tunnelErrorComplete; err->callback_data = tunnelState; errorSend(tunnelState->client.conn, err); + if (tunnelState->request != NULL) + tunnelState->request->hier.stopPeerClock(false); } return; } @@ -1079,6 +1085,9 @@ tunnelPeerSelectComplete(Comm::ConnectionList *peer_paths, ErrorState *err, void GetMarkingsToServer(tunnelState->request.getRaw(), *tunnelState->serverDestinations[0]); + if (tunnelState->request != NULL) + tunnelState->request->hier.startPeerClock(); + debugs(26, 3, HERE << "paths=" << peer_paths->size() << ", p[0]={" << (*peer_paths)[0] << "}, serverDest[0]={" << tunnelState->serverDestinations[0] << "}");