[squid-users] Need clarifications on custom log timestamps
Alex Rousskov
rousskov at measurement-factory.com
Wed Feb 26 16:06:35 UTC 2025
On 2025-02-25 06:33, BENJAMIN DELANNOY wrote:
> > 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 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.
Just to clarify why I keep asking about specifics: I believe I
understand your overall goals, but to offer a specific solution, those
high-level goals needs to be distilled into something Squid can measure.
> 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.
Today, Squid does not record the time when those events happen, but
there is work in progress to add the necessary framework. You can
approximate those times by appending an external always-matching ACL
(that would report current time in the form of transaction annotation
that can be logged). Here is a rough sketch for http_access case:
# external ACL that returns access_decision_time_=time annotation
external_acl_type AccessDecisionTimeRecorder ...
acl recordAccessDecisionTime external AccessDecisionTimeRecorder
# recordAccessDecisionTime appended to all http_access rules
http_access allow ... recordAccessDecisionTime
http_access deny all recordAccessDecisionTime
logformat myAccessLogRecordFormat ... %note{access_decision_time_}
access_log ... logformat=myAccessLogRecordFormat
The same approach can be used for ssl_bump rules.
However, this is not pretty (i.e. this workaround is clearly bad UX),
and I the precision of that solution may not be high enough for your
needs (external ACLs will add at least a few milliseconds of delays). We
need to (and will) do better!
https://wiki.squid-cache.org/SquidFaq/AboutSquid#how-to-add-a-new-squid-feature-enhance-of-fix-something
HTH,
Alex.
> On Wed, Feb 19, 2025 at 5:39 PM Alex Rousskov 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/>
> > <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>
> <http://positivetech.adeo.com <http://positivetech.adeo.com>>
> > <https://positivetech.adeo.com/
> <https://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>
> > <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>
> > <mailto: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>
> > <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>
> > <mailto: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>
> > <https://lists.squid-cache.org/listinfo/squid-users
> <https://lists.squid-cache.org/listinfo/squid-users>>
> >
>
More information about the squid-users
mailing list