New %codes for computing message forwarding delays

src/AccessLogEntry.cc

@@ -8,13 +8,15 @@
 
 #include "squid.h"
 #include "AccessLogEntry.h"
+#include "CommCalls.h"
 #include "fqdncache.h"
 #include "HttpReply.h"
 #include "HttpRequest.h"
 #include "MemBuf.h"
 #include "proxyp/Header.h"
 #include "SquidConfig.h"
 #include "ssl/support.h"
+#include "StatCounters.h"
 
 void
 AccessLogEntry::getLogClientIp(char *buf, size_t bufsz) const
@@ -225,3 +227,43 @@ AccessLogEntry::packReplyHeaders(MemBuf &mb) const
         reply->packHeadersUsingFastPacker(mb);
 }
 
+void
+ReadFromClient(const AccessLogEntryPointer &ale, const size_t size, const bool hasError)
+{
+    if (size)
+        statCounter.client_http.kbytes_in += size;
+    if (!hasError && ale)
+        ale->cache.requestReadTimer.update();
+}
+
+void
+WrittenToClient(const AccessLogEntryPointer &ale, const size_t size, const bool hasError)
+{
+    if (size)
+        statCounter.client_http.kbytes_out += size;
+    if (!hasError && ale)
+        ale->cache.responseWriteTimer.update();
+}
+
+void
+WrittenToPeer(const AccessLogEntryPointer &ale, const size_t size, const bool hasError, ByteCounter &other)
+{
+    if (size) {
+        statCounter.server.all.kbytes_out += size;
+        other += size;
+    }
+    if (!hasError && ale)
+        ale->cache.requestWriteTimer.update();
+}
+
+void
+ReadFromPeer(const AccessLogEntryPointer &ale, const size_t size, const bool hasError, ByteCounter &other)
+{
+    if (size) {
+        statCounter.server.all.kbytes_in += size;
+        other += size;
+    }
+    if (!hasError && ale)
+        ale->cache.responseReadTimer.update();
+}
+

src/AccessLogEntry.h

@@ -32,11 +32,55 @@
 #include "ssl/support.h"
 #endif
 
+#include <optional>
+
 /* forward decls */
 class HttpReply;
 class HttpRequest;
 class CustomLog;
 
+// TODO: move
+/// Accumulates timings of message IO events.
+class MessageTimer
+{
+public:
+    using Clock = std::chrono::system_clock;
+    using Time = std::optional<Clock::time_point>;
+
+    MessageTimer() = default;
+    explicit MessageTimer(const Time &s) : first(s), last(s) {}
+
+    void update() {
+        last = Clock::now();
+        if (!first)
+            first = last;
+    }
+
+    void reset() { *this = MessageTimer(); }
+
+    /// the time of the first IO for the message
+    auto firstTime() const { return first; }
+
+    /// the time of the last IO for the message
+    auto lastTime() const { return last; }
+
+private:
+    Time first;
+    Time last;
+};
+
+// TODO: move
+/// measures the current time and keeps the value within a code scope
+class TimeScope
+{
+public:
+    TimeScope(MessageTimer::Time &time) : value(&time) { *value = MessageTimer::Clock::now(); }
+    ~TimeScope() { value->reset(); }
+private:
+    MessageTimer::Time *value;
+};
+
+
 class AccessLogEntry: public CodeContext
 {
 
@@ -164,6 +208,11 @@ class AccessLogEntry: public CodeContext
         Security::CertPointer sslClientCert; ///< cert received from the client
 #endif
         AnyP::PortCfgPointer port;
+
+        MessageTimer requestReadTimer; ///< first/last IO when receiving request from the client
+        MessageTimer responseWriteTimer; ///< first/last IO when writing response to the client
+        MessageTimer requestWriteTimer; ///< first/last IO when writing request to the peer
+        MessageTimer responseReadTimer; ///< first/last IO when reading response from the peer
     } cache;
 
     /** \brief This subclass holds log info for various headers in raw format
@@ -283,6 +332,21 @@ class AccessLogEntry: public CodeContext
     SBuf virginUrlForMissingRequest_;
 };
 
+class ByteCounter;
+class CommIoCbParams;
+
+/// updates stats after size bytes have been read from client
+void ReadFromClient(const AccessLogEntryPointer &ale, const size_t size, const bool hasError);
+
+/// updates stats after size bytes have been written to client
+void WrittenToClient(const AccessLogEntryPointer &ale, const size_t size, const bool hasError);
+
+/// updates stats after size bytes have been written to peer
+void WrittenToPeer(const AccessLogEntryPointer &, size_t size, bool hasError, ByteCounter &other);
+
+/// updates stats after size bytes have been read from peer
+void ReadFromPeer(const AccessLogEntryPointer &, size_t size, bool hasError, ByteCounter &other);
+
 class ACLChecklist;
 class StoreEntry;
 

src/FwdState.cc

@@ -1063,6 +1063,9 @@ FwdState::successfullyConnectedToPeer(const Comm::ConnectionPointer &conn)
 
     NoteOutgoingConnectionSuccess(serverConnection()->getPeer());
 
+    if (al)
+        al->cache.requestWriteTimer.reset();
+
     dispatch();
 }
 

src/auth/basic/NIS/nis_support.h

@@ -8,9 +8,6 @@
 #ifndef SQUID_SRC_AUTH_BASIC_NIS_NIS_SUPPORT_H
 #define SQUID_SRC_AUTH_BASIC_NIS_NIS_SUPPORT_H
 
-#ifndef SQUID_SRC_AUTH_BASIC_NIS_NIS_SUPPORT_H
-#define SQUID_SRC_AUTH_BASIC_NIS_NIS_SUPPORT_H
-
 extern char * get_nis_password(char *user, char *nisdomain, char *nismap);
 
 #endif /* SQUID_SRC_AUTH_BASIC_NIS_NIS_SUPPORT_H */

