Skip to content

Add ASIO completion handler tracking#2681

Merged
wezrule merged 3 commits into
nanocurrency:developfrom
wezrule:asio_handler_tracking
Jul 16, 2020
Merged

Add ASIO completion handler tracking#2681
wezrule merged 3 commits into
nanocurrency:developfrom
wezrule:asio_handler_tracking

Conversation

@wezrule

@wezrule wezrule commented Mar 25, 2020

Copy link
Copy Markdown
Contributor

Boost asio has a way to output diagnostic information about completion handlers by defining BOOST_ASIO_ENABLE_HANDLER_TRACKING you get output like so:

@asio|1512254357.979980|0*1|signal_set@0x7ffeaaaa20d8.async_wait
@asio|1512254357.980127|0*2|socket@0x7ffeaaaa20f8.async_accept
@asio|1512254357.980150|.2|non_blocking_accept,ec=asio.system:11
@asio|1512254357.980162|0|resolver@0x7ffeaaaa1fd8.cancel
@asio|1512254368.457147|.2|non_blocking_accept,ec=system:0
@asio|1512254368.457193|>2|ec=system:0
@asio|1512254368.457219|2*3|socket@0x55cf39f0a238.async_receive
@asio|1512254368.457244|.3|non_blocking_recv,ec=system:0,bytes_transferred=141
@asio|1512254368.457275|2*4|socket@0x7ffeaaaa20f8.async_accept
@asio|1512254368.457293|.4|non_blocking_accept,ec=asio.system:11

Information about what these entries mean can be found here:
https://www.boost.org/doc/libs/1_72_0/doc/html/boost_asio/overview/core/handler_tracking.html

But they can also be turned into a graph: (described later)
image

By itself it's not that useful as we really care about how long these io thread completion handlers are taking. I've modified the thread_runner and system polling to now report any completion handlers which take longer than NANO_ASIO_HANDLER_TRACKING (new CMake variable). It outputs the timestamp which can be cross-referenced with the images/text to find what caused it. It is recommended to use less io_threads if trying to diagnose issues with these as multiple completion handlers cause be executing in parallel.

Proposed mode of operation:
1 - cmake -DNANO_ASIO_HANDLER_TRACKING=10 (report anything held for 10ms or greater)
2 - Lower io_threads in config-node.toml
3 - Run suspect code and pipe error output (asio uses that stream):
./core_test --gtest_filter=suspect_test 2> asio_output.txt
4 - For any "io_thread held for ??ms" messages, cross-reference with text and remove extraneous text surrounding it (see below)
5 - Generate image perl handlerviz.pl < asio_output.txt | dot -Tpng > output.png . If the asio_output.txt file is large this can crash or take a very long time, as well as make the image unreadable. dot binary is from GraphViz and can be installed for free on all platforms.

This can be a good first step in helping diagnose issues and inform of any completion handlers taking too long. A further step may be to wrap all completion handlers and break before exiting but that's a much larger effort with greater.

@wezrule wezrule added documentation This item indicates the need for or supplies updated or expanded documentation toml TOML related change debug Updates assisting with debugging and development efforts labels Mar 25, 2020
@wezrule wezrule added this to the V22.0 milestone Mar 25, 2020
@wezrule wezrule added tool Introduces or updates a tool or command and removed toml TOML related change labels Mar 25, 2020
@wezrule wezrule self-assigned this Mar 25, 2020
@wezrule
wezrule requested a review from SergiySW June 18, 2020 14:14
SergiySW
SergiySW previously approved these changes Jul 16, 2020
@SergiySW
SergiySW self-requested a review July 16, 2020 07:51
@wezrule
wezrule merged commit 1f2f61a into nanocurrency:develop Jul 16, 2020
@wezrule
wezrule deleted the asio_handler_tracking branch July 16, 2020 11:49
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

debug Updates assisting with debugging and development efforts documentation This item indicates the need for or supplies updated or expanded documentation tool Introduces or updates a tool or command

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants