[master] 88d927a23 req_fsm: Avoid misleading Timestamp:Process

[Dridi Boukelmoune]

On Thu, Feb 15, 2024 at 11:30 AM Dridi Boukelmoune
<dridi.boukelmoune at gmail.com> wrote:
>
>
> commit 88d927a23e815368a48147c37fab64fa587a40ca
> Author: Stephane Cance <stephane.cance at varnish-software.com>
> Date:   Wed Feb 7 16:35:32 2024 +0100
>
>     req_fsm: Avoid misleading Timestamp:Process
>
>     When `vcl_deliver` does not return `deliver` the timestamp ends
>     up being a duplicate of the `synth` equivalent or the `restart`
>     timestamp.

Stéphane who authored this change is also working on more extensive
coverage of our timestamps. That's how we found that return(synth)
from vcl_deliver results in two Process timestamps. We will submit the
aforementioned coverage separately since it is still work in progress
(trying to find missing or undesirable timestamps for a fair amount of
VCL paths).

Dridi


> diff --git a/bin/varnishd/cache/cache_req_fsm.c b/bin/varnishd/cache/cache_req_fsm.c
> index 3f92d91aa..e84407647 100644
> --- a/bin/varnishd/cache/cache_req_fsm.c
> +++ b/bin/varnishd/cache/cache_req_fsm.c
> @@ -233,8 +233,6 @@ cnt_deliver(struct worker *wrk, struct req *req)
>         req->t_resp = W_TIM_real(wrk);
>         VCL_deliver_method(req->vcl, wrk, req, NULL, NULL);
>
> -       VSLb_ts_req(req, "Process", W_TIM_real(wrk));
> -
>         assert(req->restarts <= cache_param->max_restarts);
>
>         if (wrk->vpi->handling != VCL_RET_DELIVER) {
> @@ -259,6 +257,8 @@ cnt_deliver(struct worker *wrk, struct req *req)
>                 return (REQ_FSM_MORE);
>         }
>
> +       VSLb_ts_req(req, "Process", W_TIM_real(wrk));
> +
>         assert(wrk->vpi->handling == VCL_RET_DELIVER);
>
>         if (IS_TOPREQ(req) && RFC2616_Do_Cond(req))
> diff --git a/bin/varnishtest/tests/s00004.vtc b/bin/varnishtest/tests/s00004.vtc
> index d86903f7c..36775d1d2 100644
> --- a/bin/varnishtest/tests/s00004.vtc
> +++ b/bin/varnishtest/tests/s00004.vtc
> @@ -30,7 +30,6 @@ logexpect l1 -v v1 -g request {
>         expect * =      Timestamp       {Start: \S+ 0\.000000 0\.000000}
>         expect * =      Timestamp       {Req: \S+ 0\.\d+ 0\.\d+}
>         expect * =      Timestamp       {Fetch: \S+ [0-4]\.\d+ [0-4]\.\d+}
> -       expect * =      Timestamp       {Process: \S+ 2\.\d+ 0\.\d+}
>         expect * =      Timestamp       {Restart: \S+ 2\.\d+ 0\.\d+}
>         expect * =      End
>         expect 0 1002   Begin           bereq
> _______________________________________________
> varnish-commit mailing list
> varnish-commit at varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-commit