Re: [PATCH] %tt (total server time) is not computed in some cases

2014-09-01 Thread Amos Jeffries
-BEGIN PGP SIGNED MESSAGE-
Hash: SHA1

On 27/08/2014 11:08 p.m., Tsantilas Christos wrote:
 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

+1, looks good. Some (optional) polishing though if you please.

* Since you are moving and touching most of the logics for
first_conn_start and total_response_time. Please take the opportunity
to upgrade their naming to camelCase and _ suffix.

Amos
-BEGIN PGP SIGNATURE-
Version: GnuPG v2.0.22 (MingW32)

iQEcBAEBAgAGBQJUBRqiAAoJELJo5wb/XPRjQtsIAJxD4SPKoH5MoV3Nmk8P+d6V
rw7VSZ2uYK8ELT3llp6cYGBNafwyLaSop2UuX4q8O6D9GcwDnTgJSLfUiCuac0S5
q9T3HdJeRX069/B0SBJfLiuyTucO6MuWi8pKtoNuH6jDk8LG5CnCyj1PP2+PlZwn
hKv4tIcT61VBS7koCXt0+xI17g89X67jlc5gn2FSA8tTRwhpFKZDe7bmoMx/slwR
7TXZaUmnC+gSDkKZaTuX0ZgULOBuPtEE8+1Ku8/qpSX3TmUaaKa2JjKovuVAMugA
QIW8dzQGhpUOjb4YlPI+MVCgxIbgxtuB4GLxzYdf8KMmr+AksFs3wIWKIIGLKYg=
=9K5L
-END PGP SIGNATURE-


[PATCH] %tt (total server time) is not computed in some cases

2014-08-27 Thread Tsantilas Christos

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 +
+++ src/FwdState.cc	2014-08-27 10:31:20 +
@@ -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