From: Christos Tsantilas <chtsanti@users.sourceforge.net>
Date: Thu, 20 Nov 2014 08:57:14 +0000 (+0200)
Subject: Logging fast things
X-Git-Tag: merge-candidate-3-v1~483
X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=01bd87d861361032aeb9f8bfda938581bfa43101;p=thirdparty%2Fsquid.git

Logging fast things

In many cases HITs logged with zero response times. The logging entries are
correct, those transaction took less than a millisecond. However, to better
monitor Squid performance and to optimize things further, a user may want to
see more precise response time measurements logged.

Squid already computes response times with microsecond resolution
(timeval::tv_usec), which would be enough for any modern measurement, but
Squid loses that precision due to tvSubMs conversion.

This patch add configurable "precision" for time-related fields such as %tr,
using a .n syntax similar to the syntax used by the well-known printf(3) API
to mean "maximum field width".

Examples:
  %tr   -- 0 -- millisecond precision (no change compared to today)
  %.3tr -- 0.123 -- microsecond precision (after this project)
  %.6tr -- 0.123456 -- nanosecond precision (year 2050 trading platform??)

This is a Measurement Factory project
---

diff --git a/src/AccessLogEntry.h b/src/AccessLogEntry.h
index 63ed1fedfd..6aef0eac01 100644
--- a/src/AccessLogEntry.h
+++ b/src/AccessLogEntry.h
@@ -141,7 +141,6 @@ public:
                 highOffset(0),
                 objectSize(0),
                 code (LOG_TAG_NONE),
-                msec(0),
                 rfc931 (NULL),
                 extuser(NULL),
 #if USE_OPENSSL
@@ -151,6 +150,7 @@ public:
         {
             caddr.setNoAddr();
             memset(&start_time, 0, sizeof(start_time));
+            memset(&trTime, 0, sizeof(start_time));
         }
 
         Ip::Address caddr;
@@ -158,7 +158,7 @@ public:
         int64_t objectSize;
         LogTags code;
         struct timeval start_time; ///< The time the master transaction started
-        int msec;
+        struct timeval trTime; ///< The response time
         const char *rfc931;
         const char *extuser;
 #if USE_OPENSSL
@@ -231,8 +231,12 @@ public:
     public:
         IcapLogEntry() : reqMethod(Adaptation::methodNone), bytesSent(0), bytesRead(0),
                 bodyBytesRead(-1), request(NULL), reply(NULL),
-                outcome(Adaptation::Icap::xoUnknown), trTime(0),
-                ioTime(0), resStatus(Http::scNone), processingTime(0) {}
+                outcome(Adaptation::Icap::xoUnknown), resStatus(Http::scNone)
+        {
+            memset(&trTime, 0, sizeof(trTime));
+            memset(&ioTime, 0, sizeof(ioTime));
+            memset(&processingTime, 0, sizeof(processingTime));
+        }
 
         Ip::Address hostAddr; ///< ICAP server IP address
         String serviceName;        ///< ICAP service name
@@ -253,15 +257,15 @@ public:
          * The timer starts when the ICAP transaction
          *  is created and stops when the result of the transaction is logged
          */
-        int trTime;
+        struct timeval trTime;
         /** \brief Transaction I/O time.
          * The timer starts when the first ICAP request
          * byte is scheduled for sending and stops when the lastbyte of the
          * ICAP response is received.
          */
-        int ioTime;
+        struct timeval ioTime;
         Http::StatusCode resStatus;   ///< ICAP response status code
-        int processingTime;      ///< total ICAP processing time in milliseconds
+        struct timeval processingTime;      ///< total ICAP processing time
     }
     icap;
 #endif
diff --git a/src/HierarchyLogEntry.h b/src/HierarchyLogEntry.h
index a395295fd0..9bcd6d000a 100644
--- a/src/HierarchyLogEntry.h
+++ b/src/HierarchyLogEntry.h
@@ -37,7 +37,7 @@ public:
     void stopPeerClock(const bool force);
 
     /// Return the total time spent communicating with peers
-    int64_t totalResponseTime();
+    void totalResponseTime(struct timeval &responseTime);
 
 public:
     hier_code code;
@@ -54,13 +54,13 @@ 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
+    struct timeval peer_response_time; ///< last peer response delay
     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
 
 private:
     timeval firstConnStart_; ///< first connection use among all peers
