Hello all, This patch adds the BereqEnd tag, always the last tag emitted for a bereq transaction before the End marker.
The format is: BereqEnd <Tstart> <Tend> <Thdr> <Tbody> Tstart: begin fetch processing (epoch) Tend: end fetch processing (epoch) Thdr: time to receive response header Tbody: time to receive response body Thdr is approximately the delta from just after sending the backend request until just after receiving the header. Tbody is approximately the delta from just after receiving the response header until just after receiving the body. So for example: BereqEnd 1381335026.155810356 1381335026.268885612 0.112095833 0.000851154 The deltas are approximate because the low-level fetch operations do some buffering, so the timings don't correspond strictly to reading the header and body off the network (see the comments in cache_http1_proto.c), but I think will for the most part reflect backend latencies well enough. The rationale is that I think backend timings will be useful for: - measuring backend performance, and in particular finding out which backends are slow - finding out how much time in a fetch is due to work done strictly in varnishd, and how much is due to latencies in systems beyond Varnish's control There is a bit of varnishd overhead in the Thdr and Tbody timings, but they are dominated by backend latencies. That does mean, however, that Tbody is always > 0, even if there is no response body. Probably most people won't be very interested in the difference between Thdr and Tbody (just Thdr+Tbody). We have to take a measurement after the header arrives anyway, since there might not be a body, so I thought we may as well log the delta. But maybe we just want the one value here, just Thdr+Tbody. Tell me what you think. Best, Geoff -- ** * * UPLEX - Nils Goroll Systemoptimierung Scheffelstraße 32 22301 Hamburg Tel +49 40 2880 5731 Mob +49 176 636 90917 Fax +49 40 42949753 http://uplex.de
From b58b16d451ea76c1dd5c48fc1ac96ed77edcf9f1 Mon Sep 17 00:00:00 2001 From: Geoff Simmons <[email protected]> Date: Thu, 10 Oct 2013 11:05:45 +0200 Subject: [PATCH] Add the VSL tag BereqEnd --- bin/varnishd/cache/cache.h | 6 +++++ bin/varnishd/cache/cache_fetch.c | 10 ++++++++ bin/varnishd/cache/cache_http1_fetch.c | 4 +++ bin/varnishtest/tests/l00002.vtc | 38 ++++++++++++++++++++++++++++++++ include/tbl/vsl_tags.h | 8 ++++++ 5 files changed, 66 insertions(+), 0 deletions(-) create mode 100644 bin/varnishtest/tests/l00002.vtc diff --git a/bin/varnishd/cache/cache.h b/bin/varnishd/cache/cache.h index 5c249f5..35db62e 100644 --- a/bin/varnishd/cache/cache.h +++ b/bin/varnishd/cache/cache.h @@ -579,6 +579,12 @@ struct busyobj { double first_byte_timeout; double between_bytes_timeout; + /* Timers */ + double t_start; + 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..301fbdd 100644 --- a/bin/varnishd/cache/cache_fetch.c +++ b/bin/varnishd/cache/cache_fetch.c @@ -593,6 +593,10 @@ vbf_fetch_thread(struct worker *wrk, void *priv) THR_SetBusyobj(bo); stp = F_STP_MKBEREQ; + bo->t_start = VTIM_real(); + 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 +622,12 @@ vbf_fetch_thread(struct worker *wrk, void *priv) if (bo->ims_obj != NULL) (void)HSH_DerefObj(&wrk->stats, &bo->ims_obj); + VSLb(bo->vsl, SLT_BereqEnd, "%.9f %.9f %.9f %.9f", + bo->t_start, + VTIM_real(), + bo->t_hdr - bo->t_sent, + bo->t_body - bo->t_hdr); + 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 e0b35d8..5c84382 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 @@ -241,6 +242,7 @@ V1F_fetch_hdr(struct worker *wrk, struct busyobj *bo, struct req *req) if (req->req_body_status == REQ_BODY_DONE) retry = -1; } + bo->t_sent = VTIM_real(); if (WRW_FlushRelease(wrk) || i != 0) { VSLb(bo->vsl, SLT_FetchError, "backend write error: %d (%s)", @@ -286,6 +288,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_real(); hp = bo->beresp; @@ -374,6 +377,7 @@ V1F_fetch_body(struct worker *wrk, struct busyobj *bo) default: INCOMPL(); } + bo->t_body = VTIM_real(); AZ(bo->vgz_rx); /* diff --git a/bin/varnishtest/tests/l00002.vtc b/bin/varnishtest/tests/l00002.vtc new file mode 100644 index 0000000..596d71d --- /dev/null +++ b/bin/varnishtest/tests/l00002.vtc @@ -0,0 +1,38 @@ +varnishtest "test VSL tags" + +server s1 { + rxreq + txresp -status 200 -body "phk rules" + rxreq + expect req.url == "/foo" + txresp -status 204 +} -start + +varnish v1 -vcl+backend { +} -start + +logexpect l1 -v v1 + +client c1 { + txreq + rxresp + expect resp.status == 200 + expect resp.body == "phk rules" + txreq -url "/foo" + rxresp + expect resp.status == 204 + expect resp.bodylen == 0 +} -run + +# XXX: it seems to me that the BereqEnd payload should match this pattern: +# "^\\d+\\.\\d+ \\d+\\.\\d+ \\d+\\.\\d+ \\d+\\.\\d+$" +# but the regex matching seems to have trouble with backslashes, spaces, +# the plus sign, and '^' +logexpect l1 -d 1 -g vxid -q "Begin ~ '^bereq'" { + expect 0 * Begin + expect * = BereqEnd "[0-9]*.[0-9]*.[0-9]*.[0-9]*.[0-9]*.[0-9]*.[0-9]*.[0-9]*$" + expect 0 = End + expect 0 * Begin + expect * = BereqEnd "[0-9]*.[0-9]*.[0-9]*.[0-9]*.[0-9]*.[0-9]*.[0-9]*.[0-9]*$" + expect 0 = End +} -run diff --git a/include/tbl/vsl_tags.h b/include/tbl/vsl_tags.h index c2fb6d9..359e3d8 100644 --- a/include/tbl/vsl_tags.h +++ b/include/tbl/vsl_tags.h @@ -108,6 +108,14 @@ 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.\n\n" + "Tend\n Timestamp when the fetch ended.\n\n" + "dThdr\n Time to receive response header\n\n" + "dTbody\n Time to receive response body\n\n" +) + SLTM(FetchError, "Error while fetching object", "") #define SLTH(aa, bb) SLTM(Req##aa, "", "") -- 1.7.2.5
signature.asc
Description: OpenPGP digital signature
_______________________________________________ varnish-dev mailing list [email protected] https://www.varnish-cache.org/lists/mailman/listinfo/varnish-dev
