Hi all,
The total server time is not computed in some cases, for example 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.
The attached patch is trying to fix these cases.
This is a Measurement Factory project
%<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
=== modified file 'src/FwdState.cc'
--- src/FwdState.cc 2014-08-26 09:01:27 +0000
+++ src/FwdState.cc 2014-08-27 10:31:20 +0000
@@ -225,40 +225,42 @@
p = new Comm::Connection();
p->peerType = ORIGINAL_DST;
p->remote = clientConn->local;
getOutgoingAddress(request, p);
debugs(17, 3, HERE << "using client original destination: " << *p);
serverDestinations.push_back(p);
}
#endif
void
FwdState::completed()
{
if (flags.forward_completed) {
debugs(17, DBG_IMPORTANT, HERE << "FwdState::completed called on a completed request! Bad!");
return;
}
flags.forward_completed = true;
+ request->hier.stopPeerClock(false);
+
if (EBIT_TEST(entry->flags, ENTRY_ABORTED)) {
debugs(17, 3, HERE << "entry aborted");
return ;
}
#if URL_CHECKSUM_DEBUG
entry->mem_obj->checkUrlChecksum();
#endif
if (entry->store_status == STORE_PENDING) {
if (entry->isEmpty()) {
if (!err) // we quit (e.g., fd closed) before an error or content
fail(new ErrorState(ERR_READ_ERROR, Http::scBadGateway, request));
assert(err);
errorAppendEntry(entry, err);
err = NULL;
#if USE_OPENSSL
if (request->flags.sslPeek && request->clientConnectionManager.valid()) {
CallJobHere1(17, 4, request->clientConnectionManager, ConnStateData,
@@ -626,40 +628,42 @@
retryOrBail();
}
void
FwdState::retryOrBail()
{
if (checkRetry()) {
debugs(17, 3, HERE << "re-forwarding (" << n_tries << " tries, " << (squid_curtime - start_t) << " secs)");
// we should retry the same destination if it failed due to pconn race
if (pconnRace == raceHappened)
debugs(17, 4, HERE << "retrying the same destination");
else
serverDestinations.erase(serverDestinations.begin()); // last one failed. try another.
startConnectionOrFail();
return;
}
// 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);
}
self = NULL; // refcounted
}
// If the Server quits before nibbling at the request body, the body sender
// will not know (so that we can retry). Call this if we will not retry. We
// will notify the sender so that it does not get stuck waiting for space.
void
FwdState::doneWithRetries()
{
if (request && request->body_pipe != NULL)
request->body_pipe->expectNoConsumption();
}
// called by the server that failed after calling unregister()
void
@@ -781,42 +785,41 @@
ftimeout = 5;
if (ftimeout < ctimeout)
return (time_t)ftimeout;
else
return (time_t)ctimeout;
}
/**
* Called after forwarding path selection (via peer select) has taken place
* and whenever forwarding needs to attempt a new connection (routing failover).
* We have a vector of possible localIP->remoteIP paths now ready to start being connected.
*/
void
FwdState::connectStart()
{
assert(serverDestinations.size() > 0);
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");
ErrorState *anErr = new ErrorState(ERR_CANNOT_FORWARD, Http::scServiceUnavailable, request);
fail(anErr);
self = NULL; // refcounted
return;
}
request->flags.pinned = false; // XXX: what if the ConnStateData set this to flag existing credentials?
// XXX: answer: the peer selection *should* catch it and give us only the pinned peer. so we reverse the =0 step below.
// XXX: also, logs will now lie if pinning is broken and leads to an error message.
if (serverDestinations[0]->peerType == PINNED) {
ConnStateData *pinned_connection = request->pinnedConnection();
debugs(17,7, "pinned peer connection: " << pinned_connection);
// pinned_connection may become nil after a pconn race
if (pinned_connection)
serverConn = pinned_connection->borrowPinnedConnection(request, serverDestinations[0]->getPeer());
else
serverConn = NULL;
=== modified file 'src/HierarchyLogEntry.h'
--- src/HierarchyLogEntry.h 2014-08-23 10:39:15 +0000
+++ src/HierarchyLogEntry.h 2014-08-27 10:27:24 +0000
@@ -34,43 +34,56 @@
#include "comm/Connection.h"
#include "enums.h"
#include "hier_code.h"
#include "http/StatusCode.h"
#include "lookup_t.h"
#include "PingData.h"
#include "rfc2181.h"
class HierarchyLogEntry
{
public:
HierarchyLogEntry();
~HierarchyLogEntry() { tcpServer = NULL; };
/// Record details from a new server connection.
/// 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];
ping_data ping;
char cd_host[SQUIDHOSTNAMELEN]; /* the host of selected by cd peer */
lookup_t cd_lookup; /* cd prediction: none, miss, hit */
int n_choices; /* #peers we selected from (cd only) */
int n_ichoices; /* #peers with known rtt we selected from (cd only) */
struct timeval peer_select_start;
struct timeval store_complete_stop;
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 first_conn_start; ///< first connection use among all peers
+ int64_t total_response_time; ///< cumulative for all peers
};
#endif /* SQUID_HTTPHIERARCHYLOGENTRY_H */
=== modified file 'src/Server.cc'
--- src/Server.cc 2014-08-23 10:39:15 +0000
+++ src/Server.cc 2014-08-27 09:01:25 +0000
@@ -179,42 +179,41 @@
entry->release();
entry->startWriting(); // write the updated entry to store
return theFinalReply;
}
// called when no more server communication is expected; may quit
void
ServerStateData::serverComplete()
{
debugs(11,5,HERE << "serverComplete " << this);
if (!doneWithServer()) {
closeServer();
assert(doneWithServer());
}
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);
if (responseBodyBuffer != NULL)
return;
serverComplete2();
}
void
ServerStateData::serverComplete2()
{
debugs(11,5,HERE << "serverComplete2 " << this);
#if USE_ADAPTATION
if (virginBodyDestination != NULL)
stopProducingFor(virginBodyDestination, true);
if (!doneWithAdaptation())
=== modified file 'src/format/Format.cc'
--- src/format/Format.cc 2014-08-26 09:01:27 +0000
+++ src/format/Format.cc 2014-08-27 08:57:00 +0000
@@ -500,48 +500,50 @@
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;
}
break;
case LFT_TIME_TO_HANDLE_REQUEST:
outint = al->cache.msec;
doint = 1;
break;
case LFT_PEER_RESPONSE_TIME:
if (al->hier.peer_response_time < 0) {
out = "-";
} else {
outoff = al->hier.peer_response_time;
dooff = 1;
}
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) {
outint = al->request->dnsWait;
doint = 1;
}
break;
case LFT_REQUEST_HEADER:
if (al->request)
sb = al->request->header.getByName(fmt->data.header.header);
out = sb.termedBuf();
quote = 1;
break;
case LFT_ADAPTED_REQUEST_HEADER:
=== modified file 'src/log/access_log.cc'
--- src/log/access_log.cc 2014-08-23 10:39:15 +0000
+++ src/log/access_log.cc 2014-08-27 10:30:02 +0000
@@ -238,79 +238,110 @@
log->logfile = NULL;
}
}
#if HEADERS_LOG
logfileClose(headerslog);
headerslog = NULL;
#endif
}
HierarchyLogEntry::HierarchyLogEntry() :
code(HIER_NONE),
cd_lookup(LOOKUP_NONE),
n_choices(0),
n_ichoices(0),
peer_reply_status(Http::scNone),
peer_response_time(-1),
- total_response_time(-1),
tcpServer(NULL),
- bodyBytesRead(-1)
+ bodyBytesRead(-1),
+ total_response_time(-1)
{
memset(host, '\0', SQUIDHOSTNAMELEN);
memset(cd_host, '\0', SQUIDHOSTNAMELEN);
peer_select_start.tv_sec =0;
peer_select_start.tv_usec =0;
store_complete_stop.tv_sec =0;
store_complete_stop.tv_usec =0;
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;
}
void
HierarchyLogEntry::note(const Comm::ConnectionPointer &server, const char *requestedHost)
{
tcpServer = server;
if (tcpServer == NULL) {
code = HIER_NONE;
xstrncpy(host, requestedHost, sizeof(host));
} else {
code = tcpServer->peerType;
if (tcpServer->getPeer()) {
// went to peer, log peer host name
xstrncpy(host, tcpServer->getPeer()->name, sizeof(host));
} else {
xstrncpy(host, requestedHost, sizeof(host));
}
}
}
+void
+HierarchyLogEntry::startPeerClock()
+{
+ if (!first_conn_start.tv_sec)
+ first_conn_start = current_time;
+}
+
+void
+HierarchyLogEntry::stopPeerClock(const bool force) {
+ debugs(46, 5, "First connection started: " << first_conn_start.tv_sec << "." <<
+ std::setfill('0') << std::setw(6) << first_conn_start.tv_usec <<
+ ", current total response time value: " << total_response_time <<
+ (force ? ", force fixing" : ""));
+ if (!force && total_response_time >= 0)
+ return;
+
+ total_response_time = first_conn_start.tv_sec ? tvSubMsec(first_conn_start, 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 (first_conn_start.tv_sec && total_response_time < 0)
+ stopPeerClock(false);
+
+ return total_response_time;
+}
+
static void
accessLogRegisterWithCacheManager(void)
{
#if USE_FORW_VIA_DB
fvdbRegisterWithCacheManager();
#endif
}
void
accessLogInit(void)
{
CustomLog *log;
accessLogRegisterWithCacheManager();
#if USE_ADAPTATION
Log::TheConfig.hasAdaptToken = false;
#endif
#if ICAP_CLIENT
Log::TheConfig.hasIcapToken = false;
=== modified file 'src/tunnel.cc'
--- src/tunnel.cc 2014-08-26 09:01:27 +0000
+++ src/tunnel.cc 2014-08-27 10:31:55 +0000
@@ -37,40 +37,41 @@
#include "CachePeer.h"
#include "client_side.h"
#include "client_side_request.h"
#include "comm.h"
#include "comm/Connection.h"
#include "comm/ConnOpener.h"
#include "comm/Read.h"
#include "comm/Write.h"
#include "errorpage.h"
#include "fde.h"
#include "globals.h"
#include "FwdState.h"
#include "http.h"
#include "HttpRequest.h"
#include "HttpStateFlags.h"
#include "ip/QosConfig.h"
#include "LogTags.h"
#include "MemBuf.h"
#include "PeerSelectState.h"
#include "SquidConfig.h"
+#include "SquidTime.h"
#include "StatCounters.h"
#if USE_OPENSSL
#include "ssl/bio.h"
#include "ssl/PeerConnector.h"
#include "ssl/ServerBump.h"
#endif
#include "tools.h"
#if USE_DELAY_POOLS
#include "DelayId.h"
#endif
#include <climits>
#include <cerrno>
/**
* TunnelStateData is the state engine performing the tasks for
* setup of a TCP tunnel from an existing open client FD to a server
* then shuffling binary data between the resulting FD pair.
*/
/*
@@ -221,40 +222,43 @@
};
static const char *const conn_established = "HTTP/1.1 200 Connection established\r\n\r\n";
static CNCB tunnelConnectDone;
static ERCB tunnelErrorComplete;
static CLCB tunnelServerClosed;
static CLCB tunnelClientClosed;
static CTCB tunnelTimeout;
static PSC tunnelPeerSelectComplete;
static void tunnelConnected(const Comm::ConnectionPointer &server, void *);
static void tunnelRelayConnectRequest(const Comm::ConnectionPointer &server, void *);
static void
tunnelServerClosed(const CommCloseCbParams ¶ms)
{
TunnelStateData *tunnelState = (TunnelStateData *)params.data;
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;
}
if (!tunnelState->server.len) {
tunnelState->client.conn->close();
return;
}
}
static void
tunnelClientClosed(const CommCloseCbParams ¶ms)
{
TunnelStateData *tunnelState = (TunnelStateData *)params.data;
debugs(26, 3, HERE << tunnelState->client.conn);
tunnelState->client.conn = NULL;
if (tunnelState->noConnections()) {
delete tunnelState;
@@ -845,40 +849,42 @@
*/
tunnelState->serverDestinations.erase(tunnelState->serverDestinations.begin());
if (status != Comm::TIMEOUT && tunnelState->serverDestinations.size() > 0) {
/* Try another IP of this destination host */
GetMarkingsToServer(tunnelState->request.getRaw(), *tunnelState->serverDestinations[0]);
debugs(26, 4, HERE << "retry with : " << tunnelState->serverDestinations[0]);
AsyncCall::Pointer call = commCbCall(26,3, "tunnelConnectDone", CommConnectCbPtrFun(tunnelConnectDone, tunnelState));
Comm::ConnOpener *cs = new Comm::ConnOpener(tunnelState->serverDestinations[0], call, Config.Timeout.connect);
cs->setHost(tunnelState->url);
AsyncJob::Start(cs);
} else {
debugs(26, 4, HERE << "terminate with error.");
ErrorState *err = new ErrorState(ERR_CONNECT_FAIL, Http::scServiceUnavailable, tunnelState->request.getRaw());
*tunnelState->status_ptr = Http::scServiceUnavailable;
err->xerrno = xerrno;
// on timeout is this still: err->xerrno = ETIMEDOUT;
err->port = conn->remote.port();
err->callback = tunnelErrorComplete;
err->callback_data = tunnelState;
errorSend(tunnelState->client.conn, err);
+ if (tunnelState->request != NULL)
+ tunnelState->request->hier.stopPeerClock(false);
}
return;
}
#if USE_DELAY_POOLS
/* no point using the delayIsNoDelay stuff since tunnel is nice and simple */
if (conn->getPeer() && conn->getPeer()->options.no_delay)
tunnelState->server.setDelayId(DelayId());
#endif
tunnelState->request->hier.note(conn, tunnelState->getHost());
tunnelState->server.conn = conn;
tunnelState->request->peer_host = conn->getPeer() ? conn->getPeer()->host : NULL;
comm_add_close_handler(conn->fd, tunnelServerClosed, tunnelState);
debugs(26, 4, HERE << "determine post-connect handling pathway.");
if (conn->getPeer()) {
tunnelState->request->peer_login = conn->getPeer()->login;
tunnelState->request->flags.proxying = !(conn->getPeer()->options.originserver);
@@ -1062,40 +1068,43 @@
static void
tunnelPeerSelectComplete(Comm::ConnectionList *peer_paths, ErrorState *err, void *data)
{
TunnelStateData *tunnelState = (TunnelStateData *)data;
if (peer_paths == NULL || peer_paths->size() < 1) {
debugs(26, 3, HERE << "No paths found. Aborting CONNECT");
if (!err) {
err = new ErrorState(ERR_CANNOT_FORWARD, Http::scServiceUnavailable, tunnelState->request.getRaw());
}
*tunnelState->status_ptr = err->httpStatus;
err->callback = tunnelErrorComplete;
err->callback_data = tunnelState;
errorSend(tunnelState->client.conn, err);
return;
}
delete err;
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] << "}");
AsyncCall::Pointer call = commCbCall(26,3, "tunnelConnectDone", CommConnectCbPtrFun(tunnelConnectDone, tunnelState));
Comm::ConnOpener *cs = new Comm::ConnOpener(tunnelState->serverDestinations[0], call, Config.Timeout.connect);
cs->setHost(tunnelState->url);
AsyncJob::Start(cs);
}
CBDATA_CLASS_INIT(TunnelStateData);
bool
TunnelStateData::noConnections() const
{
return !Comm::IsConnOpen(server.conn) && !Comm::IsConnOpen(client.conn);
}
#if USE_DELAY_POOLS
void
TunnelStateData::Connection::setDelayId(DelayId const &newDelay)