-    int64_t totalResponseTime_; ///< cumulative for all peers
+    struct timeval totalResponseTime_; ///< cumulative for all peers
 };
 
 #endif /* SQUID_HTTPHIERARCHYLOGENTRY_H */
diff --git a/src/SquidTime.h b/src/SquidTime.h
index 99b618d30d..585eab84b6 100644
--- a/src/SquidTime.h
+++ b/src/SquidTime.h
@@ -24,6 +24,24 @@ extern time_t squid_curtime;
 time_t getCurrentTime(void);
 int tvSubMsec(struct timeval, struct timeval);
 
+/// timeval substraction operation
+/// \param[out] res = t2 - t1
+void tvSub(struct timeval &res, struct timeval const &t1, struct timeval const &t2);
+
+/// timeval addition operation
+/// \param[out] res = t1 + t2
+void tvAdd(struct timeval &res, struct timeval const &t1, struct timeval const &t2);
+
+/// timeval addition assignment operation
+/// \param[out] t += add
+void tvAssignAdd(struct timeval &t, struct timeval const &add);
+
+/// Convert timeval to milliseconds
+inline long int tvToMsec(struct timeval &t)
+{
+    return t.tv_sec * 1000 + t.tv_usec / 1000;
+}
+
 /** event class for doing synthetic time etc */
 class TimeEngine
 {
diff --git a/src/adaptation/icap/History.cc b/src/adaptation/icap/History.cc
index a32b96619e..62e9537585 100644
--- a/src/adaptation/icap/History.cc
+++ b/src/adaptation/icap/History.cc
@@ -15,10 +15,10 @@
 Adaptation::Icap::History::History():
         logType(LOG_TAG_NONE),
         req_sz(0),
-        pastTime(0),
         concurrencyLevel(0)
 {
     memset(&currentStart, 0, sizeof(currentStart));
+    memset(&pastTime, 0, sizeof(pastTime));
 }
 
 void Adaptation::Icap::History::start(const char *context)
@@ -27,7 +27,7 @@ void Adaptation::Icap::History::start(const char *context)
         currentStart = current_time;
 
     debugs(93,4, HERE << "start " << context << " level=" << concurrencyLevel
-           << " time=" << pastTime << ' ' << this);
+           << " time=" << tvToMsec(pastTime) << ' ' << this);
 }
 
 void Adaptation::Icap::History::stop(const char *context)
@@ -37,23 +37,30 @@ void Adaptation::Icap::History::stop(const char *context)
         return;
     }
 
-    const int current = currentTime();
+    struct timeval current;
+    currentTime(current);
     debugs(93,4, HERE << "stop " << context << " level=" << concurrencyLevel <<
-           " time=" << pastTime << '+' << current << ' ' << this);
+           " time=" << tvToMsec(pastTime) << '+' << tvToMsec(current) << ' ' << this);
 
     if (!--concurrencyLevel)
-        pastTime += current;
+        tvAssignAdd(pastTime, current);
 }
 
-int Adaptation::Icap::History::processingTime() const
+void
+Adaptation::Icap::History::processingTime(timeval &total) const
 {
-    const int total = pastTime + currentTime();
-    debugs(93,7, HERE << " current total: " << total << ' ' << this);
-    return total;
+    currentTime(total);
+    tvAssignAdd(total, pastTime);
+    debugs(93,7, HERE << " current total: " << tvToMsec(total) << ' ' << this);
 }
 
-int Adaptation::Icap::History::currentTime() const
+void
+Adaptation::Icap::History::currentTime(timeval &current) const
 {
-    return concurrencyLevel > 0 ?
-           max(0, tvSubMsec(currentStart, current_time)) : 0;
+    if (concurrencyLevel > 0)
+        tvSub(current, currentStart, current_time);
+    else {
+        current.tv_sec = 0;
+        current.tv_usec = 0;
+    }
 }
diff --git a/src/adaptation/icap/History.h b/src/adaptation/icap/History.h
index b7a6ab9145..db087cdc98 100644
--- a/src/adaptation/icap/History.h
+++ b/src/adaptation/icap/History.h
@@ -32,8 +32,9 @@ public:
     /// note the end of an ICAP processing interval
     void stop(const char *context);
 
