[squid-users] logformat odd values

[Alex Rousskov]

On 9/17/21 10:35 AM, Moti Berger wrote:

> It's possible that in some cases they will run concurrently, however not
> in my setup. The ICAPs are chained. If the chain doesn't guarantee it
> please let me know since I rely on it.

Chaining adaptation services guarantees that they will _start_
sequentially, but does not guarantee that they will _run_ sequentially.
That guarantee can only come from the services themselves.

For example, imagine two chained REQMOD services handling a 1GB HTTP PUT
request. If the first service emits the adapted request headers (at
least), then Squid will start the second service and will send those
adapted request headers (and any adapted request body trickled after the
headers) to that second service. The two services, in that case, will
run concurrently.


> Regarding what you said about things that can happen in parallel, I'm OK
> with it since what I care the most is the extra time my ICAPs add to the
> user latency and this is what I would like to measure.

The desire to measure ICAP overheads is common and natural.
Unfortunately, bugs notwithstanding, %icap::tt measures the latency
added exclusively by adaptation if and only if the corresponding
adaptation transaction is tiny (e.g., one I/O to receive the entire
adapted HTTP message from the adaptation service). In most real world
scenarios involving larger HTTP messages, adaptation services will run
in parallel with Squid reading/writing from the HTTP client and/or
server because Squid uses adapted bytes as soon as it can.


HTH,

Alex.

> On Wed, Sep 15, 2021, 20:47 Alex Rousskov wrote:
> 
>     On 9/14/21 3:04 PM, Moti Berger wrote:
> 
>     > I have the followings in squid.conf:
>     >
>     >     logformat metrics %icap::tt %adapt::all_trs %adapt::sum_trs
>     >     %{service_req_a}adapt::sum_trs %{service_resp_a}adapt::sum_trs
>     >     %{service_req_b}adapt::sum_trs %{service_resp_b}adapt::sum_trs
>     >     access_log daemon:/var/log/squid/metrics.log metrics
>     >
>     >  
>     >
>     >     icap_service service_req_a reqmod_precache bypass=1
>     on-overload=wait
>     >     routing=1 icap://a.y:12345/request
>     >     icap_service service_req_b reqmod_precache bypass=1
>     on-overload=wait
>     >     icap://b.y:10101/request
>     >     adaptation_service_chain svcRequest service_req_a service_req_b
>     >     adaptation_access svcRequest deny manager
>     >     adaptation_access svcRequest allow all
>     >     icap_service service_resp_a respmod_precache bypass=1
>     >     on-overload=wait routing=1 icap://a.y:12345/response
>     >     icap_service service_resp_b respmod_precache bypass=1
>     >     on-overload=wait icap://b.y:10101/response
>     >     adaptation_service_chain svcResponse service_resp_a service_resp_b
>     >     adaptation_access svcResponse deny manager
>     >     adaptation_access svcResponse allow all
>     >
>     >
>     >  I see in metrics.log lines like this:
>     >
>     >     4 4,180 4,180 4 180 - -
>     >
>     >
>     > Now I wonder how come the value of %icap:tt isn't at least as the
>     sum of
>     > all the numbers appear on %adapt::all_trs or %adapt::sum_trs (assuming
>     > no failed transactions)?
> 
>     There is probably a bug somewhere, but please note that %icap:tt may not
>     be the sum of individual transaction response times (in _some_ cases)
>     even after that bug is fixed because those individual transactions may
>     run _concurrently_ (i.e. partially overlap in time).
> 
> 
>     > If %icap:tt isn't at least the sum of all ICAPs processing time,
>     what is?
> 
>     Bugs notwithstanding, it is approximate time a master transaction spent
>     doing adaptation (including checking whether adaptation is necessary).
>     This stopwatch ticks when adaptation_access ACLs are checked and also
>     when at least one adaptation transaction associated with that master
>     transaction is in progress.
> 
>     Please note that a master transaction can do a lot of different things
>     at once or in parallel. For example, it can communicate with an HTTP
>     client while communicating with an FTP server while communicating with
>     an eCAP REQMOD adaptation service while communicating with a DNS server
>     to decide whether to start communicating with an ICAP RESPMOD service.
> 
> 
>     HTH,
> 
>     Alex.
>     _______________________________________________
>     squid-users mailing list
>     squid-users at lists.squid-cache.org
>     <mailto:squid-users at lists.squid-cache.org>
>     http://lists.squid-cache.org/listinfo/squid-users
>     <http://lists.squid-cache.org/listinfo/squid-users>
>