Skip to content

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

Merged
michaelbaamonde merged 14 commits into
elastic:masterfrom
michaelbaamonde:logging-cleanup
Nov 8, 2022
Merged

Cut down on the amount of INFO-level logging#1607
michaelbaamonde merged 14 commits into
elastic:masterfrom
michaelbaamonde:logging-cleanup

Conversation

@michaelbaamonde
Copy link
Copy Markdown
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.

Comment thread esrally/utils/git.py Outdated
Copy link
Copy Markdown
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