[squid-users] Need clarifications on custom log timestamps

Wed Feb 19 16:39:34 UTC 2025

On 2025-02-19 06:26, BENJAMIN DELANNOY wrote:

> For %<pt : "The timer starts when the last request byte is sent to the 
> next hop and stops when the last response byte is received."  Are we 
> talking of last request / last response of a single TCP connection on 
> server side ?

I believe the short answer is "no": If Squid uses multiple TCP 
Squid-peer connections to forward a single client request, then the last 
connection used for that request forwarding should determine overall 
transaction outcome and %<pt values in access.log.

> Do we agree that we are purely talking about 
> request/response on HTTP, and thus this time does not take into account 
> the time spent with SSL negotiation / squid actions before ?

I believe the short answer is "yes": Today, %<pt timer starts after the 
HTTP (or FTP) request is written to the peer, so TLS handshake (if any) 
would happen before that timer starts. AFAIK, Squid does not support 
0-RTT TLS.

> For %<tt : I understand that all the time spent sending requests & 
> waiting responses from the Origin are added. It would also means that if 
> I subtract this timer to %tr, I would have only the ClientSide time 
> before first packet is sent to Origin by the squid & after the last 
> packet is received from the Origin ?

Yes, but "before" and "after" can be misleading here (in general) 
because there may be periods of time when Squid is _not_ talking to a 
peer but is working on what you call "ClientSide". For example, there is 
code that decides whether to revalidate a received peer response. From 
Squid point of view, that code runs on "ClientSide" -- %<tt timers may 
be stopped when that code runs. Since you are not caching, that 
particular code is not relevant to you.

Also, please keep in mind that a slow client may effectively stall 
Squid-to-peer I/O by not consuming response data fast enough, filling 
Squid response buffers (see read_ahead_gap). If one only looks at "%tr - 
%<tt" difference in such cases, one would observe near-0 values and may 
mistakenly conclude that the slow client is super fast!

> Actually, what I want to monitor, is the time between the first client 
> packet received on the Squid and the time the squid makes its choice :
> - based on SNI for SSL Splice
> - based on HTTP ACL (HTTP traffic or HTTPS traffic with SSL Bump)
> Based on this, I would be able to check if a squid server is taking too 
> much time making a decision.
> 
> Is this something feasible?

Please detail what you mean by "choice" or "decision". For example, do 
you want to stop the timer when Squid makes its final http_access decision?

Thank you,

Alex.

> On Mon, Feb 17, 2025 at 4:47 PM Alex Rousskov wrote:
> 
>     On 2025-02-17 10:02, BENJAMIN DELANNOY wrote:
> 
>      > I try to figure out what is exactly measured with the <pt & <tt
>     timings.
>      > I don't get what are the difference between them, what is the
>     difference
>      > between "peer response time" & "time spent forwarding to origin
>      > servers",
> 
>     Have you seen %<pt and %<tt descriptions at [1]? %<tt description was
>     updated in August 2024, and squid.conf.documented in Squid v6 and
>     earlier does not have those documentation updates (and the
>     corresponding
>     bug fixes)...
> 
>     [1] http://www.squid-cache.org/Doc/config/logformat/
>     <http://www.squid-cache.org/Doc/config/logformat/>
> 
> 
>      > what is the "last I/O with the last peer", etc.
> 
>     When forwarding a single client request, Squid may talk to multiple
>     cache_peer and origin server addresses (collectively called "peers").
>     Talking to a given peer may include multiple socket reading and writing
>     (i.e. I/O) events. Does this clarify?
> 
> 
> 
>      > For information, I aim to calculate the time spent on the
>     client-side &
>      > by squid processing time,  excluding the server-side time spent
>     (=what I
>      > don't manage).
> 
>     This kind of calculation is a common need. Please keep in mind that
>     Squid may spend time on the client side (e.g., awaiting the next
>     request
>     body byte) while also spending time on the server side (e.g., awaiting
>     the next response body byte), complicating things.
> 
>     If existing %codes are not enough, please detail your needs in terms of
>     events that Squid can recognize (e.g., receiving the first response
>     header byte or sending the last request body byte).
> 
> 
>     HTH,
> 
>     Alex.
> 
> 
> 
> 
>      > We do not use squid for caching but only for http & ssl
>     proxy/filtering.
>      >
>      > Thanks a lot !
>      >
>      >
>      > Cordialement, Regards,
>      >
>      >
>      > Benjamin DELANNOY
>      >
>      > Cloud Network Engineer
>      >
>      > NETWORK SOLUTIONS - GTDP
>      >
>      > Mobile +33 (0)6 16 98 23 72
>      >
>      >
>      > 135 rue Sadi Carnot • CS 00001 • 59790 Ronchin • FRANCE
>      >
>      > positivetech.adeo.com <http://positivetech.adeo.com>
>     <https://positivetech.adeo.com/ <https://positivetech.adeo.com/>>
>      >
>      > adeolinkedin <https://www.linkedin.com/company/groupe-adeo
>     <https://www.linkedin.com/company/groupe-adeo>>
>      >
>      >
>      >
>      > _______________________________________________
>      > squid-users mailing list
>      > squid-users at lists.squid-cache.org
>     <mailto:squid-users at lists.squid-cache.org>
>      > https://lists.squid-cache.org/listinfo/squid-users
>     <https://lists.squid-cache.org/listinfo/squid-users>
> 
>     _______________________________________________
>     squid-users mailing list
>     squid-users at lists.squid-cache.org
>     <mailto:squid-users at lists.squid-cache.org>
>     https://lists.squid-cache.org/listinfo/squid-users
>     <https://lists.squid-cache.org/listinfo/squid-users>
> 