-    /// returns the total time of all ICAP processing intervals
-    int processingTime() const;
+    /// the total time of all ICAP processing intervals
+    /// \param[out] total time taken for all ICAP processing
+    void processingTime(struct timeval &total) const;
 
     String rfc931; ///< the username from ident
 #if USE_OPENSSL
@@ -45,10 +46,10 @@ public:
     size_t req_sz; ///< the request size
 
 private:
-    int currentTime() const; ///< time since current start or zero
+    void currentTime(struct timeval &) const; ///< time since current start or zero
 
     timeval currentStart; ///< when the current processing interval started
-    int pastTime;         ///< sum of closed processing interval durations
+    struct timeval pastTime; ///< sum of closed processing interval durations
     int concurrencyLevel; ///< number of concurrent processing threads
 };
 
diff --git a/src/adaptation/icap/Xaction.cc b/src/adaptation/icap/Xaction.cc
index b69d040159..17035440ef 100644
--- a/src/adaptation/icap/Xaction.cc
+++ b/src/adaptation/icap/Xaction.cc
@@ -575,8 +575,8 @@ void Adaptation::Icap::Xaction::finalizeLogInfo()
     al.icap.serviceName = s.cfg().key;
     al.icap.reqUri = s.cfg().uri;
 
-    al.icap.ioTime = tvSubMsec(icap_tio_start, icap_tio_finish);
-    al.icap.trTime = tvSubMsec(icap_tr_start, current_time);
+    tvSub(al.icap.ioTime, icap_tio_start, icap_tio_finish);
+    tvSub(al.icap.trTime, icap_tr_start, current_time);
 
     al.icap.request = icapRequest;
     HTTPMSGLOCK(al.icap.request);