src/cf.data.pre

@@ -4868,6 +4868,28 @@ DOC_START
 			values may significantly understate or exaggerate actual times.
 			Do not use this measurement unless you know it works in your case.
 
+TODO: Reduce duplication??
+XXX: Format.
+
+event_time{name}: Approximate time of the named event in <full seconds since epoch>.<fractional seconds> format. The following events are currently supported:
+
+	request_first_read: Squid starts working with an incoming HTTP or FTP request. This event is the first successful read event for the request. A successful request read event usually corresponds to the completion of a successful socket read(2) call (including a zero-size/EOF read), but it may also be associated with discovering the request in a buffer filled when reading an earlier request (on the same client-to-Squid connection), extracting request bytes from a completed TLS handshake with the client, etc. Client-to-Squid TCP connection acceptance and client-Squid TLS handshake (if any) happen earlier. REQMOD adaptation of read bytes (if any) happens later. Failed socket reads do not trigger this event (and usually result in transaction errors).
+
+	request_last_read: The latest observed event in a series of successful request read events. See request_first_read event for the definition of a successful request read event. If the entire request was received in a single socket read(2), then this event is the same as request_first_read event.
+
+	request_first_write: Squid starts delivering an HTTP or FTP request to an origin server or cache_peer. If Squid retries or re-forwards the request, then this event corresponds to the last such attempt. For a given forwarded request, this event is the first successful write event for the request. A successful request write event corresponds to the completion of a successful socket write(2) call. REQMOD adaptation of written bytes (if any), Squid-to-peer TCP connection establishment and Squid-peer TLS handshake (if any) happen earlier. Failed socket writes do not trigger this event (and usually result in request forwarding errors).
+
+	request_last_write: The latest observed event in a series of successful request write events. See request_first_write event for the definition of a successful request write event. If the entire request was delivered in a single socket write(2), then this event is the same as request_first_write event.
+
+	response_first_read: Squid starts working with an incoming HTTP or FTP response. If Squid retries or re-forwards the request, receiving multiple responses, then this event corresponds to the last such response. For a given response, this event is the first successful read event for the response. A successful response read event corresponds to the completion of a successful socket read(2) call (including a zero-size/EOF read). Squid-to-peer TCP connection establishment and Squid-peer TLS handshake (if any) happen earlier. RESPMOD adaptation of read bytes (if any) happens later. Failed socket reads do not trigger this event (and usually result in response processing errors).
+
+	response_last_read: The latest observed event in a series of successful response read events. See response_first_read event for the definition of a successful response read event. If the entire response was received in a single socket read(2), then this event is the same as response_first_read event.
+
+	response_first_write: Squid starts delivering an HTTP or FTP response to a client. This event is the first successful write event for the response. A successful response write event corresponds to the completion of a successful socket write(2) call. RESPMOD adaptation of written bytes (if any) happens earlier. Failed socket writes do not trigger this event (and usually result in transaction errors).
+
+	response_last_write: The latest observed event in a series of successful response write events. See response_first_write event for the definition of a successful response write event. If the entire response was delivered in a single socket write(2), then this event is the same as response_first_write event.
+
+
 	Access Control related format codes:
 
 		et	Tag returned by external acl

