------------------------------------------------------------ revno: 13572 revision-id: chtsanti@users.sourceforge.net-20140902145401-x4ogx0oojywgadaw parent: squid3@treenet.co.nz-20140902144428-jzq69hdmbpwip3wf committer: Christos Tsantilas branch nick: trunk timestamp: Tue 2014-09-02 17:54:01 +0300 message: %hier.stopPeerClock(false); + if (EBIT_TEST(entry->flags, ENTRY_ABORTED)) { debugs(17, 3, HERE << "entry aborted"); return ; @@ -643,6 +645,8 @@ // 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 @@ 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"); === modified file 'src/HierarchyLogEntry.h' --- src/HierarchyLogEntry.h 2014-09-02 01:08:58 +0000 +++ src/HierarchyLogEntry.h 2014-09-02 14:54:01 +0000 @@ -51,6 +51,17 @@ /// 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 @@ 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 */ === modified file 'src/Server.cc' --- src/Server.cc 2014-09-02 01:08:58 +0000 +++ src/Server.cc 2014-09-02 14:54:01 +0000 @@ -196,8 +196,7 @@ 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); === modified file 'src/format/Format.cc' --- src/format/Format.cc 2014-09-02 01:08:58 +0000 +++ src/format/Format.cc 2014-09-02 14:54:01 +0000 @@ -517,14 +517,16 @@ } 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) { === modified file 'src/log/access_log.cc' --- src/log/access_log.cc 2014-09-02 01:08:58 +0000 +++ src/log/access_log.cc 2014-09-02 14:54:01 +0000 @@ -255,9 +255,9 @@ 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 @@ 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 @@ } } +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) { === modified file 'src/tunnel.cc' --- src/tunnel.cc 2014-09-02 01:08:58 +0000 +++ src/tunnel.cc 2014-09-02 14:54:01 +0000 @@ -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 @@ 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 @@ 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 @@ 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] << "}");