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

Fix the log duplication issue for --log-file. #65

Merged
merged 1 commit into from
May 28, 2019

Conversation

yuwenma
Copy link

@yuwenma yuwenma commented May 18, 2019

What this PR does / why we need it:
We noticed that when a service/app is using the --log-file flag, there could be a severe performance regression due to the duplicated logs generated in log severity cascading (e.g. Error level Log is also tracked and stored in Warning and Info level log). This not only generates duplicate logs in the destination log-file, but also slow down the log-file flush. This PR is specifically adjusting the klog behavior when --log-file is used, and not aimed at providing a generic solution about the log severity cascading or other klog improvements.

For more context, see kubernetes/kubernetes#77904

Which issue(s) this PR fixes (optional, in fixes #<issue number>(, fixes #<issue_number>, ...) format, will close the issue(s) when PR gets merged):
Fixes #53

Special notes for your reviewer:

Please confirm that if this PR changes any image versions, then that's the sole change this PR makes.

Release note:

NONE

@k8s-ci-robot k8s-ci-robot added cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. size/L Denotes a PR that changes 100-499 lines, ignoring generated files. labels May 18, 2019
@yuwenma
Copy link
Author

yuwenma commented May 18, 2019

/assign @dims @tallclair
/cc @mborsz @wojtek-t

@yuwenma
Copy link
Author

yuwenma commented May 18, 2019

/cc @adrianlzt @DirectXMan12 (Thanks Adrián for filing the issue) 😃

@dims
Copy link
Member

dims commented May 18, 2019

/assign @munnerz

klog.go Outdated Show resolved Hide resolved
klog.go Outdated Show resolved Hide resolved
klog.go Outdated Show resolved Hide resolved
klog.go Outdated
// no longer tracks logs separately due to their severity level, but rather
// only write to the info logfile which later on will be flushed to the
// dedicated log_file.
func (l *loggingT) writeToDifferentSeverity(s severity, data []byte) {
Copy link
Member

Choose a reason for hiding this comment

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

I recommend factoring this a bit differently:

Make the function:

func (l *logging.T) writeLogData(s severity, data byte) {
  if l.shouldLogToStderr(s) { ... }
  if l.logFile != "" {
    ... // handle single-file mode
  } else {
    ... // handle multi-file mode
  }
}

Copy link
Author

Choose a reason for hiding this comment

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

Sure. but it will have many duplicate code. Is that okay?

Copy link
Member

Choose a reason for hiding this comment

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

I don't think it will have too much. I'm worried that the current approach of defaulting to the info log is too error-prone, and folding in the log-to-stderr functionality will actually deduplicate code (and fix a bug) in the fatal log path.

Copy link
Author

@yuwenma yuwenma left a comment

Choose a reason for hiding this comment

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

Updated. PTAL

klog.go Outdated Show resolved Hide resolved
klog.go Outdated
// dedicated log_file.
func (l *loggingT) writeLogData(s severity, data []byte) {
if l.logFile != "" { // single-file mode
if l.file[infoLog] == nil {
Copy link
Member

Choose a reason for hiding this comment

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

Can we use a dedicated buffer for this, rather than repurposing infoLog?

Copy link
Author

Choose a reason for hiding this comment

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

Agree we shouldn't repurpose infolog. But I also have some concerns to use a dedicated buffer:
I want to patch a quick/safe fix to the log duplicate problem and catch the 1.15 release. Defining a new buffer results in much more complicated changes and it should have longer testing time before imported to kubernetes/kubernetes.

Updated the code with a dedicated buffer for single mode. Let me know if that's the reasonable approach and is safe to go in. If not, I'd prefer a quick fix that touches the least code.

klog.go Outdated Show resolved Hide resolved
klog.go Outdated Show resolved Hide resolved
klog.go Outdated Show resolved Hide resolved
@dims
Copy link
Member

dims commented May 22, 2019

@tallclair happy with this?

@tallclair
Copy link
Member

/lgtm

@k8s-ci-robot k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label May 28, 2019
@k8s-ci-robot
Copy link

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: tallclair, yuwenma

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
approved Indicates a PR has been approved by an approver from all required OWNERS files. cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. lgtm "Looks good to me", indicates that a PR is ready to be merged. size/L Denotes a PR that changes 100-499 lines, ignoring generated files.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Repeated trace in log file with error
5 participants