src/client_side.cc

@@ -1028,7 +1028,7 @@ ConnStateData::afterClientWrite(size_t size)
 
     auto ctx = pipeline.front();
     if (size) {
-        statCounter.client_http.kbytes_out += size;
+        WrittenToClient(ctx->http->al, size, false);
         if (ctx->http->loggingTags().isTcpHit())
             statCounter.client_http.hit_kbytes_out += size;
     }

src/client_side.h

@@ -11,6 +11,7 @@
 #ifndef SQUID_SRC_CLIENT_SIDE_H
 #define SQUID_SRC_CLIENT_SIDE_H
 
+#include "AccessLogEntry.h"
 #include "acl/ChecklistFiller.h"
 #include "base/RunnersRegistry.h"
 #include "clientStreamForward.h"
@@ -384,6 +385,10 @@ class ConnStateData:
     /// managers logging of the being-accepted TLS connection secrets
     Security::KeyLogger keyLogger;
 
+    /// parseOneRequest() start time
+    /// nil outside parseOneRequest() scope
+    MessageTimer::Time requestParseStart;
+
 protected:
     void startDechunkingRequest();
     void finishDechunkingRequest(bool withSuccess);

src/client_side_request.cc

@@ -134,6 +134,7 @@ ClientHttpRequest::ClientHttpRequest(ConnStateData * aConn) :
 {
     CodeContext::Reset(al);
     al->cache.start_time = current_time;
+    al->cache.requestReadTimer = MessageTimer(aConn->requestParseStart ? aConn->requestParseStart : MessageTimer::Clock::now());
     if (aConn) {
         al->tcpClient = aConn->clientConnection;
         al->cache.port = aConn->port;

src/clients/Client.cc

@@ -369,8 +369,6 @@ Client::sentRequestBody(const CommIoCbParams &io)
 
     if (io.size > 0) {
         fd_bytes(io.fd, io.size, FD_WRITE);
-        statCounter.server.all.kbytes_out += io.size;
-        // kids should increment their counters
     }
 
     if (io.flag == Comm::ERR_CLOSING)

src/clients/FtpClient.cc

@@ -364,8 +364,7 @@ Ftp::Client::readControlReply(const CommIoCbParams &io)
     debugs(9, 3, "FD " << io.fd << ", Read " << io.size << " bytes");
 
     if (io.size > 0) {
-        statCounter.server.all.kbytes_in += io.size;
-        statCounter.server.ftp.kbytes_in += io.size;
+        ReadFromPeer(fwd->al, io.size, io.flag, statCounter.server.ftp.kbytes_in);
     }
 
     if (io.flag == Comm::ERR_CLOSING)
@@ -859,8 +858,7 @@ Ftp::Client::writeCommandCallback(const CommIoCbParams &io)
 
     if (io.size > 0) {
         fd_bytes(io.fd, io.size, FD_WRITE);
-        statCounter.server.all.kbytes_out += io.size;
-        statCounter.server.ftp.kbytes_out += io.size;
+        WrittenToPeer(fwd->al, io.size, io.flag, statCounter.server.ftp.kbytes_out);
     }
 
     if (io.flag == Comm::ERR_CLOSING)
@@ -964,8 +962,7 @@ Ftp::Client::dataRead(const CommIoCbParams &io)
     debugs(9, 3, "FD " << io.fd << " Read " << io.size << " bytes");
 
     if (io.size > 0) {
-        statCounter.server.all.kbytes_in += io.size;
-        statCounter.server.ftp.kbytes_in += io.size;
+        ReadFromPeer(fwd->al, io.size, io.flag, statCounter.server.ftp.kbytes_in);
     }
 
     if (io.flag == Comm::ERR_CLOSING)
@@ -1006,6 +1003,8 @@ Ftp::Client::dataRead(const CommIoCbParams &io)
         }
     } else if (io.size == 0) {
         debugs(9, 3, "Calling dataComplete() because io.size == 0");
+        fwd->al->cache.responseReadTimer.update();
+
         /*
          * DPW 2007-04-23
          * Dangerous curves ahead.  This call to dataComplete was
@@ -1078,7 +1077,7 @@ void
 Ftp::Client::sentRequestBody(const CommIoCbParams &io)
 {
     if (io.size > 0)
-        statCounter.server.ftp.kbytes_out += io.size;
+        WrittenToPeer(fwd->al, io.size, io.flag, statCounter.server.ftp.kbytes_out);
     ::Client::sentRequestBody(io);
 }
 

src/clients/HttpTunneler.cc

@@ -190,8 +190,7 @@ Http::Tunneler::handleWrittenRequest(const CommIoCbParams &io)
         return;
     }
 
-    statCounter.server.all.kbytes_out += io.size;
-    statCounter.server.other.kbytes_out += io.size;
+    WrittenToPeer(al, io.size, io.flag, statCounter.server.other.kbytes_out);
     requestWritten = true;
     debugs(83, 5, status());
 }
@@ -224,15 +223,15 @@ Http::Tunneler::handleReadyRead(const CommIoCbParams &io)
 #if USE_DELAY_POOLS
         delayId.bytesIn(rd.size);
 #endif
-        statCounter.server.all.kbytes_in += rd.size;
-        statCounter.server.other.kbytes_in += rd.size; // TODO: other or http?
+        ReadFromPeer(al, io.size, io.flag, statCounter.server.other.kbytes_in);  // TODO: other or http?
         request->hier.notePeerRead();
         handleResponse(false);
         return;
     }
 
     case Comm::ENDFILE: {
         // TODO: Should we (and everybody else) call request->hier.notePeerRead() on zero reads?
+        al->cache.responseReadTimer.update();
         handleResponse(true);
         return;
     }

src/format/ByteCode.h

@@ -160,6 +160,14 @@ typedef enum {
     LFT_TIME_LOCALTIME,
     LFT_TIME_GMT,
     LFT_TIME_START, // the time the master transaction started
+    LFT_REQUEST_FIRST_READ,
+    LFT_REQUEST_LAST_READ,
+    LFT_REQUEST_FIRST_WRITE,
+    LFT_REQUEST_LAST_WRITE,
+    LFT_RESPONSE_FIRST_READ,
+    LFT_RESPONSE_LAST_READ,
+    LFT_RESPONSE_FIRST_WRITE,
+    LFT_RESPONSE_LAST_WRITE,
 
     /* processing time details */
     LFT_TIME_TO_HANDLE_REQUEST,

src/format/Format.cc

@@ -373,6 +373,18 @@ actualRequestHeader(const AccessLogEntry::Pointer &al)
     return al->request;
 }
 
