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.

Sign up for GitHub

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

basic-authorship: debug level is now less spammy #6768

Merged
merged 3 commits into from
Dec 5, 2024
Merged

basic-authorship: debug level is now less spammy #6768

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
0ec7e08
basic-authorship: debug level is now less spammy
michalkucharczyk Dec 5, 2024
1618880
Update from michalkucharczyk running command 'prdoc --bump major --au…
actions-user Dec 5, 2024
db11394
Update substrate/client/basic-authorship/src/basic_authorship.rs
michalkucharczyk Dec 5, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
14 changes: 14 additions & 0 deletions prdoc/pr_6768.prdoc
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,14 @@
title: '`basic-authorship`: debug level is now less spammy'
doc:
- audience: Node Dev
description: |-
The `debug` level in `sc-basic-authorship` is now less spammy. Previously it was outputing logs per individual transactions. It made quite hard to follow the logs (and also generates unneeded traffic in grafana).

Now debug level only show some internal details, without spamming output with per-transaction logs. They were moved to `trace` level.

I also added the `EndProposingReason` to the summary INFO message. This allows us to know what was the block limit (which is very useful for debugging).
crates:
- name: sc-basic-authorship
bump: major
- name: sc-proposer-metrics
bump: major
12 changes: 7 additions & 5 deletions substrate/client/basic-authorship/src/basic_authorship.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -483,7 +483,7 @@ where
match sc_block_builder::BlockBuilder::push(block_builder, pending_tx_data) {
Ok(()) => {
transaction_pushed = true;
debug!(target: LOG_TARGET, "[{:?}] Pushed to the block.", pending_tx_hash);
trace!(target: LOG_TARGET, "[{:?}] Pushed to the block.", pending_tx_hash);
},
Err(ApplyExtrinsicFailed(Validity(e))) if e.exhausted_resources() => {
pending_iterator.report_invalid(&pending_tx);
Expand Down Expand Up @@ -565,20 +565,22 @@ where

if log::log_enabled!(log::Level::Info) {
info!(
"🎁 Prepared block for proposing at {} ({} ms) [hash: {:?}; parent_hash: {}; extrinsics_count: {}",
"🎁 Prepared block for proposing at {} ({} ms) hash: {:?}; parent_hash: {}; end: {:?}; extrinsics_count: {};",
michalkucharczyk marked this conversation as resolved.
Show resolved Hide resolved
block.header().number(),
block_took.as_millis(),
<Block as BlockT>::Hash::from(block.header().hash()),
block.header().parent_hash(),
end_reason,
Copy link
Member

@bkchr bkchr Dec 5, 2024 •
edited
Loading

Choose a reason for hiding this comment

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

Suggested change
"🎁 Prepared block for proposing at {} ({} ms) hash: {:?}; parent_hash: {}; end: {:?}; extrinsics_count: {};",
block.header().number(),
block_took.as_millis(),
<Block as BlockT>::Hash::from(block.header().hash()),
block.header().parent_hash(),
end_reason,
"🎁 Prepared block for proposing at {} ({} ms) hash: {:?}; parent_hash: {}; extrinsics_count: {};",
block.header().number(),
block_took.as_millis(),
<Block as BlockT>::Hash::from(block.header().hash()),
block.header().parent_hash(),

No need to log this in info.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I need it here, this is why I added it. I need to know why block builder is hitting limits. And we may have it "for free" in this line.

I am now confused, it is OK to merge it with end reason or not?

Copy link
Member

Choose a reason for hiding this comment

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

Why do you need it there? You could just enable trace logging.

Copy link
Member

Choose a reason for hiding this comment

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

Also we have metrics for this.

Copy link
Contributor

Choose a reason for hiding this comment

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

I think its useful to have, with tracing it will spam all tx again.

Copy link
Contributor Author

@michalkucharczyk michalkucharczyk Dec 5, 2024 •
edited
Loading

Choose a reason for hiding this comment

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

I don't want to enable trace, because it is way too spammy. With 7k txs in block it may affect the block time building. And for sure it does not help with collecting logs in grafana/loki - it sometimes breaks with too many logs.

I can add another "if branch" here for debug level, but I think it will be more confusing when reasoning about what to enable.

Copy link
Member

Choose a reason for hiding this comment

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

Adding this because you want to debug one network doesn't make that much sense IMO. Then print the end reason in debug. For normal operators this is not that useful.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

It is not one network, instead of having important info in log I always need to restart the node whiat is a cost (time). having this log allows very quick assessment of what is happening in block builder.

and logs are not only for operator. after all why does operator need this hash?

I would not propose it if I could live w/o this. And finally @skunert says he finds it useful too.

extrinsics.len()
)
} else if log::log_enabled!(log::Level::Debug) {
debug!(
"🎁 Prepared block for proposing at {} ({} ms) [hash: {:?}; parent_hash: {}; {extrinsics_summary}",
} else if log::log_enabled!(log::Level::Trace) {
trace!(
"🎁 Prepared block for proposing at {} ({} ms) hash: {:?}; parent_hash: {}; end: {:?}; {extrinsics_summary}",
block.header().number(),
block_took.as_millis(),
<Block as BlockT>::Hash::from(block.header().hash()),
block.header().parent_hash(),
end_reason
);
}

Expand Down
2 changes: 1 addition & 1 deletion substrate/client/proposer-metrics/src/lib.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -44,7 +44,7 @@ impl MetricsLink {
}

/// The reason why proposing a block ended.
#[derive(Clone, Copy, PartialEq, Eq)]
#[derive(Clone, Copy, PartialEq, Eq, Debug)]
pub enum EndProposingReason {
NoMoreTransactions,
HitDeadline,
Expand Down
Loading