diff --git a/src/client_side.cc b/src/client_side.cc
index f885b018fc..486b4de846 100644
--- a/src/client_side.cc
+++ b/src/client_side.cc
@@ -551,7 +551,7 @@ prepareLogWithRequestDetails(HttpRequest * request, AccessLogEntry::Pointer &aLo
 #if ICAP_CLIENT
     const Adaptation::Icap::History::Pointer ih = request->icapHistory();
     if (ih != NULL)
-        aLogEntry->icap.processingTime = ih->processingTime();
+        ih->processingTime(aLogEntry->icap.processingTime);
 #endif
 
     aLogEntry->http.method = request->method;
@@ -603,7 +603,7 @@ ClientHttpRequest::logRequest()
 
     al->cache.code = logType;
 
-    al->cache.msec = tvSubMsec(al->cache.start_time, current_time);
+    tvSub(al->cache.trTime, al->cache.start_time, current_time);
 
     if (request)
         prepareLogWithRequestDetails(request, al);
diff --git a/src/format/Format.cc b/src/format/Format.cc
index 7a6a11bc40..82d743b0a8 100644
--- a/src/format/Format.cc
+++ b/src/format/Format.cc
@@ -323,6 +323,9 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
         int dofree = 0;
         int64_t outoff = 0;
         int dooff = 0;
+        struct timeval outtv = {0, 0};
+        int doMsec = 0;
+        int doSec = 0;
 
         switch (fmt->type) {
 
@@ -504,42 +507,44 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
 
         break;
 
-        case LFT_TIME_START: {
-            int precision = fmt->widthMax >=0 ? fmt->widthMax :3;
-            snprintf(tmp, sizeof(tmp), "%0*" PRId64 ".%0*d", fmt->zero && (fmt->widthMin - precision - 1 >= 0) ? fmt->widthMin - precision - 1 : 0, static_cast<int64_t>(al->cache.start_time.tv_sec), precision, (int)(al->cache.start_time.tv_usec / fmt->divisor));
-            out = tmp;
-        }
+        case LFT_TIME_START:
+            outtv = al->cache.start_time;
+            doSec = 1;
         break;
 
         case LFT_TIME_TO_HANDLE_REQUEST:
-            outint = al->cache.msec;
-            doint = 1;
+            outtv = al->cache.trTime;
+            doMsec = 1;
             break;
 
         case LFT_PEER_RESPONSE_TIME:
-            if (al->hier.peer_response_time < 0) {
+            if (al->hier.peer_response_time.tv_sec ==  -1) {
                 out = "-";
             } else {
-                outoff = al->hier.peer_response_time;
-                dooff = 1;
+                outtv = al->hier.peer_response_time;
+                doMsec = 1;
             }
             break;
 
         case LFT_TOTAL_SERVER_SIDE_RESPONSE_TIME: {
-            const int64_t total_response_time = al->hier.totalResponseTime();
-            if (total_response_time < 0) {
+            timeval total_response_time;
+            al->hier.totalResponseTime(total_response_time);
+            if (total_response_time.tv_sec == -1) {
                 out = "-";
             } else {
-                outoff = total_response_time;
-                dooff = 1;
+                outtv = total_response_time;
+                doMsec = 1;
             }
         }
         break;
 
         case LFT_DNS_WAIT_TIME:
             if (al->request && al->request->dnsWait >= 0) {
-                outint = al->request->dnsWait;
-                doint = 1;
+                // TODO: microsecond precision for dns wait time.
+                // Convert miliseconds to timeval struct:
+                outtv.tv_sec = al->request->dnsWait / 1000;
+                outtv.tv_usec = (al->request->dnsWait % 1000) * 1000;
+                doMsec = 1;
             }
             break;
 
@@ -731,13 +736,13 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             break;
 
         case LFT_ICAP_TR_RESPONSE_TIME:
-            outint = al->icap.trTime;
-            doint = 1;
+            outtv = al->icap.trTime;
+            doMsec = 1;
             break;
 
         case LFT_ICAP_IO_TIME:
-            outint = al->icap.ioTime;
-            doint = 1;
+            outtv = al->icap.ioTime;
+            doMsec = 1;
             break;
 
         case LFT_ICAP_STATUS_CODE:
@@ -750,8 +755,8 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             break;
 
         case LFT_ICAP_TOTAL_TIME:
-            outint = al->icap.processingTime;
-            doint = 1;
+            outtv = al->icap.processingTime;
+            doMsec = 1;
             break;
 #endif
         case LFT_REQUEST_HEADER_ELEM:
@@ -1234,6 +1239,18 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
         } else if (doint) {
             snprintf(tmp, sizeof(tmp), "%0*ld", fmt->zero && fmt->widthMin >= 0 ? fmt->widthMin : 0, outint);
             out = tmp;
+        } else if (doMsec) {
+            if (fmt->widthMax < 0) {
+                snprintf(tmp, sizeof(tmp), "%0*ld", fmt->widthMin , tvToMsec(outtv));
+            } else {
+                int precision = fmt->widthMax;
+                snprintf(tmp, sizeof(tmp), "%0*" PRId64 ".%0*" PRId64 "", fmt->zero && (fmt->widthMin - precision - 1 >= 0) ? fmt->widthMin - precision - 1 : 0, static_cast<int64_t>(outtv.tv_sec * 1000 + outtv.tv_usec / 1000), precision, static_cast<int64_t>((outtv.tv_usec % 1000 )* (1000 / fmt->divisor)));
+            }
+            out = tmp;
+        } else if (doSec) {
+            int precision = fmt->widthMax >=0 ? fmt->widthMax :3;
+            snprintf(tmp, sizeof(tmp), "%0*" PRId64 ".%0*d", fmt->zero && (fmt->widthMin - precision - 1 >= 0) ? fmt->widthMin - precision - 1 : 0, static_cast<int64_t>(outtv.tv_sec), precision, (int)(outtv.tv_usec / fmt->divisor));
+            out = tmp;
         }
 
         if (out && *out) {
@@ -1282,7 +1299,7 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             }
 
             // enforce width limits if configured
-            const bool haveMaxWidth = fmt->widthMax >=0 && !doint && !dooff && !fmt->divisor;
+            const bool haveMaxWidth = fmt->widthMax >=0 && !doint && !dooff && !doMsec && !doSec;
             if (haveMaxWidth || fmt->widthMin) {
                 const int minWidth = fmt->widthMin >= 0 ?
                                      fmt->widthMin :0;
diff --git a/src/format/Token.cc b/src/format/Token.cc
index e2c008bf4e..6ab45a8bcb 100644
--- a/src/format/Token.cc
+++ b/src/format/Token.cc
@@ -507,6 +507,13 @@ Format::Token::parse(const char *def, Quoting *quoting)
         Config.onoff.log_fqdn = 1;
         break;
 
+    case LFT_TIME_TO_HANDLE_REQUEST:
+    case LFT_PEER_RESPONSE_TIME:
+    case LFT_TOTAL_SERVER_SIDE_RESPONSE_TIME:
+    case LFT_DNS_WAIT_TIME:
+    case LFT_ICAP_TR_RESPONSE_TIME:
+    case LFT_ICAP_IO_TIME:
+    case LFT_ICAP_TOTAL_TIME:
     case LFT_TIME_START:
     case LFT_TIME_SUBSECOND:
         divisor = 1000;
diff --git a/src/htcp.cc b/src/htcp.cc
index faa2f6cc29..9519d702b8 100644
--- a/src/htcp.cc
+++ b/src/htcp.cc
@@ -1708,6 +1708,7 @@ htcpLogHtcp(Ip::Address &caddr, int opcode, LogTags logcode, const char *url)
     al->url = url;
     al->cache.caddr = caddr;
     al->cache.code = logcode;
-    al->cache.msec = 0;
+    al->cache.trTime.tv_sec = 0;
+    al->cache.trTime.tv_usec = 0;
     accessLogLog(al, NULL);
 }
diff --git a/src/http.cc b/src/http.cc
index 48adde746f..d296989f66 100644
--- a/src/http.cc
+++ b/src/http.cc
@@ -1160,8 +1160,10 @@ HttpStateData::readReply(const CommIoCbParams &io)
 
         // update peer response time stats (%<pt)
         const timeval &sent = request->hier.peer_http_request_sent;
-        request->hier.peer_response_time =
-            sent.tv_sec ? tvSubMsec(sent, current_time) : -1;
+        if (sent.tv_sec)
+            tvSub(request->hier.peer_response_time, sent, current_time);
+        else
+            request->hier.peer_response_time.tv_sec = -1;
     }
 
     /** \par
diff --git a/src/icp_v2.cc b/src/icp_v2.cc
index fbcd9e0a62..bdb9f1f21b 100644
--- a/src/icp_v2.cc
+++ b/src/icp_v2.cc
@@ -203,7 +203,7 @@ icpLogIcp(const Ip::Address &caddr, LogTags logcode, int len, const char *url, i
 
     al->cache.code = logcode;
 
-    al->cache.msec = delay;
+    al->cache.trTime.tv_sec = delay;
 
     accessLogLog(al, NULL);
 }
diff --git a/src/log/FormatSquidIcap.cc b/src/log/FormatSquidIcap.cc
index fa673fd853..cf05b95390 100644
--- a/src/log/FormatSquidIcap.cc
+++ b/src/log/FormatSquidIcap.cc
@@ -56,10 +56,10 @@ Log::Format::SquidIcap(const AccessLogEntry::Pointer &al, Logfile * logfile)
     if (user && !*user)
         safe_free(user);
 
-    logfilePrintf(logfile, "%9ld.%03d %6d %s %s/%03d %" PRId64 " %s %s %s -/%s -\n",
+    logfilePrintf(logfile, "%9ld.%03d %6ld %s %s/%03d %" PRId64 " %s %s %s -/%s -\n",
                   (long int) current_time.tv_sec,
                   (int) current_time.tv_usec / 1000,
-                  al->icap.trTime,
+                  tvToMsec(al->icap.trTime),
                   client,
                   al->icap.outcome,
                   al->icap.resStatus,
diff --git a/src/log/FormatSquidNative.cc b/src/log/FormatSquidNative.cc
index ed96f0fd55..a5fb9011fb 100644
--- a/src/log/FormatSquidNative.cc
+++ b/src/log/FormatSquidNative.cc
@@ -54,10 +54,10 @@ Log::Format::SquidNative(const AccessLogEntry::Pointer &al, Logfile * logfile)
     else
         method = al->http.method.image();
 
-    logfilePrintf(logfile, "%9ld.%03d %6d %s %s%s/%03d %" PRId64 " " SQUIDSBUFPH " %s %s %s%s/%s %s%s",
+    logfilePrintf(logfile, "%9ld.%03d %6ld %s %s%s/%03d %" PRId64 " " SQUIDSBUFPH " %s %s %s%s/%s %s%s",
                   (long int) current_time.tv_sec,
                   (int) current_time.tv_usec / 1000,
-                  al->cache.msec,
+                  tvToMsec(al->cache.trTime),
                   clientip,
                   LogTags_str[al->cache.code],
                   al->http.statusSfx(),
diff --git a/src/log/access_log.cc b/src/log/access_log.cc
index 7bc72a8693..c9356f59da 100644
--- a/src/log/access_log.cc
+++ b/src/log/access_log.cc
@@ -232,10 +232,8 @@ HierarchyLogEntry::HierarchyLogEntry() :
         n_choices(0),
         n_ichoices(0),
         peer_reply_status(Http::scNone),
-        peer_response_time(-1),
         tcpServer(NULL),
-        bodyBytesRead(-1),
-        totalResponseTime_(-1)
+        bodyBytesRead(-1)
 {
     memset(host, '\0', SQUIDHOSTNAMELEN);
     memset(cd_host, '\0', SQUIDHOSTNAMELEN);
@@ -249,6 +247,12 @@ HierarchyLogEntry::HierarchyLogEntry() :
     peer_http_request_sent.tv_sec = 0;
     peer_http_request_sent.tv_usec = 0;
 
+    peer_response_time.tv_sec = -1;
+    peer_response_time.tv_usec = 0;
+
+    totalResponseTime_.tv_sec = -1;
+    totalResponseTime_.tv_usec = 0;
+
     firstConnStart_.tv_sec = 0;
     firstConnStart_.tv_usec = 0;
 }
@@ -284,24 +288,25 @@ 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_ <<
+           ", current total response time value: " << (totalResponseTime_.tv_sec * 1000 +  totalResponseTime_.tv_usec/1000) <<
            (force ? ", force fixing" : ""));
-    if (!force && totalResponseTime_ >= 0)
+    if (!force && totalResponseTime_.tv_sec != -1)
         return;
 
-    totalResponseTime_ = firstConnStart_.tv_sec ? tvSubMsec(firstConnStart_, current_time) : -1;
+    if (firstConnStart_.tv_sec)
+        tvSub(totalResponseTime_, firstConnStart_, current_time);
 }
 
-int64_t
-HierarchyLogEntry::totalResponseTime()
+void
+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_ < 0)
+    if (firstConnStart_.tv_sec && totalResponseTime_.tv_sec == -1)
         stopPeerClock(false);
 
-    return totalResponseTime_;
+    responseTime = totalResponseTime_;
 }
 
 static void
diff --git a/src/neighbors.cc b/src/neighbors.cc
index e3d1c1f45d..79bcbe9195 100644
--- a/src/neighbors.cc
+++ b/src/neighbors.cc
@@ -670,7 +670,7 @@ neighborsUdpPing(HttpRequest * request,
 
                     query = _icp_common_t::createMessage(ICP_QUERY, flags, url, reqnum, 0);
 
-                    icpUdpSend(icpOutgoingConn->fd, p->in_addr, query, LOG_ICP_QUERY, 0);
+                    icpUdpSend(icpOutgoingConn->fd, p->in_addr, query, LOG_ICP_QUERY, 0.0);
                 }
             }
         }
diff --git a/src/time.cc b/src/time.cc
index 8159ecaf6d..6b2dc33bcb 100644
--- a/src/time.cc
+++ b/src/time.cc
@@ -37,6 +37,38 @@ tvSubMsec(struct timeval t1, struct timeval t2)
            (t2.tv_usec - t1.tv_usec) / 1000;
 }
 
+void
+tvSub(struct timeval &res, struct timeval const &t1, struct timeval const &t2)
+{
+    res.tv_sec = t2.tv_sec - t1.tv_sec;
+    if (t2.tv_usec >= t1.tv_usec)
+        res.tv_usec = t2.tv_usec - t1.tv_usec;
+    else {
+        res.tv_sec -= 1;
+        res.tv_usec = t2.tv_usec + 1000000 - t1.tv_usec;
+    }
+}
+
+void tvAdd(struct timeval &res, struct timeval const &t1, struct timeval const &t2)
+{
+    res.tv_sec = t1.tv_sec + t2.tv_sec;
+    res.tv_usec = t1.tv_usec + t2.tv_usec;
+    if (res.tv_usec >= 1000000) {
+        ++res.tv_sec;
+        res.tv_usec -= 1000000;
+    }
+}
+
+void tvAssignAdd(struct timeval &t, struct timeval const &add)
+{
+    t.tv_sec += add.tv_sec;
+    t.tv_usec += add.tv_usec;
+    if (t.tv_usec >= 1000000) {
+        ++t.tv_sec;
+        t.tv_usec -= 1000000;
+    }
+}
+
 TimeEngine::~TimeEngine()
 {}