[squid-users] logformat odd values

[Alex Rousskov]

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.