Re: [squid-users] logformat odd values
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@lists.squid-cache.org
>>
>>
Re: [squid-users] logformat odd values
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@lists.squid-cache.org
>
> http://lists.squid-cache.org/listinfo/squid-users
>
>
___
squid-users mailing list
squid-users@lists.squid-cache.org
http://lists.squid-cache.org/listinfo/squid-users
Re: [squid-users] logformat odd values
Hi
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.
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.
Thanks
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@lists.squid-cache.org
> http://lists.squid-cache.org/listinfo/squid-users
>
___
squid-users mailing list
squid-users@lists.squid-cache.org
http://lists.squid-cache.org/listinfo/squid-users
Re: [squid-users] logformat odd values
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@lists.squid-cache.org
http://lists.squid-cache.org/listinfo/squid-users
Re: [squid-users] logformat odd values
On 15/09/21 7:04 am, Moti Berger wrote:
Hi
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)?
%icap:: codes are relevant to ICAP.
%adapt:: codes are relevant to all adaptation types: ICAP, eCAP, and (in
theory, though often not really) redirector and URL re-writer helpers.
NP: failed transactions timers are included in all three metrics.
If %icap:tt isn't at least the sum of all ICAPs processing time, what is?
AFAIK you are right - it is supposed to be the sum of all processing
time for ICAP related things.
It does seem to be a bit odd that only the first one ("4") is counted.
Likely a bug IMO.
Amos
___
squid-users mailing list
squid-users@lists.squid-cache.org
http://lists.squid-cache.org/listinfo/squid-users
[squid-users] logformat odd values
Hi
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)?
If %icap:tt isn't at least the sum of all ICAPs processing time, what is?
Thanks,
Moti
___
squid-users mailing list
squid-users@lists.squid-cache.org
http://lists.squid-cache.org/listinfo/squid-users
