Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[3.2] Log block trx summary for speculative and BP blocks #145

Merged
merged 5 commits into from
Sep 15, 2022

Conversation

heifner
Copy link
Member

@heifner heifner commented Sep 12, 2022

Add additional logging to report transaction execution time per block including speculative blocks. Also report block idle time waiting on incoming transactions.

The output is enabled by producer_plugin logger at debug level.

Example output:

debug 2022-09-12T18:47:37.241 test_trx_ producer_plugin.cpp:187       report               ] Block trx idle: 231428us out of 241425us, success: 1128, 6622us, fail: 174, 2321us, other: 1054us
  • The Block trx idle: is time the node is waiting for trxs to come into a node and be scheduled for execution since the end of the last trx processed.
  • The out of is the time since the last block completion. Should be close to the configured CPU Effort for a given block. For example an empty block with 80% CPU effort Block trx idle: 400351us out of 400541us, success: 0, 0us, fail: 0, 0us, other: 190us. The complete "idle" time for this block would be 500ms. The idle time of the CPU effort is not reported. The value should be thought of as the time the node was able according to configuration to process trxs.
  • success: {n}, {t}us is the number of successful transactions processed during this block and how long they took to execute.
  • fail: {n}, {t}us is the number of transactions that failed processing during this block and how long they took to execute before they failed.
  • other: is the time of (out of - Block trx idle - success time - fail time). The time nodeos is logging or doing other book keeping. It is the block time not accounted for in the other reported times.

Also move producer_plugin.cpp:1980 push_transaction ] Failed 3050003 trx, auth: stopblocking, prev billed: 0us, ran: 5594us, id: b9cb28694b54e721994011e4d4ae128dee54467a98e8afb3e7b9d6d041fe2f91 logging to transaction_failure_tracing logger from producer_plugin as it produces too much logging when producer_plugin set to debug.

Resolves #119

@heifner heifner added the OCI Work exclusive to OCI team label Sep 12, 2022
@@ -226,6 +249,12 @@ class account_failures {

std::map<account_name, account_failure> failed_accounts;
uint32_t max_failures_per_account = 3;
mutable fc::microseconds block_idle_time;
Copy link
Member

Choose a reason for hiding this comment

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

Quite unusual to see this. How bad is it to unwind the const train to not make this mutable? A cursory look, seems like report() const is called from both abort_block() & produce_block() (neither of which are const already)

Copy link
Member Author

Choose a reason for hiding this comment

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

Thanks. Removed mutable/const which is much cleaner.

@heifner heifner merged commit 04c625b into main Sep 15, 2022
@heifner heifner deleted the GH-119-more-logging branch September 15, 2022 14:18
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
OCI Work exclusive to OCI team
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Add more logging of subjective information on non-producing nodes
2 participants