]> git.ipfire.org Git - thirdparty/squid.git/commit - src/client_side_request.cc
Report context of level-0/1 cache.log messages (#483)
authorAlex Rousskov <rousskov@measurement-factory.com>
Fri, 4 Oct 2019 14:14:09 +0000 (14:14 +0000)
committerSquid Anubis <squid-anubis@squid-cache.org>
Fri, 11 Oct 2019 13:03:45 +0000 (13:03 +0000)
commitccfbe8f49d36e8cce928b552a2ad7b4343ccdabd
treedd503472f6fc3e38344fbaef4d33efe88241ebe5
parent508590d942a905cfc3301df3d83fe417c402c5ee
Report context of level-0/1 cache.log messages (#483)

Most runtime level-0/1 cache.log messages do not carry information
sufficient to identify the transaction that caused the problem. Admins
are forced to guess the transaction based on message timestamp and, if
they are lucky to get one, request URL. The associated triage and
mitigation delay costs are often significant and can be huge, especially
when administering busy proxies in complex deployment environments.

The focus of this change is associating level-0/1 cache.log messages
with access.log records, but the same API is also used for associating
master transactions with (sections of) debugging cache.log messages.

Since level-0/1 messages are rare, association code usually wastes
resources. This performance overhead is reduced by saving pointers to
the existing transaction information (e.g., ALE). ALE gives access to
HttpRequest and MasterXaction (where available), is available in
contexts where HttpRequest and MasterXaction do not exist, and (unlike
HttpRequest) represents the whole master transaction rather than its
(often repeated) component.

CodeContext::Current() represents the current master transaction (or a
similar "primary processing task" context). A new context is created
when the master transaction (or a similar "primary processing task")
starts. Context changes usually happen in low-level transaction-unaware
callback-calling "context switching" code such as DoSelect().

The vast majority of AsyncCalls, including AsyncCall-based callbacks,
should run in their creator's context. This association is easily
automated. The primary difficulty is in handling C-style typeless calls
that prohibit context storage and restoration automation:

* In our design, the "context switching" code is ultimately responsible
  for associating the being-saved callback with the current code context
  and for restoring CodeContext::Current() when calling that callback.

* An alternative design would task the higher-level callback creator and
  callback recipient with saving/restoring CodeContext::Current(). That
  design is inferior because there are a lot more callback creators and
  recipients than "context switchers". That alternative would require a
  lot more manual changes.

The code context remains unknown if the context creator is not
instrumented to set CodeContext::Current(). TODO: Instrument ICP query
listener. Check for others.

The code context gets forgotten if the context switcher dealing with
C-style callbacks does not remember and restore CodeContext::Current().
TODO: Instrument remaining DoSelect()s, event.cc, as well as DNS, ICP,
HTCP, and IPC listeners/handlers. Check for others.

This change covers epoll DoSelect(), TcpAcceptor, ConnStateData, and SMP
disk I/O (IpcIoFile). It already annotates several level-0/1 messages
and significantly improves complex debugging. The remaining
instrumentation TODOs are likely to use similar techniques.

Squid might report wrong context until all context switchers are
instrumented, but the vast majority of uninstrumented cases result in
benign loss of context knowledge rather than mis-attribution. No design
guarantees correct attribution until all C-style callbacks are gone.

TODO: Remove legacy ctx_enter()/exit() debugging that covers very little
while suffering from worse mis-attribution problems.

Also log "-" instead of the made-up method "NONE".
33 files changed:
src/AccessLogEntry.cc
src/AccessLogEntry.h
src/Debug.h
src/DiskIO/IpcIo/IpcIoFile.cc
src/DiskIO/IpcIo/IpcIoFile.h
src/anyp/PortCfg.cc
src/anyp/PortCfg.h
src/base/AsyncCall.cc
src/base/AsyncCall.h
src/base/AsyncCallQueue.cc
src/base/CodeContext.cc [new file with mode: 0644]
src/base/CodeContext.h [new file with mode: 0644]
src/base/InstanceId.h
src/base/Makefile.am
src/base/RefCount.h
src/base/Subscription.h
src/base/TextException.cc
src/base/TextException.h
src/base/forward.h
src/client_side.cc
src/client_side_request.cc
src/comm.cc
src/comm/Connection.cc
src/comm/Connection.h
src/comm/ModEpoll.cc
src/comm/TcpAcceptor.cc
src/comm/TcpAcceptor.h
src/debug.cc
src/fde.h
src/htcp.cc
src/http/Stream.cc
src/neighbors.cc
src/tests/stub_libcomm.cc