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

Cut down on the amount of INFO-level logging #1607

Merged
merged 14 commits into from
Nov 8, 2022

Conversation

michaelbaamonde
Copy link
Contributor

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-mode with master results 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:

Worker[0] finished executing tasks ['delete-index'] in 0.107148 seconds
Worker[0] finished executing tasks ['create-index'] in 0.677319 seconds
Worker[0] finished executing tasks ['check-cluster-health'] in 0.011707 seconds
Worker[1] finished executing tasks ['index-append'] in 0.143370 seconds

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 INFO as opposed to DEBUG, 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 DEBUG as 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.

esrally/utils/git.py Outdated Show resolved Hide resolved
Copy link
Member

@inqueue inqueue left a comment

Choose a reason for hiding this comment

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

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).

image

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.1607

I'm good with what is removed, and good with this PR. LGTM!

Footnotes

  1. https://github.com/elastic/rally-tracks/pull/340

@michaelbaamonde michaelbaamonde merged commit 847b9b3 into elastic:master Nov 8, 2022
@pquentin pquentin added the :misc Changes that don't affect users directly: linter fixes, test improvements, etc. label Mar 2, 2023
@pquentin pquentin added this to the 2.7.1 milestone Mar 2, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
:misc Changes that don't affect users directly: linter fixes, test improvements, etc. tech debt
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants