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

Add log de-duplication support to glog #3

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

Conversation

stieg
Copy link

@stieg stieg commented Nov 28, 2022

Adds de-duplication support to glog so that we can eliminate noisy log sources in code. Will only de-duplicate consecutive lines that are noisy.

Includes a flag logdedupeafter that will begin de-duplicating after N consecutive log statements. Defaults to 0 (disabled).

Test output to demonstrate operation:

=== RUN   TestDedupe
=== RUN   TestDedupe/Dedupe_disabled_(0)
=== RUN   TestDedupe/Dedupe_after_1
=== RUN   TestDedupe/Dedupe_after_2
=== RUN   TestDedupe/Dedupe_after_3
=== RUN   TestDedupe/Dedupe_after_4_(none_expected)
=== RUN   TestDedupe/Dedupe_after_5_(none_expected)
--- PASS: TestDedupe (0.00s)
    --- PASS: TestDedupe/Dedupe_disabled_(0) (0.00s)
        glog_test.go:456: I1128 10:36:08.352539    1234 glog_test.go:449] test
            I1128 10:36:08.352550    1234 glog_test.go:449] test
            I1128 10:36:08.352566    1234 glog_test.go:449] test
            I1128 10:36:08.352571    1234 glog_test.go:449] test
            I1128 10:36:08.352579    1234 glog_test.go:451] done

    --- PASS: TestDedupe/Dedupe_after_1 (0.00s)
        glog_test.go:456: I1128 10:36:08.352768    1234 glog_test.go:449] test
            I1128 10:36:08.352796    1234 glog_test.go:449] ...statement repeated 3 time(s)...
            I1128 10:36:08.352830    1234 glog_test.go:451] done

    --- PASS: TestDedupe/Dedupe_after_2 (0.00s)
        glog_test.go:456: I1128 10:36:08.352967    1234 glog_test.go:449] test
            I1128 10:36:08.352975    1234 glog_test.go:449] test
            I1128 10:36:08.352989    1234 glog_test.go:449] ...statement repeated 2 time(s)...
            I1128 10:36:08.353013    1234 glog_test.go:451] done

    --- PASS: TestDedupe/Dedupe_after_3 (0.00s)
        glog_test.go:456: I1128 10:36:08.353148    1234 glog_test.go:449] test
            I1128 10:36:08.353160    1234 glog_test.go:449] test
            I1128 10:36:08.353166    1234 glog_test.go:449] test
            I1128 10:36:08.353176    1234 glog_test.go:449] ...statement repeated 1 time(s)...
            I1128 10:36:08.353179    1234 glog_test.go:451] done

    --- PASS: TestDedupe/Dedupe_after_4_(none_expected) (0.00s)
        glog_test.go:456: I1128 10:36:08.353307    1234 glog_test.go:449] test
            I1128 10:36:08.353324    1234 glog_test.go:449] test
            I1128 10:36:08.353331    1234 glog_test.go:449] test
            I1128 10:36:08.353336    1234 glog_test.go:449] test
            I1128 10:36:08.353346    1234 glog_test.go:451] done

    --- PASS: TestDedupe/Dedupe_after_5_(none_expected) (0.00s)
        glog_test.go:456: I1128 10:36:08.353492    1234 glog_test.go:449] test
            I1128 10:36:08.353502    1234 glog_test.go:449] test
            I1128 10:36:08.353514    1234 glog_test.go:449] test
            I1128 10:36:08.353526    1234 glog_test.go:449] test
            I1128 10:36:08.353535    1234 glog_test.go:451] done

glog.go Outdated
// message. Method will return true if we do, false otherwise. Method is also
// responsible for noticing a different logging statement is being called and
// adding any relevant de-duplication log information about our previously
// de-dupled log statements. As such IT MUST BE CALLED AS PART OF EVERY LOG

Choose a reason for hiding this comment

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

Suggested change
// de-dupled log statements. As such IT MUST BE CALLED AS PART OF EVERY LOG
// de-duped log statements. As such IT MUST BE CALLED AS PART OF EVERY LOG

Copy link
Author

Choose a reason for hiding this comment

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

<3 my spelling :)

// function performant. Thus we must not use a defer unlock here.
l.lastStatementMu.Lock()

if l.lastStatementCaller.pc == c.pc {

Choose a reason for hiding this comment

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

When do we reset the lastStatementCount? If the program counter doesn't change, we will never log the line again? I was sort of the under the impression we would want to reset this after a timeout

Choose a reason for hiding this comment

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

I'm also not positive I understand the structs/fields you have here. There is only a single lastStatementCount field in loggingT, which gets overwritten every time we change program counter. I'd expect there to be a something like a map of program counter to this state. so like

type loggingT struct {
   ...
   logCounts map[uintptr]uint // maps program counter to log count
}

It seems like the way this works, the deduping will only happen if we hit the same log line (determined by program counter) sequentially. If there is another log line interspersed with the spammy log, no deduping will happen.

Copy link
Author

Choose a reason for hiding this comment

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

When do we reset the lastStatementCount?

See line 617 for where that assignment happens (we assign a new caller which includes the pc value).

It seems like the way this works, the deduping will only happen if we hit the same log line (determined by program counter) sequentially

This is precisely how it works. It will de-dupe multiple consecutive log statements. So this helps when one single message is spamming the log file. To do more is a much more complicated lift as you have to define when a log is too noisy and track independent behaviors for each log line (which can get hairy as you might imagine). This in its current form is simple and fast and effective without being too big of a change to an otherwise critical system.

glog.go Outdated
Comment on lines 576 to 577
// Unsure if needed, but since this was in code previously I am carrying it
// forward here to avoid any surprise regressions.

Choose a reason for hiding this comment

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

I would include the original comment that was on the old line

// not a real line number, but acceptable to someDigits

Adds deduplication support to glog so that we can eliminate noisy log sources in
code. Will only deduplicate consecutive lines that are noisy.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants