[master] 68b9177 Integrate (with minor polishing) patch from Geoff to add a SLT_BereqEnd record with timing info about the fetch.
Poul-Henning Kamp
phk at varnish-cache.org
Thu Oct 24 15:12:53 CEST 2013
commit 68b9177c6fc0748f86d6ca7224a04a090a614098
Author: Poul-Henning Kamp <phk at FreeBSD.org>
Date: Thu Oct 24 13:12:37 2013 +0000
Integrate (with minor polishing) patch from Geoff to add a SLT_BereqEnd
record with timing info about the fetch.
Submitted by: Geoff Simmons @ UPLEX
diff --git a/bin/varnishd/cache/cache.h b/bin/varnishd/cache/cache.h
index b51354d..662adbd 100644
--- a/bin/varnishd/cache/cache.h
+++ b/bin/varnishd/cache/cache.h
@@ -579,6 +579,13 @@ struct busyobj {
double first_byte_timeout;
double between_bytes_timeout;
+ /* Timers */
+ double t_start;
+ double t_send;
+ double t_sent;
+ double t_hdr;
+ double t_body;
+
const char *storage_hint;
struct director *director;
struct VCL_conf *vcl;
diff --git a/bin/varnishd/cache/cache_fetch.c b/bin/varnishd/cache/cache_fetch.c
index f5d7d8f..6a177b5 100644
--- a/bin/varnishd/cache/cache_fetch.c
+++ b/bin/varnishd/cache/cache_fetch.c
@@ -586,6 +586,7 @@ vbf_fetch_thread(struct worker *wrk, void *priv)
{
struct busyobj *bo;
enum fetch_step stp;
+ double t_hdr, t_body;
CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
CAST_OBJ_NOTNULL(bo, priv, BUSYOBJ_MAGIC);
@@ -593,6 +594,11 @@ vbf_fetch_thread(struct worker *wrk, void *priv)
THR_SetBusyobj(bo);
stp = F_STP_MKBEREQ;
+ bo->t_start = VTIM_real();
+ bo->t_send = NAN;
+ bo->t_sent = NAN;
+ bo->t_hdr = NAN;
+ bo->t_body = NAN;
while (stp != F_STP_DONE) {
CHECK_OBJ_NOTNULL(bo, BUSYOBJ_MAGIC);
@@ -618,6 +624,14 @@ vbf_fetch_thread(struct worker *wrk, void *priv)
if (bo->ims_obj != NULL)
(void)HSH_DerefObj(&wrk->stats, &bo->ims_obj);
+ t_hdr = bo->t_hdr - bo->t_sent;
+ t_body = bo->t_body - bo->t_hdr;
+ VSLb(bo->vsl, SLT_BereqEnd, "%.9f %.9f %.9f %.9f %.9f %.9f",
+ bo->t_start,
+ VTIM_real(),
+ bo->t_sent - bo->t_send,
+ t_hdr, t_body, t_hdr + t_body);
+
VBO_DerefBusyObj(wrk, &bo);
THR_SetBusyobj(NULL);
}
diff --git a/bin/varnishd/cache/cache_http1_fetch.c b/bin/varnishd/cache/cache_http1_fetch.c
index 50c421a..57384f3 100644
--- a/bin/varnishd/cache/cache_http1_fetch.c
+++ b/bin/varnishd/cache/cache_http1_fetch.c
@@ -42,6 +42,7 @@
#include "vcli_priv.h"
#include "vct.h"
#include "vtcp.h"
+#include "vtim.h"
/*--------------------------------------------------------------------
* Convert a string to a size_t safely
@@ -231,6 +232,7 @@ V1F_fetch_hdr(struct worker *wrk, struct busyobj *bo, struct req *req)
(void)VTCP_blocking(vc->fd); /* XXX: we should timeout instead */
WRW_Reserve(wrk, &vc->fd, bo->vsl, bo->t_fetch);
+ bo->t_send = VTIM_mono();
(void)HTTP1_Write(wrk, hp, 0); /* XXX: stats ? */
/* Deal with any message-body the request might (still) have */
@@ -257,8 +259,8 @@ V1F_fetch_hdr(struct worker *wrk, struct busyobj *bo, struct req *req)
return (retry);
}
- /* XXX is this the right place? */
VSC_C_main->backend_req++;
+ bo->t_sent = VTIM_mono();
/* Receive response */
@@ -293,6 +295,7 @@ V1F_fetch_hdr(struct worker *wrk, struct busyobj *bo, struct req *req)
vc->between_bytes_timeout);
}
} while (hs != HTTP1_COMPLETE);
+ bo->t_hdr = VTIM_mono();
hp = bo->beresp;
@@ -381,6 +384,7 @@ V1F_fetch_body(struct worker *wrk, struct busyobj *bo)
default:
INCOMPL();
}
+ bo->t_body = VTIM_mono();
AZ(bo->vgz_rx);
/*
diff --git a/bin/varnishd/cache/cache_http1_fsm.c b/bin/varnishd/cache/cache_http1_fsm.c
index fcdbebb..6a92bc5 100644
--- a/bin/varnishd/cache/cache_http1_fsm.c
+++ b/bin/varnishd/cache/cache_http1_fsm.c
@@ -258,7 +258,7 @@ http1_req_body_status(struct req *req)
req->h1.bytes_yet = req->req_bodybytes - req->h1.bytes_done;
return (REQ_BODY_PRESENT);
}
- if (http_GetHdr(req->http, H_Transfer_Encoding, NULL))
+ if (http_GetHdr(req->http, H_Transfer_Encoding, NULL))
return (REQ_BODY_FAIL);
return (REQ_BODY_NONE);
}
diff --git a/include/tbl/vsl_tags.h b/include/tbl/vsl_tags.h
index 6bf6646..67548d5 100644
--- a/include/tbl/vsl_tags.h
+++ b/include/tbl/vsl_tags.h
@@ -119,6 +119,16 @@ SLTM(HttpGarbage, "", "")
SLTM(Backend, "Backend selected", "")
SLTM(Length, "Size of object body", "")
+SLTM(BereqEnd, "Backend request end",
+ "Marks the end of a backend request.\n\n"
+ "Tstart\n Timestamp when the fetch started (epoch)\n\n"
+ "Tend\n Timestamp when the fetch ended (epoch)\n\n"
+ "dTsend\n Time to send the backend request\n\n"
+ "dThdr\n Time to receive the backend response headers\n\n"
+ "dTbody\n Time to receive the backend response body\n\n"
+ "dTresp\n Time to receive the backend response (dThdr + dTbody)\n\n"
+)
+
SLTM(FetchError, "Error while fetching object", "")
#define SLTH(tag, ind, req, resp, sdesc, ldesc) \
More information about the varnish-commit
mailing list