A gentle introduction to ATS logging internals¶
The logging subsystem is a rather large and tricky section of the code base. You’ll find that over the years, as people have come and gone, large swathes of the code may lack comments and/or documentation. Even worse, when there are comments, some (but not all) might be flat out wrong or outdated.
Your author has put in some effort in adding comments and removing wrong documentation, but the effort is ongoing.
Note: before reading this, make sure you read the Logging chapter so you don’t lose sight of the big picture.
Here we will discuss the internal (and in the case of binary logging, also external) memory layout for logs. Keep in mind that you should revisit this section after reading the rest of this doc.
Log data for each transaction (henceforth called a log entry) is stored in a
LogBuffer. There may be more than one log entry in each
LogBuffer is prepended with a
LogBufferHeader. Each log entry is
prepended with a
LogEntryHeader. In this manner, the layout for a single
LogBuffer might look something like this:
free space LogBuffer | v +--+--+----+--+---+--+-----+------------+ |bh|eh|eeee|eh|eee|eh|eeeee|xxxxxxxxxxxx| +--+--+----+--+---+--+-----+------------+ ^ ^ ^ ^ | | | | | | | +- a LogEntryHeader | | +----- actual log entry data | +--------- a LogEntryHeader describing the entry +------------ a LogBufferHeader containing info about the log entries
Important data structures¶
There are a lot of data structures present in the logging code, but
undoubtedly the two most important are
They are defined in
LogObject represents a logical ATS logging object. This may
sound tautological, but that’s because the implementation fits the
abstraction well. Hand in glove, so to speak. In typical cases (with the
notable exceptions of logging to pipe and logging over network), a
LogObject will map to a file on disk.
When a logging event occurs, ATS will cycle through all the configured
LogObjects and attempt to save that logging event to each
LogObject. In this way, the same event can be saved in a variety of
different formats and places.
The list of
LogObjects is stored in the
proxy/logging/LogObject.h. There is one and only one
LogObjectManager instance stored inside the
LogConfig instance, which
is in turn stored inside static
Log class. As indicated by the decades old
Log class should ideally be converted to a
namespace. Feeling confused yet? We’re just getting started.
LogConfig stores all the configuration the logging
subsystem needs. Pretty straightforward.
LogBuffer class is designed to provide a thread-safe mechanism
to buffer/store log entries before they’re flushed. To reduce system call
LogBuffers are designed to avoid heavy-weight mutexes in
favor of using lightweight atomics built on top of compare-and-swap
operations. When a caller wants to write into a
caller “checks out” a segment of the buffer to write into.
makes sure that no two callers are served overlapping segments. To
illustrate this point, consider this diagram of a buffer:
LogBuffer instance +--------------------------------+ | thread_1's segment | |--------------------------------| | thread_2's segment | | | | | |--------------------------------| | thread_3's segment | | | | | | | |--------------------------------| | thread_4's segment | |--------------------------------| | <unused> | | | | | | | | | | | | | | | +--------------------------------+
In this manner, since no two threads are writing in the other’s segment,
we avoid race conditions during the actual logging. This also makes
LogBuffer’s critical section extremely small. In fact, the only time we
need to enter a critical section is when we do the book keeping to keep
track of which segments are checked out. Despite this, it’s not unusual
to see between 5% and 20% of total processor time spent inside
serialization code. It’s unclear at this time whether or not actual locks
will improve performance, so further performance testing is still necessary.
There’s a lot more that could be said about
LogBuffer. If you’re
interested, come read it on the author’s personal
Brief overview of the code¶
Here I’ll cover the most important parts of the logging code. Note that what’s being covered here is the main data path, the path user agent accesses take to getting into a log file. Much more can be said about the rest of the logging code, but it’s all rather trivial to manually figure out once you know the data path and data structures. In an effort to keep this document timeless, we will avoid documenting more code than this.
proxy/logging/Log.cc are the entry
points into the logging subsystem. There are a few notable functions in
Log.cc that we should pay close attention to:
These two functions are the entirety of the API that the logging
subsystem exposes to the rest of ATS.
Log::access(..) records access
events, eg. when a user agent requests a document through ATS. These
entries are typically sent to
used to put error logs into
preproc_thread_main(..) is a thread that runs inside Apache Traffic Server™’s event system.
Think of it as just a regular POSIX pthread. This thread periodically takes a
look all the full
LogBuffers, does some
preprocessing work on them,
and then finally adds the full and preprocessed
LogBuffers to the
consumes these processed
flush_thread_main(..) is run
in a thread like environment.
flush_thread_main(..)’s role is rather
Pop each processed
LogBufferoff the global/static queue.
Check to make sure all the file structures underpinning our
LogObjects are good to go.
LogBuffers onto disk or through the network (in the case of collated logs).
If you’re working with logging code, there’s a good chance you’ll be adding more log fields. This isn’t so much hard as it’s annoying. The best way to learn all the incantations is to look at an example. For example, this commit.