[squid-users] Need clarifications on custom log timestamps

Tue Feb 25 11:33:24 UTC 2025

> 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?

I mean I want to monitor the latency on what I could manage : the
communication between client & squid, the time squid uses to process
requests. But not the time spent by the destination server as I don't
manage it.
This could be multiple monitors if 1 is too complicated or not possible. So
yes for example a timer that stop when Squid makes its final http_access
decision (in case of http or bumped https) or its final ssl_bump splice
decision.

Thanks a lot for your time !

Cordialement, Regards,

Benjamin DELANNOY

On Wed, Feb 19, 2025 at 5:39 PM Alex Rousskov <
rousskov at measurement-factory.com> wrote:

> 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>
> >
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.squid-cache.org/pipermail/squid-users/attachments/20250225/d759fb9e/attachment.htm>