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@xxxxxxxxxxxxxxxxxxxxx >> <mailto:squid-users@xxxxxxxxxxxxxxxxxxxxx> >> http://lists.squid-cache.org/listinfo/squid-users >> <http://lists.squid-cache.org/listinfo/squid-users> >> > > _______________________________________________ > squid-users mailing list > squid-users@xxxxxxxxxxxxxxxxxxxxx > http://lists.squid-cache.org/listinfo/squid-users > _______________________________________________ squid-users mailing list squid-users@xxxxxxxxxxxxxxxxxxxxx http://lists.squid-cache.org/listinfo/squid-users
