...one of the most highly
regarded and expertly designed C++ library projects in the
world.
— Herb Sutter and Andrei
Alexandrescu, C++
Coding Standards
To aid in debugging asynchronous programs, Boost.Asio provides support
for handler tracking. When enabled by defining BOOST_ASIO_ENABLE_HANDLER_TRACKING
,
Boost.Asio writes debugging output to the standard error stream. The output
records asynchronous operations and the relationships between their handlers.
This feature is useful when debugging and you need to know how your asynchronous operations are chained together, or what the pending asynchronous operations are. As an illustration, here is the output when you run the HTTP Server example, handle a single request, then shut down via Ctrl+C:
@asio|1589424178.741850|0*1|signal_set@0x7ffee977d878.async_wait @asio|1589424178.742593|0*2|socket@0x7ffee977d8a8.async_accept @asio|1589424178.742619|.2|non_blocking_accept,ec=asio.system:11 @asio|1589424178.742625|0|resolver@0x7ffee977d760.cancel @asio|1589424195.830382|.2|non_blocking_accept,ec=system:0 @asio|1589424195.830413|>2|ec=system:0 @asio|1589424195.830473|2*3|socket@0x7fa71d808230.async_receive @asio|1589424195.830496|.3|non_blocking_recv,ec=system:0,bytes_transferred=151 @asio|1589424195.830503|2*4|socket@0x7ffee977d8a8.async_accept @asio|1589424195.830507|.4|non_blocking_accept,ec=asio.system:11 @asio|1589424195.830510|<2| @asio|1589424195.830529|>3|ec=system:0,bytes_transferred=151 @asio|1589424195.831143|3^5|in 'async_write' (./../../../boost/asio/impl/write.hpp:330) @asio|1589424195.831143|3*5|socket@0x7fa71d808230.async_send @asio|1589424195.831186|.5|non_blocking_send,ec=system:0,bytes_transferred=1090 @asio|1589424195.831194|<3| @asio|1589424195.831218|>5|ec=system:0,bytes_transferred=1090 @asio|1589424195.831263|5|socket@0x7fa71d808230.close @asio|1589424195.831298|<5| @asio|1589424199.793770|>1|ec=system:0,signal_number=2 @asio|1589424199.793781|1|socket@0x7ffee977d8a8.close @asio|1589424199.793809|<1| @asio|1589424199.793840|>4|ec=asio.system:125 @asio|1589424199.793854|<4| @asio|1589424199.793883|0|signal_set@0x7ffee977d878.cancel
Each line is of the form:
<tag>|<timestamp>|<action>|<description>
The <tag>
is always @asio
, and is used
to identify and extract the handler tracking messages from the program
output.
The <timestamp>
is seconds and microseconds from 1 Jan
1970 UTC.
The <action>
takes one of the following forms:
The program entered the handler number n
. The <description>
shows the arguments to the handler.
The program left handler number n
.
The program left handler number n due to an exception.
The handler number n
was destroyed without having been
invoked. This is usually the case for any unfinished asynchronous
operations when the io_context
is destroyed.
The handler number n
is about to create a new asynchronous
operation with completion handler number m
. The <description>
contains source location information to help identify where in the
program the asynchronous operation is being started.
The handler number n
created a new asynchronous operation
with completion handler number m
. The <description>
shows what asynchronous operation was started.
The handler number n
performed some other operation.
The <description>
shows what function was called.
Currently only close()
and cancel()
operations
are logged, as these may affect the state of pending asynchronous
operations.
The implementation performed a system call as part of the asynchronous
operation for which handler number n
is the completion
handler. The <description>
shows what function
was called and its results. These tracking events are only emitted
when using a reactor-based implementation.
Where the <description>
shows a synchronous or asynchronous
operation, the format is <object-type>@<pointer>.<operation>
.
For handler entry, it shows a comma-separated list of arguments and their
values.
As shown above, Each handler is assigned a numeric identifier. Where the handler tracking output shows a handler number of 0, it means that the action was performed outside of any handler.
Programs may augment the handler tracking output's location information
by using the macro BOOST_ASIO_HANDLER_LOCATION
in the source code. For example:
#define HANDLER_LOCATION \ BOOST_ASIO_HANDLER_LOCATION((__FILE__, __LINE__, __func__)) // ... void do_read() { HANDLER_LOCATION; auto self(shared_from_this()); socket_.async_read_some(boost::asio::buffer(data_, max_length), [this, self](boost::system::error_code ec, std::size_t length) { HANDLER_LOCATION; if (!ec) { do_write(length); } }); }
With the additional location information available, the handler tracking output may include a call stack of source locations:
@asio|1589423304.861944|>7|ec=system:0,bytes_transferred=5 @asio|1589423304.861952|7^8|in 'async_write' (./../../../boost/asio/impl/write.hpp:330) @asio|1589423304.861952|7^8|called from 'do_write' (handler_tracking/async_tcp_echo_server.cpp:62) @asio|1589423304.861952|7^8|called from 'operator()' (handler_tracking/async_tcp_echo_server.cpp:51) @asio|1589423304.861952|7*8|socket@0x7ff61c008230.async_send @asio|1589423304.861975|.8|non_blocking_send,ec=system:0,bytes_transferred=5 @asio|1589423304.861980|<7|
Furthermore, if std::source_location
or std::experimental::source_location
are available, the use_awaitable_t
token (when default-constructed or used as a default completion token)
will also cause handler tracking to output a source location for each newly
created asynchronous operation. A use_awaitable_t
object may
also be explicitly constructed with location information.
The handler tracking output may be post-processed using the included handlerviz.pl
tool to create a visual representation of the handlers (requires the GraphViz
tool dot
).
Handling tracking may be customised by defining the BOOST_ASIO_CUSTOM_HANDLER_TRACKING
macro to the name of a header file (enclosed in ""
or <>
). This header
file must implement the following preprocessor macros:
Macro |
Description |
---|---|
|
Specifies a base class for classes that implement asynchronous
operations. When used, the macro immediately follows the class
name, so it must have the form |
|
Specifies a base class for classes that implement asynchronous
operations. When used, the macro follows other base classes,
so it must have the form |
|
An expression that is used to initialise the tracking mechanism. |
|
A variable declaration that is used to define a source code location.
|
|
An expression that is called on creation of an asynchronous operation.
|
|
An expression that is called on completion of an asynchronous
operation. |
|
An expression that is called immediately before a completion
handler is invoked. |
|
An expression that is called immediately after a completion handler is invoked. |
|
An expression that is called when some synchronous object operation
is called (such as |
|
An expression that is called when an object is registered with
the reactor. |
|
An expression that is called when an object is deregistered from
the reactor. |
|
A bitmask constant used to identify reactor read readiness events. |
|
A bitmask constant used to identify reactor write readiness events. |
|
A bitmask constant used to identify reactor error readiness events. |
|
An expression that is called when an object registered with the
reactor becomes ready. |
|
An expression that is called when the implementation performs
a system call as part of a reactor-based asynchronous operation.
|