On 10/15/2013 01:56 PM, Martin Blix Grydeland wrote: > > So my suggestion on the fields present is: > BereqEnd <Tstart> <Tend> <dTreq> <dThdr> <dTbody> <dTresp> > > Tstart: begin fetch processing (epoch) > Tend: end fetch processing (epoch) > dTreq: time to send the backend request > dThdr: time to receive the backend response headers > dTbody: time to receive the backend response body > dTresp: time to receive the backend response (dThdr + dTbody)
Attached is a new version of the patch with this implementation of BereqEnd. It also now uses VTIM_mono() to get the measurement points for the deltas, so there are 2 calls to VTIM_real() and 4 to VTIM_mono() for every fetch. 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 0f1a345e5a95051e84e010e594823d33d8a168e1 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 | 7 ++++++ bin/varnishd/cache/cache_fetch.c | 14 +++++++++++ bin/varnishd/cache/cache_http1_fetch.c | 5 ++++ bin/varnishtest/tests/l00002.vtc | 38 ++++++++++++++++++++++++++++++++ include/tbl/vsl_tags.h | 10 ++++++++ 5 files changed, 74 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..b94709e 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..95467c8 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 e0b35d8..91fbe28 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 */ @@ -241,6 +243,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_mono(); if (WRW_FlushRelease(wrk) || i != 0) { VSLb(bo->vsl, SLT_FetchError, "backend write error: %d (%s)", @@ -286,6 +289,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; @@ -374,6 +378,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/varnishtest/tests/l00002.vtc b/bin/varnishtest/tests/l00002.vtc new file mode 100644 index 0000000..dae21e3 --- /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]*.[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]*.[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..a4216c4 100644 --- a/include/tbl/vsl_tags.h +++ b/include/tbl/vsl_tags.h @@ -108,6 +108,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(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
