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] Additional transaction/block time logging #537

Merged
merged 4 commits into from
Jun 29, 2022
Merged

Conversation

heifner
Copy link
Member

@heifner heifner commented Jun 25, 2022

Additional logging to existing log statements:

info 2022-06-25T16:37:28.419 nodeos producer_plugin.cpp:2486 produce_block ] Produced block 23e74c6387b1b15f... #53 @ 2022-06-25T16:37:28.500 signed by defproducerc [trxs: 18, lib: 48, confirmed: 0, net: 2592, cpu: 7030]

  • info level logging for default logger
  • net - sum of transaction trace net_usage in bytes
  • cpu - sum of transaction trace cpu_usage_us in microseconds

info 2022-06-25T16:37:23.979 nodeos producer_plugin.cpp:509 on_incoming_block ] Received block 01e618736c7f02f5... #44 @ 2022-06-25T16:37:24.000 signed by eosio [trxs: 9, lib: 43, conf: 0, net: 89592, cpu: 20526, elapsed: 19293, time: 44956, latency: -20 ms]

  • info level logging for default logger
  • net - sum of transaction trace net_usage in bytes
  • cpu - sum of transaction trace cpu_usage_us in microseconds
  • elapsed - sum of transaction trace elapsed in microseconds
  • time - wall clock time for processing/validating the block in microseconds

debug 2022-06-25T16:37:24.007 nodeos producer_plugin.cpp:743 process_incoming_tra ] Subjective bill for success eosio: 0 elapsed 1082us, time 1287us

  • debug level logging for transaction_success_tracing & transaction_failure_tracing logger
  • elapsed - transaction trace elapsed in microseconds
  • time - wall clock time for processing/validating the transaction in microseconds

New logging:

debug 2022-06-25T17:26:28.501 nodeos producer_plugin.cpp:2213 process_scheduled_an ] [TRX_TRACE] Block 77 for producer defproducera is ACCEPTING scheduled tx: 8203fcf4583e6f86377c09391d3a11688379fb4969df65eec38173d286ee083f, time: 452, auth: eosio, cpu: 210

  • debug level logging for transaction_success_tracing & transaction_failure_tracing logger
  • time - wall clock time for executing the transaction in microseconds
  • auth - first authorizer of the transaction
  • cpu - transaction trace receipt cpu_usage_us in microseconds

debug 2022-06-25T17:38:36.326 nodeos producer_plugin.cpp:689 process_incoming_tra ] Time since last trx: 21479us

  • debug level logging for transaction_success_tracing logger
  • Reports wall clock time in microseconds since the completion of the previous transaction or since the start of the block

debug 2022-06-25T17:38:34.001 nodeos producer_plugin.cpp:2216 process_scheduled_an ] [TRX_TRACE] Block 77 for producer defproducera is ACCEPTING scheduled tx: {"id":"93778ab0d07ceab684323c3f7ab053923266318254ab5d583f5a699ef1d7b585","block_num":77,"block_time":"2022-06-25T17:38:34.500","producer_block_id":null,"receipt":{"status":"executed","cpu_usage_us":172,"net_usage_words":0},"elapsed":172,"net_usage":0,"scheduled":true,"action_traces":[{"action_ordinal":1,"creator_action_ordinal":0,"closest_unnotified_ancestor_action_ordinal":0,"receipt":{"receiver":"eosio","act_digest":"cfd5ae30263ee0c3873c6f6895fb34d6b2898f55a16afd4fc4c41044a069b60f","global_sequence":111,"recv_sequence":107,"auth_sequence":[["eosio",108]],"code_sequence":1,"abi_sequence":1},"receiver":"eosio","act":{"account":"eosio","name":"newaccount","authorization":[{"actor":"eosio","permission":"active"}],"data":{"creator":"eosio","name":"sample","owner":{"threshold":1,"keys":[{"key":"EOS6MRyAjQq8ud7hVNYcfnVPJqcVpscN5So8BhtHuGYqET5GDW5CV","weight":1}],"accounts":[],"waits":[]},"active":{"threshold":1,"keys":[{"key":"EOS6MRyAjQq8ud7hVNYcfnVPJqcVpscN5So8BhtHuGYqET5GDW5CV","weight":1}],"accounts":[],"waits":[]}},"hex_data":"0000000000ea305500000000a858a5c101000000010002c0ded2bc1f1305fb0faac5e6c03ee3a1924234985427b6167ca569d13df435cf0100000001000000010002c0ded2bc1f1305fb0faac5e6c03ee3a1924234985427b6167ca569d13df435cf01000000"},"context_free":false,"elapsed":111,"console":"","trx_id":"93778ab0d07ceab684323c3f7ab053923266318254ab5d583f5a699ef1d7b585","block_num":77,"block_time":"2022-06-25T17:38:34.500","producer_block_id":null,"account_ram_deltas":[{"account":"sample","delta":2724}],"except":null,"error_code":null,"return_value_hex_data":""}],"account_ram_delta":{"account":"eosio","delta":-424},"except":null,"error_code":null}

  • debug level logging for transaction_trace_success & transaction_trace_failure logger
  • Same logging that was available for incoming transaction traces now also available for scheduled transaction traces.

Resolves #292
Resolves #293
Resolves #294

@heifner heifner added the OCI OCI working this issue... label Jun 25, 2022
@heifner heifner merged commit 85b9825 into main Jun 29, 2022
@heifner heifner deleted the additional-logging branch June 29, 2022 12:17
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
OCI OCI working this issue...
Projects
None yet
2 participants