[squid-users] logformat odd values

[Alex Rousskov]

FTR: Factory investigation triggered by this email thread found an
explanation for the observed odd measurements. Armed with that
knowledge, we concluded that %icap::tt documentation is wrong and
proposed a fix at https://github.com/squid-cache/squid/pull/914/


HTH,

Alex.

On 9/17/21 10:56 AM, Alex Rousskov wrote:
> 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>
>>
> 
> _______________________________________________
> squid-users mailing list
> squid-users at lists.squid-cache.org
> http://lists.squid-cache.org/listinfo/squid-users
>