Skip to content

Tracing#4412

Merged
pwojcikdev merged 12 commits intonanocurrency:developfrom
pwojcikdev:tracing-4-develop
Feb 8, 2024
Merged

Tracing#4412
pwojcikdev merged 12 commits intonanocurrency:developfrom
pwojcikdev:tracing-4-develop

Conversation

@pwojcikdev
Copy link
Copy Markdown
Contributor

@pwojcikdev pwojcikdev commented Jan 30, 2024 •
edited
Loading

The goal of this PR is to introduce a framework for tracing events in the node. This is meant to be used for debugging and profiling purposes, eg. by visualizing the flow of votes through the network or analyzing the delay between receiving a block and confirming it.

This is accomplished by introducing a nano::object_stream class that can be used to serialize objects. It is meant to be a relatively thin wrapper around the underlying stream, that ensures the output format is structured and consistent. It avoids allocations and unnecessary run-time dispatching by using a compile-time visitor pattern.

This interface also allows to switch between different output formats and automatically handles some common functionality, like providing operator<<, to_string() and to_json(). If in the future a better serialization library is found, it should be possible to easily replace the underlying implementation without changing the interface.

Usage

To use tracing, it must be enabled at compile time by passing -DNANO_TRACING=ON flag to CMake. By default, it is disabled for release builds and enabled for debug builds.

After that, tracing can be enabled by setting the logging verbosity level to trace. (NANO_LOG=trace)

Since the amount of logs when setting logging level to trace is very large, it is recommended to use trace level only for specific components. This can be done by setting NANO_LOG_LEVELS environment variable to a comma-separated list of components to trace. For example, to trace only active_transactions and vote_processor, set NANO_LOG_LEVELS="active_transactions=trace,vote_processor=trace". Alternatively this can also be done by modifying the config-log.toml file.

Tracing Formats

It is possible to specify format of tracing output at runtime. This is done by setting NANO_TRACE_FORMAT environment variable to one of the following: standard or json.

Standard

Standard tracing format is enabled by default. It is a simple key: { value } format with indentation that should be easy to read.
Sample output:

[2024-01-30 17:04:19.001] [active_transactions::active_stopped] [trace] event: "active_transactions::active_stopped",
time: 1706630658999596,
election: {
   id: "0x10b0171e68aac183",
   qualified_root: "AA97A292E1F8B84B2F95F03CE54DE97F8E7ACF9B3CFE6408A58CD859E89BAFBBAA97A292E1F8B84B2F95F03CE54DE97F8E7ACF9B3CFE6408A58CD859E89BAFBB",
   behaviour: "normal",
   height: 1027,
   status: {
      winner: "2F5FE06EA686B46AEDF807FE1BB87AA87650EC2B9FBD6EE45BE0E248CF6DFC01",
      tally_amount: "63604200648126004984521699083584821166",
      final_tally_amount: "63604200648126004984521699083584821166",
      confirmation_request_count: 1,
      block_count: 1,
      voter_count: 46,
      type: "active_confirmed_quorum",
      votes: [
         {
            account: "nano_37imps4zk1dfahkqweqa91xpysacb7scqxf3jqhktepeofcxqnpx531b3mnt",
            hash: "2F5FE06EA686B46AEDF807FE1BB87AA87650EC2B9FBD6EE45BE0E248CF6DFC01",
            final: true,
            timestamp: 18446744073709551615,
            time: 9747922583882
         }
      ],
      blocks: [
         {
            type: "state",
            hash: "2F5FE06EA686B46AEDF807FE1BB87AA87650EC2B9FBD6EE45BE0E248CF6DFC01",
            sideband: {
               successor: "F397C6B0B4DA7F78A371A7C1104FC09CF9026DBDC1F1362DCC8FF79A34397074",
               account: "0000000000000000000000000000000000000000000000000000000000000000",
               balance: "00000000000000000000000000000000",
               height: 1027,
               timestamp: 1706630658,
               source_epoch: "epoch_begin",
               details: {
                  epoch: "epoch_2",
                  is_send: true,
                  is_receive: false,
                  is_epoch: false
               }
            },
            account: "000F4E4E400F69BE1CE68B685380CF8D07C46CE2E75A1C1DB36CBC06A129EA49",
            previous: "AA97A292E1F8B84B2F95F03CE54DE97F8E7ACF9B3CFE6408A58CD859E89BAFBB",
            representative: "897F7EE0A29F631912ABB513FAC371FC82B319DA76D665149E70C8263FEF802E",
            balance: "0000000000000000000000000001869E",
            link: "000F4E4E400F69BE1CE68B685380CF8D07C46CE2E75A1C1DB36CBC06A129EA49",
            signature: "6017882E2970085AC44BE3CA3B9424D6093A8266CC04012114B718ACE6D688E183EDEE89D10F8D2072E9DB27111E5D3FFCA7DC786A45C1CB25470BCEBE75790A",
            work: 13187085369013726348
         }
      ],
      tally: [
         {
            hash: "2F5FE06EA686B46AEDF807FE1BB87AA87650EC2B9FBD6EE45BE0E248CF6DFC01",
            amount: "63604200648126004984521699083584821166"
         }
      ]
   }
}

