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

'No sync target' logging improvements #4853

Merged
merged 11 commits into from
Jan 16, 2023

Conversation

mark-terry
Copy link
Contributor

Signed-off-by: mark-terry mark.terry@consensys.net

PR description

"No sync target, checking current peers for usefulness" logging made less spammy, with improved detail.

  • DEBUG level log message rate reduced to once every 15 seconds, with pivot block target added to logging message.
  • INFO level log message added at 2 minute intervals to provide user feedback while import is paused

Fixed Issue(s)

Addresses #4794

Documentation

  • I thought about documentation and added the doc-change-required label to this PR if
    updates are required.

Changelog

@mark-terry mark-terry added TeamRevenant GH issues worked on by Revenant Team logging labels Dec 21, 2022
@mark-terry mark-terry self-assigned this Dec 21, 2022
"No sync target, checking current peers for usefulness: {}",
ethContext.getEthPeers().peerCount());
if (maybeBestPeer.isEmpty()) {
if (shouldLogDebug.compareAndSet(true, false)) {
Copy link
Contributor

Choose a reason for hiding this comment

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

I know log throttling is done in at least one other place:

private void logForkchoiceUpdatedCall(
final BiConsumer<EngineStatus, EngineForkchoiceUpdatedParameter> logAtLevel,
final EngineStatus status,
final EngineForkchoiceUpdatedParameter forkChoice) {
// cheaply limit the noise of fcU during consensus client syncing to once a minute:
if (lastFcuInfoLog + ENGINE_API_LOGGING_THRESHOLD < System.currentTimeMillis()) {
lastFcuInfoLog = System.currentTimeMillis();
logAtLevel.accept(status, forkChoice);
}
}

Would be good to have a single way to do it in a logging util. I can think of several places we could use it.

Copy link
Contributor

Choose a reason for hiding this comment

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

Has the usage of a BurstFilter been analyzed for this use case?

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 @fab-10 may have looked into that or some similar feature of log4j. I agree that would be a neater approach and can't see a reason why we wouldn't want to use it for all logs

Copy link
Contributor

Choose a reason for hiding this comment

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

I haven't yet looked at how to throttle this kind of logs, what I did was about summarizing the progress of the sync every tot seconds, this seems different, and I agree that something like the BurstFilter make sense here, since it could also be easily configurable.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

From my investigation, BurstFilter doesn't appear to be specific enough to address this use case. My understanding is that it throttles the entire log level, whereas this functionality allows a specific (potentially spammy) log message to be throttled. Is my understanding of BurstFilter correct, or is it able to be targeted to a class/method level?

A logging improvement via log4j configuration would likely also require the user to configure it.

Copy link
Contributor

@fab-10 fab-10 left a comment

Choose a reason for hiding this comment

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

Change request to avoid creating a thread on very log call. But if possible evaluate the usage of a BurstFilter for throttling logs

@mark-terry
Copy link
Contributor Author

Will review BurstFilter. 👍

Signed-off-by: mark-terry <mark.terry@consensys.net>
Signed-off-by: mark-terry <mark.terry@consensys.net>
Signed-off-by: mark-terry <mark.terry@consensys.net>
@mark-terry mark-terry force-pushed the fast_sync_logging_improvement branch from 874cfd8 to 57ec20f Compare January 11, 2023 11:23
Signed-off-by: mark-terry <mark.terry@consensys.net>
@mark-terry mark-terry requested a review from fab-10 January 11, 2023 15:06
@mark-terry mark-terry requested review from fab-10, siladu and diega January 15, 2023 12:54
@mark-terry mark-terry merged commit 8a886c8 into hyperledger:main Jan 16, 2023
@mark-terry mark-terry deleted the fast_sync_logging_improvement branch January 16, 2023 13:14
elenduuche pushed a commit to elenduuche/besu that referenced this pull request Aug 16, 2023
Signed-off-by: mark-terry <mark.terry@consensys.net>
eum602 pushed a commit to lacchain/besu that referenced this pull request Nov 3, 2023
Signed-off-by: mark-terry <mark.terry@consensys.net>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
logging TeamRevenant GH issues worked on by Revenant Team
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Improve "No sync target, checking current peers for usefulness" logging
4 participants