%<tt (total server time) is not computed in some cases

The total server time is not computed for CONNECT requests.
An other example case is when server-first bumping mode is used and squid
connects to SSL peer, but connection terminated before the SSL handshake
completes.

This is a Measurement Factory project

diff --git a/src/FwdState.cc b/src/FwdState.cc
index c0c45844d39ea9b7ebe5177a880e2ce5e13db74f..2ded1f79f2f857daf9810c6be55db96ab6fd14ff 100644 (file)
--- a/src/FwdState.cc
+++ b/src/FwdState.cc
@@ -242,6 +242,8 @@ FwdState::completed()
 
     flags.forward_completed = true;
 
+    request->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 921eb07c5fb7b87cc4507189f06619bb4b80951b..9091299cad20add44116613bdce6fc39f48bed90 100644 (file)
--- 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 712d5651fa76fffc49bc6c3a0e5850ce0d4189f7..fd53fe9481624ff04aac6849ea79074d54b1adeb 100644 (file)
--- 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 fe2be648c0ecebd83e6710d7bdf09fc8dce36c38..c94f06a1af7b68a4f0942b093f0d91e9f9084527 100644 (file)
--- 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 4c6853c6e96ad4663be52579c2f6286e049260ad..bd5ae9a6cf87dc178324e171873f441d6471f1af 100644 (file)
--- 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 020749c7138dfcef3820fa652dbb809cdc3a1bb2..d946df03ddcea39d2dd20a1c86a540021eae20e7 100644 (file)
--- 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 &params)
     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] << "}");