JSON

JSON tracing format is meant to be parsed by external tools. There is no indentation or newlines, so each log output line can be treated as a separate event, which simplifies parsing.
Sample output:

[2024-01-30 17:56:53.312] [vote_processor::vote_processed] [trace] "event":"vote_processor::vote_processed","time":1706633813312751,"vote":{"account":"FD16B0FE0102F68C2D9482348AE7211E3CBF86681364E53D8793A5E551167A6C","final":true,"timestamp":18446744073709551615,"hashes":["7DEF4D1F5EB222BC5DE2123293EE5A8CE58E283176AB65DF3373DA009FD99E86"]},"result":"indeterminate"

@pwojcikdev pwojcikdev force-pushed the tracing-4-develop branch 2 times, most recently from fe73f62 to d0bdc6b Compare January 30, 2024 21:52
@pwojcikdev pwojcikdev force-pushed the tracing-4-develop branch 2 times, most recently from ee85b5d to b994921 Compare February 1, 2024 17:57
dsiganos
dsiganos reviewed Feb 2, 2024
View reviewed changes
dsiganos
dsiganos previously approved these changes Feb 6, 2024
View reviewed changes
nano/node/transport/channel.cpp Outdated
node.logger.trace (nano::log::type::channel_sent, nano::to_log_detail (message_a.type ()),
nano::log::arg{ "message", message_a },
nano::log::arg{ "channel", *this },
nano::log::arg{ "dropped", false });
Copy link
Copy Markdown
Contributor

@dsiganos dsiganos Feb 3, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

To achieve more compression of data, we could remove the dropped field when it is set to false.
So, a missing dropped would mean that the message was not dropped.

Copy link
Copy Markdown
Contributor Author

@pwojcikdev pwojcikdev Feb 6, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Some tools that automatically detect data format (eg. Apache Drill, but likely others too) might have problems with format that is inconsistent. I believe in case of Drill it infers schema from first ~60k entries. Looking at this now, this function flow should be refactored, so that it has a single point at which data is logged.

dsiganos
dsiganos reviewed Feb 6, 2024
View reviewed changes
@dsiganos dsiganos mentioned this pull request Feb 7, 2024
Open
@pwojcikdev pwojcikdev merged commit 5abd5ba into nanocurrency:develop Feb 8, 2024
@qwahzi qwahzi added this to the V27 milestone Feb 8, 2024
@qwahzi qwahzi added the logging label Feb 8, 2024
@qwahzi qwahzi mentioned this pull request Mar 11, 2024
Closed
@gr0vity-dev gr0vity-dev mentioned this pull request Jul 4, 2024
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@dsiganos dsiganos dsiganos approved these changes

Assignees

No one assigned

Labels

logging

Projects

Nano Roadmap
Status: Merged / V27.0

Milestone

V27

Development

Successfully merging this pull request may close these issues.

3 participants

@pwojcikdev @dsiganos @qwahzi