+static void
+TimePointToTimeval(MessageTimer::Time time, timeval &outtv, int &doMsec) {
+    if (!time)
+        return;
+    using namespace std::chrono_literals;
+    const auto duration = time->time_since_epoch();
+    outtv.tv_sec = std::chrono::duration_cast<std::chrono::seconds>(duration).count();
+    const auto totalUsec = std::chrono::duration_cast<std::chrono::microseconds>(duration);
+    outtv.tv_usec = (totalUsec % std::chrono::microseconds(1s)).count();
+    doMsec = 1;
+}
+
 void
 Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logSequenceNumber) const
 {
@@ -653,6 +665,37 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
                 doMsec = 1;
             }
             break;
+        case LFT_REQUEST_FIRST_READ:
+            TimePointToTimeval(al->cache.requestReadTimer.firstTime(), outtv, doMsec);
+            break;
+
+        case LFT_REQUEST_LAST_READ:
+            TimePointToTimeval(al->cache.requestReadTimer.lastTime(), outtv, doMsec);
+            break;
+
+        case LFT_REQUEST_FIRST_WRITE:
+            TimePointToTimeval(al->cache.requestWriteTimer.firstTime(), outtv, doMsec);
+            break;
+
+        case LFT_REQUEST_LAST_WRITE:
+            TimePointToTimeval(al->cache.requestWriteTimer.lastTime(), outtv, doMsec);
+            break;
+
+        case LFT_RESPONSE_FIRST_READ:
+            TimePointToTimeval(al->cache.responseReadTimer.firstTime(), outtv, doMsec);
+            break;
+
+        case LFT_RESPONSE_LAST_READ:
+            TimePointToTimeval(al->cache.responseReadTimer.lastTime(), outtv, doMsec);
+            break;
+
+        case LFT_RESPONSE_FIRST_WRITE:
+            TimePointToTimeval(al->cache.responseWriteTimer.firstTime(), outtv, doMsec);
+            break;
+
+        case LFT_RESPONSE_LAST_WRITE:
+            TimePointToTimeval(al->cache.responseWriteTimer.lastTime(), outtv, doMsec);
+            break;
 
         case LFT_REQUEST_HEADER:
             if (const Http::Message *msg = actualRequestHeader(al)) {