From: Alex Rousskov <rousskov@measurement-factory.com>
Date: Sat, 30 Oct 2021 11:41:10 +0000 (+0000)
Subject: Docs: %adapt::sum_trs entries may well exceed %icap::tt (#914)
X-Git-Tag: SQUID_6_0_1~276
X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=40dc90df00a73f90fbce3e34ae76d133996ee80a;p=thirdparty%2Fsquid.git

Docs: %adapt::sum_trs entries may well exceed %icap::tt (#914)

%icap::tt documentation incorrectly implied that the measurement
includes the entire ICAP transaction(s) lifetime. In reality, individual
ICAP transaction contribution stops with
Adaptation::Icap::ModXactLauncher::swanSong(), which is normally
triggered by Adaptation::Icap::Launcher::noteAdaptationAnswer(). Here,
the "answer" does not include the entire ICAP response, but just enough
information to form adapted HTTP message headers (echoed or received).
Thus, a large or slow ICAP response body may result in %adapt::sum_trs
values that far exceed the corresponding %icap::tt "total".

This change does not imply that %icap::tt should (not) work differently.

Also fixed a typo in %adapt::all_trs and polished %adapt::sum_trs docs.
---

diff --git a/src/cf.data.pre b/src/cf.data.pre
index be6741ec2e..35ac847a0a 100644
--- a/src/cf.data.pre
+++ b/src/cf.data.pre
@@ -4982,10 +4982,29 @@ DOC_START
 	If ICAP is enabled, the following code becomes available (as
 	well as ICAP log codes documented with the icap_log option):
 
-		icap::tt        Total ICAP processing time for the HTTP
-				transaction. The timer ticks when ICAP
-				ACLs are checked and when ICAP
-				transaction is in progress.
+		icap::tt Total ICAP "blocking" time for the HTTP transaction. The
+				timer ticks while Squid checks adaptation_access and while
+				ICAP transaction(s) expect ICAP response headers, including
+				the embedded adapted HTTP message headers (where applicable).
+				This measurement is meant to estimate ICAP impact on HTTP
+				transaction response times, but it does not currently account
+				for slow ICAP response body delivery blocking HTTP progress.
+
+				Once Squid receives the final ICAP response headers (e.g.,
+				ICAP 200 or 204) and the associated adapted HTTP message
+				headers (if any) from the ICAP service, the corresponding ICAP
+				transaction stops affecting this measurement, even though the
+				transaction itself may continue for a long time (e.g., to
+				finish sending the ICAP request and/or to finish receiving the
+				ICAP response body).
+
+				When "blocking" sections of multiple concurrent ICAP
+				transactions overlap in time, the overlapping segment is
+				counted only once.
+
+				To see complete ICAP transaction response times (rather than
+				the cumulative effect of their blocking sections) use the
+				%adapt::all_trs logformat code or the icap_log directive.
 
 	If adaptation is enabled the following codes become available:
 
@@ -5004,11 +5023,12 @@ DOC_START
 				milliseconds.  When a failed transaction is
 				being retried or repeated, its time is not
 				logged individually but added to the
-				replacement (next) transaction. See also:
-				adapt::all_trs.
+				replacement (next) transaction. Lifetimes of individually
+				listed adaptation transactions may overlap.
+				See also: %icap::tt and %adapt::all_trs.
 
 		adapt::all_trs All adaptation transaction response times.
-				Same as adaptation_strs but response times of
+				Same as %adapt::sum_trs but response times of
 				individual transactions are never added
 				together. Instead, all transaction response
 				times are recorded individually.