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

grpclog: change logger to avoid Printf when the logger is io.Discard #7471

Open
wants to merge 1 commit into
base: master
Choose a base branch
from

Conversation

rob05c
Copy link

@rob05c rob05c commented Aug 1, 2024

Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of io.MultiWriter(io.Discard, io.Discard), which is necessary to detect all levels being discarded.

This is a significant performance improvement for disabled logs, see #7463 for details.

Notes:

  • This is similar to how the std does it, see log.go
  • I was hoping to use the std log.Printf itself, but I don't think that's possible, because the JSON option needs to Printf and then escape the result after interpolating, which I don't think is possible with what's exposed by the std (possibly sans some overly complex io.Writer interceptors).
  • It could use log.Printf for the non-JSON, but there's not much point if we can't use it for the JSON, and it would incur an unnecessary atomic call.
  • The constructor io.Discard logic could be made faster (e.g. with more nested if's), and could do smarter things around the discard/multiwriter. I wrote it this way for readability, and because I don't think the performance is significant. But I'm happy to change it.

Fixes #7463

RELEASE NOTES:

  • grpclog: Avoid expensive printf calls for io.Discard loggers.

Copy link

linux-foundation-easycla bot commented Aug 1, 2024

CLA Signed

The committers listed above are authorized under a signed CLA.

  • ✅ login: rob05c / name: Robert O Butts (2bf7f34)

Copy link

codecov bot commented Aug 1, 2024

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 81.83%. Comparing base (31ffeee) to head (2bf7f34).
Report is 71 commits behind head on master.

Additional details and impacted files
@@            Coverage Diff             @@
##           master    #7471      +/-   ##
==========================================
+ Coverage   81.73%   81.83%   +0.10%     
==========================================
  Files         361      361              
  Lines       27817    27833      +16     
==========================================
+ Hits        22735    22776      +41     
+ Misses       3871     3850      -21     
+ Partials     1211     1207       -4     
Files with missing lines Coverage Δ
grpclog/internal/loggerv2.go 100.00% <100.00%> (+48.00%) ⬆️

... and 14 files with indirect coverage changes

@rob05c rob05c force-pushed the rob05c/nil-loggers branch 6 times, most recently from 463f9b1 to ae6fd53 Compare August 5, 2024 17:40
@rob05c rob05c force-pushed the rob05c/nil-loggers branch 2 times, most recently from bf693df to bd9603c Compare August 5, 2024 18:15
@purnesh42H purnesh42H self-assigned this Aug 6, 2024
grpclog/loggerv2.go Outdated Show resolved Hide resolved
grpclog/loggerv2_test.go Outdated Show resolved Hide resolved
grpclog/loggerv2_test.go Outdated Show resolved Hide resolved
grpclog/loggerv2.go Outdated Show resolved Hide resolved
grpclog/loggerv2.go Outdated Show resolved Hide resolved
@rob05c rob05c force-pushed the rob05c/nil-loggers branch 5 times, most recently from 2242738 to 1184eb7 Compare August 13, 2024 12:28
@rob05c rob05c requested a review from purnesh42H August 13, 2024 13:04
@purnesh42H
Copy link
Contributor

Adding @dfawley as 2nd reviewer

@purnesh42H purnesh42H modified the milestones: 1.67 Release, 1.68 Release Sep 10, 2024
@rob05c rob05c force-pushed the rob05c/nil-loggers branch 4 times, most recently from 0da4704 to 7bb19d4 Compare September 15, 2024 15:46
Changes the logger to not call Printf when the logger is io.Discard.

Also changes the logger constructor to use io.Discard instead of
io.MultiWriter(io.Discard, io.Discard), which is necessary to
detect all levels being discarded.

Fixes grpc#7463
@rob05c
Copy link
Author

rob05c commented Sep 15, 2024

Ok, I think I addressed all the comments again. Let me know if I missed anything.

Also, the PR started failing a new Github check for RELEASE NOTES in the description, so I attempted to add it like I see in other PRs. I'm happy to change it if it isn't right, just let me know

Copy link
Contributor

@purnesh42H purnesh42H left a comment

Choose a reason for hiding this comment

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

lgtm

@purnesh42H purnesh42H modified the milestones: 1.68 Release, 1.69 Release Oct 16, 2024
@rob05c
Copy link
Author

rob05c commented Oct 21, 2024

Is there anything else I need to do for this to be merged?

@purnesh42H
Copy link
Contributor

Doug is reviewing it. Nothing is needed from you right now.

@dfawley
Copy link
Member

dfawley commented Oct 22, 2024

Is there anything else I need to do for this to be merged?

Apologies; I have a lot on my plate right now, but will try to get to this in the next week or so.

Copy link
Member

@dfawley dfawley left a comment

Choose a reason for hiding this comment

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

Thanks for the PR and sorry again for the delay.

func (g *loggerT) output(severity int, s string) {
// printFunc prints the output of fn to the logger of the given severity.
// If the logger at given severity is io.Discard, fn is not called.
func (g *loggerT) printFunc(severity int, fn func() string) {
Copy link
Member

Choose a reason for hiding this comment

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

The closure here seems unfortunate, and I think this approach has performance impacts for non-Discard use cases (creating the closure and the call to concatenate the strings inside if !g.jsonFormat).

Can we keep output and add an outputf that duplicates the io.Discard check, and avoids the closure and different formatting?

Comment on lines +226 to +234
warnLogW := io.Discard
if warningW != io.Discard || infoW != io.Discard {
warnLogW = io.MultiWriter(infoW, warningW)
}

errLogW := io.Discard
if errorW != io.Discard || warningW != io.Discard || infoW != io.Discard {
errLogW = io.MultiWriter(infoW, warningW, errorW)
}
Copy link
Member

Choose a reason for hiding this comment

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

I think we could optimize this a bit, and make it easier to read as well?

// Returns a combined logger for both higher & lower severity logs, or higher only if lower is io.Discard.
func combineLoggers(lower, higher io.Writer) io.Writer {
	if lower == io.Discard || higher == io.Discard {
		return higher
	}
	return io.MultiWriter(lower, higher)		
}

func NewLoggerV2(..) {
	// ...

	// Just overwrite instead of creating new locals with different names:
	warningW = combineLoggers(infoW, warningW)
	errorW = combineLoggers(warningW, errorW)
}

This ends up with 2 nested multiwriters if you have 3 different loggers, but that's probably fairly uncommon, and would be no worse than the behavior this PR adds of creating a multiwriter for (warningW, io.Discard) if infoW is io.Discard.

@dfawley dfawley assigned rob05c and unassigned dfawley Oct 28, 2024
@dfawley dfawley added Status: Requires Reporter Clarification Type: Performance Performance improvements (CPU, network, memory, etc) and removed Type: Bug labels Oct 28, 2024
Copy link

github-actions bot commented Nov 3, 2024

This PR is labeled as requiring an update from the reporter, and no update has been received after 6 days. If no update is provided in the next 7 days, this issue will be automatically closed.

@github-actions github-actions bot added stale and removed stale labels Nov 3, 2024
@rob05c
Copy link
Author

rob05c commented Nov 4, 2024

This PR is labeled as requiring an update from the reporter, and no update has been received after 6 days. If no update is provided in the next 7 days, this issue will be automatically closed.

Sorry, I was on vacation last week. I'll try to address the comments sometime this week

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Status: Requires Reporter Clarification Type: Performance Performance improvements (CPU, network, memory, etc)
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Improve Logger Performance When Disabled
5 participants