highOffset(0),
objectSize(0),
code (LOG_TAG_NONE),
- msec(0),
rfc931 (NULL),
extuser(NULL),
#if USE_OPENSSL
{
caddr.setNoAddr();
memset(&start_time, 0, sizeof(start_time));
+ memset(&trTime, 0, sizeof(start_time));
}
Ip::Address caddr;
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
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
* 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
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;
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 */
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
{
Adaptation::Icap::History::History():
logType(LOG_TAG_NONE),
req_sz(0),
- pastTime(0),
concurrencyLevel(0)
{
memset(¤tStart, 0, sizeof(currentStart));
+ memset(&pastTime, 0, sizeof(pastTime));
}
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)
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 ¤t) 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;
+ }
}
/// 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
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
};
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);
#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;
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);
int dofree = 0;
int64_t outoff = 0;
int dooff = 0;
+ struct timeval outtv = {0, 0};
+ int doMsec = 0;
+ int doSec = 0;
switch (fmt->type) {
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;
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:
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:
} 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) {
}
// 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;
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;
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);
}
// 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
al->cache.code = logcode;
- al->cache.msec = delay;
+ al->cache.trTime.tv_sec = delay;
accessLogLog(al, NULL);
}
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,
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(),
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);
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;
}
{
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
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);
}
}
}
(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()
{}