You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@trafficserver.apache.org by am...@apache.org on 2017/05/05 14:49:56 UTC
[trafficserver] branch master updated: Improve logging documentation
This is an automated email from the ASF dual-hosted git repository.
amc pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/trafficserver.git
The following commit(s) were added to refs/heads/master by this push:
new 2af6549 Improve logging documentation
2af6549 is described below
commit 2af6549f5fcb37b65987b94eafa912c8ce345e72
Author: Daniel Xu <dx...@dxuuu.xyz>
AuthorDate: Fri May 5 09:39:59 2017 -0500
Improve logging documentation
A couple of things happened in this patch:
1. Overhaul of comments in Log.h as well as fast path code in LogObject
& LogBuffer.
2. Initial draft for logging internals document. This is supposed
to be the canonical entry point for understanding logging code.
All of the previous logging documentation was either 1) missing or 2)
wrong/outdated.
---
doc/developer-guide/index.en.rst | 1 +
.../logging-architecture/architecture.en.rst | 213 ++++++++++++++++++
.../logging-architecture/index.en.rst | 28 +++
proxy/logging/Log.cc | 7 +-
proxy/logging/Log.h | 241 ---------------------
proxy/logging/LogBuffer.cc | 4 +-
proxy/logging/LogBuffer.h | 2 +-
proxy/logging/LogObject.cc | 16 +-
8 files changed, 260 insertions(+), 252 deletions(-)
diff --git a/doc/developer-guide/index.en.rst b/doc/developer-guide/index.en.rst
index 81ed665..9eed3c1 100644
--- a/doc/developer-guide/index.en.rst
+++ b/doc/developer-guide/index.en.rst
@@ -44,6 +44,7 @@ duplicate bugs is encouraged, but not required.
testing-with-vagrant/index.en
debugging/index.en
cache-architecture/index.en
+ logging-architecture/index.en
internal-libraries/index.en
plugins/index.en
config-vars.en
diff --git a/doc/developer-guide/logging-architecture/architecture.en.rst b/doc/developer-guide/logging-architecture/architecture.en.rst
new file mode 100644
index 0000000..c444aa2
--- /dev/null
+++ b/doc/developer-guide/logging-architecture/architecture.en.rst
@@ -0,0 +1,213 @@
+.. Licensed to the Apache Software Foundation (ASF) under one
+ or more contributor license agreements. See the NOTICE file
+ distributed with this work for additional information
+ regarding copyright ownership. The ASF licenses this file
+ to you under the Apache License, Version 2.0 (the
+ "License"); you may not use this file except in compliance
+ with the License. You may obtain a copy of the License at
+
+ http://www.apache.org/licenses/LICENSE-2.0
+
+ Unless required by applicable law or agreed to in writing,
+ software distributed under the License is distributed on an
+ "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ KIND, either express or implied. See the License for the
+ specific language governing permissions and limitations
+ under the License.
+
+.. include:: ../../common.defs
+
+.. _logging-architecture-introduction:
+
+A gentle introduction to ATS logging internals
+**********************************************
+
+Preface
+=======
+
+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 :ref:`admin-logging`
+chapter so you don't lose sight of the big picture.
+
+Memory layout
+=============
+
+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``. 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 ``LogObject`` and ``LogBuffer``.
+They are defined in ``proxy/logging/LogObject.h`` and
+``proxy/logging/LogBuffer.h``, respectively.
+
+LogObject
+---------
+
+Each ``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
+``LogObject``\ s 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 ``LogObject``\ s is stored in the ``LogObjectManager`` class,
+defined in ``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
+comment in ``Log.h``, the ``Log`` class should ideally be converted to a
+namespace. Feeling confused yet? We're just getting started.
+
+Brief detour: ``LogConfig`` stores all the configuration the logging
+subsystem needs. Pretty straightforward.
+
+LogBuffer
+---------
+
+The ``LogBuffer`` class is designed to provide a thread-safe mechanism
+to buffer/store log entries before they’re flushed. To reduce system call
+overhead, ``LogBuffer``\ s 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 ``LogBuffer``, the
+caller “checks out” a segment of the buffer to write into. ``LogBuffer``
+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 ``LogBuffer``
+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
+website <https://dxuuu.xyz/optimistic-concurrency.html>`__
+
+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.h`` and ``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: ``Log::access(..)``,
+``Log::error(..)``, ``preproc_thread_main(..)``, and
+``flush_thread_main(..)``.
+
+``Log::access(..)`` and ``Log::error(..)``
+------------------------------------------
+
+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 ``squid.[b]log``. ``Log::error(..)`` is
+used to put error logs into ``error.log``.
+
+``preproc_thread_main(..)``
+---------------------------
+
+``preproc_thread_main(..)`` is a thread that runs inside |ATS|'s event system.
+Think of it as just a regular POSIX pthread. This thread periodically takes a
+look all the full ``LogBuffer``\ s, does some ``preproc``\ essing work on them,
+and then finally adds the full and preprocessed ``LogBuffer``\ s to the
+global/static ``Log::flush_data_list``. ``flush_thread_main(..)`` then
+consumes these processed ``LogBuffer``\ s.
+
+``flush_thread_main(..)``
+-------------------------
+
+Just like ``preproc_thread_main(..)``, ``flush_thread_main(..)`` is run
+in a thread like environment. ``flush_thread_main(..)``'s role is rather
+simple.
+
+1. Pop each processed ``LogBuffer`` off the global/static queue.
+
+2. Check to make sure all the file structures underpinning our
+ ``LogObject``\ s are good to go.
+
+3. Flush the ``LogBuffer``\ s onto disk or through the network (in the
+ case of collated logs).
+
+Misc
+====
+
+Adding LogFields
+----------------
+
+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 <https://github.com/apache/trafficserver/commit/ead9d56da076b43a>`__.
diff --git a/doc/developer-guide/logging-architecture/index.en.rst b/doc/developer-guide/logging-architecture/index.en.rst
new file mode 100644
index 0000000..16b6fd8
--- /dev/null
+++ b/doc/developer-guide/logging-architecture/index.en.rst
@@ -0,0 +1,28 @@
+.. Licensed to the Apache Software Foundation (ASF) under one
+ or more contributor license agreements. See the NOTICE file
+ distributed with this work for additional information
+ regarding copyright ownership. The ASF licenses this file
+ to you under the Apache License, Version 2.0 (the
+ "License"); you may not use this file except in compliance
+ with the License. You may obtain a copy of the License at
+
+ http://www.apache.org/licenses/LICENSE-2.0
+
+ Unless required by applicable law or agreed to in writing,
+ software distributed under the License is distributed on an
+ "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ KIND, either express or implied. See the License for the
+ specific language governing permissions and limitations
+ under the License.
+
+.. include:: ../../common.defs
+
+.. _logging_architecture:
+
+Logging Architecture
+**********************
+
+.. toctree::
+ :maxdepth: 2
+
+ architecture.en
diff --git a/proxy/logging/Log.cc b/proxy/logging/Log.cc
index 22b6b79..c8e83f3 100644
--- a/proxy/logging/Log.cc
+++ b/proxy/logging/Log.cc
@@ -1186,10 +1186,9 @@ Log::trace_va(bool in, const sockaddr *peer_addr, uint16_t peer_port, const char
/*-------------------------------------------------------------------------
Log::preproc_thread_main
- This function defines the functionality of the logging flush prepare
- thread, whose purpose is to consume LogBuffer objects from the
- global_buffer_full_list, do some prepare work(such as convert to ascii),
- and then forward to flush thread.
+ This function defines the functionality of the logging flush preprocess
+ thread, whose purpose is to consume full LogBuffer objects, do some prepare
+ work (such as convert to ascii), and then forward to flush thread.
-------------------------------------------------------------------------*/
void *
diff --git a/proxy/logging/Log.h b/proxy/logging/Log.h
index 1e34dfb..545e35c 100644
--- a/proxy/logging/Log.h
+++ b/proxy/logging/Log.h
@@ -20,247 +20,6 @@
See the License for the specific language governing permissions and
limitations under the License.
- @section design Logging Design
-
- @verbatim
- o Configuration Variables (and sample values)
-
- proxy.config.log.format_file logs/formats
- proxy.config.log.logging_enabled 1
- proxy.config.log.failsafe_logging_enabled 0
- proxy.config.log.sampling_interval 1
- proxy.config.log.buffer_segment_count 16
- proxy.config.log.buffer_segment_size 1MB
- proxy.config.log.max_entries_per_segment 100
- proxy.config.log.online_formats_enabled 0
- proxy.config.log.online_squid_format 0
- proxy.config.log.online_ns_common_format 0
- proxy.config.log.online_ns_ext_format 0
- proxy.config.log.online_ns_ext2_format 0
- proxy.config.log.filtering_enabled 0
- proxy.config.log.local_disk_enabled 2 (only if network fails)
- proxy.config.log.network_enabled 1
- proxy.config.log.network_port 4444
- proxy.config.log.network_timeout_ms 100
- proxy.config.log.lock_timeout_ms 10
-
- o Memory Layout
-
- Log data for each transaction is stored in a LogBufferEntry that has
- been allocated from a LogBufferSegment, which in-turn is located
- within a LogBufferPool. A LogBufferPool looks like:
-
- +--++--++--+---+--+-----+--+--++--++--+----+--+---++--++...+
- |ph||sh||eh|eee|eh|eeeee|eh|ee||sh||eh|eeee|eh|eee||sh|| |
- +--++--++--+---+--+-----+--+--++--++--+----+--+---++--++...+
- ^ ^ ^ ^
- | | | |
- | | | +-- actual data for a LogBufferEntry
- | | +----- a LogBufferEntryHeader describing the following entry
- | +--------- a LogBufferSegmentHeader describing the entries
- +------------- a LogBufferPoolHeader describing the segments
-
- o Initial State
-
- - A LogBufferPool is allocated, with storage equal to
- sizeof (LogBufferPoolHeader) + buffer_segment_count * buffer_segment_size
-
- - The buffer pool space is divided into buffer_segment_count
- segments, each with a fixed size of buffer_segment_size.
-
- - All of the segments are placed on the empty_segment list in the
- pool header (H), and the first segment is assigned as the
- current_segment.
-
- o LogBuffer Allocation
-
- - If logging is disabled (!proxy.config.log.logging_enabled),
- return Log::SKIP.
-
- - If proxy.config.log.sampling_interval > 1 but it's not time to
- sample, return Log::SKIP.
-
- - If proxy.config.log.filtering_enabled, then check host and domain
- in the request_header against the filter file. If this request does
- not pass the filter, return Log::SKIP.
-
- - The pool_lock in the pool header is obtained. If it cannot be
- obtained after proxy.config.log.trylock_time_ms milliseconds, then
- a new pool is allocated and the lock is taken on the new pool.
- If a new pool cannot be allocated, then Log::FAIL is returned and
- the client (HttpStateMachineGet) can deal with the failure in the
- best possible way.
-
- - If there is not enough space in the current segment, the current
- segment is moved to the full_segment list and a segment from the
- empty_segment list is designated as the current_segment. If there
- are no segments in the empty_segment list, the FAIL_MEMORY status
- is returned.
-
- - The entry count for the current segment is bumped and the next
- offset value is computed and stored.
-
- - The pool_lock is released.
-
- - The c_request_timestamp field is set, ensuring that each of the
- entries within the segment are automatically ordered, and the
- LogBuffer pointer is returned.
-
- o LogBuffer Completion
-
- - Since each client thread now has a unique buffer pointer, all
- writes can occur concurrently and without additional locking.
-
- - The logging data will be extracted from the LogAccessData object
- using the member functions within. Only those data items that will
- be needed will be taken. The data is then marshalled into the
- buffer previously allocated.
-
- - The LogBuffer is composed of two parts: a fixed-size part that
- contains all of the statically-sized fields, and a variable-sized
- buffer that follows, containing all of the space for strings.
- Variable-size fields in the LogBuffer are actually just
- fixed-size offsets into the variable-size region.
-
- +---------------------+
- | fixed-size |
- +---------------------+
- | | contains strings and any custom logging
- : variable-size : fields not in the union set.
- | |
- +---------------------+
-
- - Once the buffer has been completed, it is committed into the
- segment from which it was allocated by incrementing the
- commit_count within the segment header. This is an ATOMIC update
- so that no locking is required. If the commit_count is equal to
- the entry_count and the segment is on the full_list, then the
- logging thread will be awoken so that it can flush the segment
- to disk/net.
-
- o Flushing
-
- +-+---------------+
- |h|bbb|b|bbbb|bbb |
- +-+---------------+
- |
- | ********** +---------------+
- +-?-> * format * ---> |abcdefghijklmno| ---> DISK
- | ********** +---------------+
- |
- +-?-> DISK
- |
- +-?-> NETWORK
-
- - The logging thread wakes up whenever there is a LogBufferSegment
- ready to be flushed. This occurs when it is on the full_segment
- list and the commit_count is the same as the entry_count.
-
- - If proxy.config.log.online_formats_enabled is set, then the segment
- is passed through the formatting module, which creates ASCII buffers
- for the selected pre-defined formats. All ASCII buffers are then
- flushed to local disk using basic I/O primitives. The logging
- thead is allowed to block on I/O since logging buffers can be
- continually allocated without the assistance of the logging thread.
-
- - If local disk logging is enabled, the complete binary segment
- structure is written to disk, and can be processed later with an
- off-line formatting tool.
-
- - If network logging is enabled, the segment is written to the
- pre-defined network port. A timeout keeps this from being an
- unbounded operation.
-
- - Once the segment has been passed through all possible output
- channels, it must be placed back onto the free_list in its pool.
- The LogBufferPool lock is then obtained.
-
- - The evacuated segment is returned to the empty_segment list.
-
- - If all of the segments are on the empty_segment list and there is
- at least one other pool around, then this pool will be deleted.
- Otherwsise, the LogBufferPool lock is released.
-
- - If there are no more segments to be flushed, then the logging
- thread will go back to sleep (waiting on a condition variable).
-
- o Off-line Processing
-
- - In the default case, data written to disk will be in binary form,
- in units of a segment. An off-line processing tool, called logcat,
- can be written to read this data (as stdin) and generate formatted
- log entries (as stdout). Thus, this tool could be used as a pipe.
-
- o Log Collation
-
- - Log collation is managed by LogCollator nodes, which are
- stand-alone processes that receive LogBufferSegments from specified
- clients and merges them into larger, collated LogBufferSegments.
- At this point, the collated segments can be flushed as before.
- To ease the impact of the initial implementation on the manager,
- the collator will likely be implemented as a new thread within the
- proxy process on the node that will do the log collation. That
- means that this node will have to run the proxy, but we should see
- about being able to disable it from actually participating in the
- proxy cluster.
-
- - Log collator processes attach to the network port for the client
- nodes they're receiving their logs from. A single collator can
- attach to any number of client nodes, and is responsible for
- keeping the network pipes clean so that log entries don't back up.
-
- - Collation is accomplished with a merge-sort of the segments from
- each node, since segments from each node are guaranteed to be
- in-order. If, due to a timeout, the collator has to continue with
- the sort and later receives an out-of-order buffer, the data will
- be processed and an error will be generated indicating that the
- collated logs are out of order. A tool will be provided to
- re-order the entries in the event of a sorting error.
-
- o Custom Log Formats
-
- - Custom logging formats are possible, where the field selection is
- the "union" set of pre-defined log format fields plus any
- information from the HTTP headers.
-
- - Log formats are specified using a printf-like format string, where
- the conversion codes (%) are replaced with the appropriate logging
- fields. Each of the union set fields will have its own conversion
- code (see LogBuffer below), and additional fields from a header
- will have the general form of %{field}header.
-
- - Formats are specified in the log format file.
-
- o Filtering
-
- - Currently, filtering will only be supported based on exact matching
- of the host or domain name of the request.
-
- - Filtering is specified in the log format file.
-
- o Log Format File
-
- - Each line of the log format file consists of four fields separated
- by whitespaces:
-
- + identifier - used to identify this format/filter
- + filename - the name of the log file
- + (filter) - the filter to apply for this file
- + "format" - the format string for each entry
-
- Filters have the form (field op value), where "field" can either be
- %shn (server host name) or %sdn (sever domain name); "op" can either
- be == or !=; and "value" can be any valid hostname or domain name,
- such as hoot.example.com or example.com.
-
- - Sample entries in the log format file:
-
- 1 common () "%chi - %cun [%cqtf] \"%cqtx\" %pss %pcl"
- 2 custom (%shn == hoot.example.com) "%cqu"
- @endverbatim
-
- @section api External API
-
@verbatim
int Log::access (LogAccess *entry);
diff --git a/proxy/logging/LogBuffer.cc b/proxy/logging/LogBuffer.cc
index 9f73277..f15f519 100644
--- a/proxy/logging/LogBuffer.cc
+++ b/proxy/logging/LogBuffer.cc
@@ -219,7 +219,9 @@ LogBuffer::checkout_write(size_t *write_offset, size_t write_size)
uint64_t retries = (uint64_t)-1;
do {
- new_s = old_s = m_state;
+ // we want sequence points between these two statements
+ old_s = m_state;
+ new_s = old_s;
if (old_s.s.full) {
// the buffer has already been set to full by somebody else
diff --git a/proxy/logging/LogBuffer.h b/proxy/logging/LogBuffer.h
index f59e2c4..b7462ad 100644
--- a/proxy/logging/LogBuffer.h
+++ b/proxy/logging/LogBuffer.h
@@ -105,7 +105,7 @@ union LB_State {
return *this;
}
- int64_t ival;
+ int64_t ival; // ival is used to help do an atomic CAS for struct s
struct {
uint32_t offset; // buffer offset(bytes in buffer)
uint16_t num_entries; // number of entries in buffer
diff --git a/proxy/logging/LogObject.cc b/proxy/logging/LogObject.cc
index 6878210..1578312 100644
--- a/proxy/logging/LogObject.cc
+++ b/proxy/logging/LogObject.cc
@@ -414,11 +414,14 @@ LogObject::_checkout_write(size_t *write_offset, size_t bytes_needed)
do {
INK_QUEUE_LD(old_h, m_log_buffer);
+ // we may depend on comparing the old pointer to the new pointer to detect buffer swaps
+ // without worrying about pointer collisions because we always allocate a new LogBuffer
+ // before freeing the old one
if (FREELIST_POINTER(old_h) != FREELIST_POINTER(h)) {
ink_atomic_increment(&buffer->m_references, -1);
- // another thread should be taking care of creating a new
- // buffer, so delete new_buffer and try again
+ // another thread is already creating a new buffer,
+ // so delete new_buffer and try again next loop iteration
delete new_buffer;
break;
}
@@ -458,23 +461,26 @@ LogObject::_checkout_write(size_t *write_offset, size_t bytes_needed)
if (!decremented) {
head_p old_h;
+ // The do-while loop protects us from races while we're examining ptr(old_h) and ptr(h)
+ // (essentially an optimistic lock)
do {
INK_QUEUE_LD(old_h, m_log_buffer);
if (FREELIST_POINTER(old_h) != FREELIST_POINTER(h)) {
+ // Another thread's allocated a new LogBuffer, we don't need to do anything more
break;
}
} while (!write_pointer_version(&m_log_buffer, old_h, FREELIST_POINTER(h), FREELIST_VERSION(old_h) - 1));
if (FREELIST_POINTER(old_h) != FREELIST_POINTER(h)) {
+ // Another thread's allocated a new LogBuffer, meaning this LogObject is no longer referencing the old LogBuffer
ink_atomic_increment(&buffer->m_references, -1);
}
}
} while (retry && write_offset); // if write_offset is null, we do
- // not retry because we really do
- // not want to write to the buffer
- // only to set it as full
+ // not retry because we really do not want to write to the buffer,
+ // only to mark the buffer as full
if (result_code == LogBuffer::LB_BUFFER_TOO_SMALL) {
buffer = nullptr;
}
--
To stop receiving notification emails like this one, please contact
['"commits@trafficserver.apache.org" <co...@trafficserver.apache.org>'].