Cut down on the amount of INFO-level logging#1607
Merged
Merged
Conversation
added 12 commits
November 2, 2022 16:24
We'll have already logged that a task was finished executing from within the `Driver` class.
This seems unnecessary.
b-deam
reviewed
Nov 3, 2022
This reverts commit 15dfce8.
inqueue
approved these changes
Nov 3, 2022
Member
inqueue
left a comment
There was a problem hiding this comment.
Thank you for this PR. I tested it against a new track I'm developing1 and so far so good. With timestamps removed and "zeroing" all Actor thread/process IDs, I see a significant improvement (though this analysis is not without flaws).
The number of logged lines with this PR dropped by over half:
grape:logs $ wc -l rally.log rally.log.1607
432 rally.log
210 rally.log.1607I'm good with what is removed, and good with this PR. LGTM!
Footnotes
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.

This PR moves many INFO-level logging statements to DEBUG. These primarily concern the actor system, ES client instantiation, and relatively low-level load-driver operations.
On my machine, running
esrally race --track=geonames --test-modewithmasterresults in 2,295 lines of logs. This PR cuts it down to 650, with no (IMO) substantial loss of actionable information in the default case.This commit in particular makes it easier to follow what's going on during task execution. We'll now have a single line logged each time a worker finishes executing a task, including the time it took to complete the task. For example:
And so on. Previously, this was scattered across multiple lines and difficult to parse.
All that said, I can see case-by-case arguments for some of these remaining at
INFOas opposed toDEBUG, and I'm happy to adjust if there are places where I've been too ruthless. :) Git operations, for example, may be worth logging by default.I'd suggest that reviewers give this a try locally with a few different tracks and see how it strikes them. The goal is to cut down on noise while preserving usefulness, and provide
DEBUGas a fallback for trickier cases that require lower-level inspection. I've pinged the team broadly since this affects everyone to one degree or another.