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.

Sign up for GitHub

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

Summarize compact snapshot logs to reduce noise #467

Merged
merged 7 commits into from
Nov 9, 2023
Merged

Summarize compact snapshot logs to reduce noise #467

Show file tree
Hide file tree
Changes from 5 commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
7b95308
Move compact snapshot logs from info to verbose level
seanlinsley Oct 24, 2023
6637bfd
log summary of compact snapshots submitted every minute
seanlinsley Oct 25, 2023
61dc1e2
track stats per-server, shorten log message
seanlinsley Oct 26, 2023
5f63009
fmt
seanlinsley Oct 26, 2023
707c0f7
CI: lint code before running tests to shorten feedback cycle
seanlinsley Oct 26, 2023
70be798
review updates
seanlinsley Nov 8, 2023
651c191
align log events to even minutes
seanlinsley Nov 9, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 5 additions & 5 deletions .github/workflows/ci.yml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -33,13 +33,13 @@ jobs:
with:
submodules: true

- name: Runs tests
- name: Lint
run: |
test $(go fmt ./... | wc -l) -eq 0

- name: Run tests
run: |
make build OUTFILE=pganalyze-collector-linux-amd64
make test
DOCKER_BUILDKIT=1 make integration_test
shellcheck contrib/install.sh

- name: Lint
run: |
test $(go fmt ./... | wc -l) -eq 0
25 changes: 24 additions & 1 deletion output/compact.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,7 @@ import (
"io"
"net/http"
"net/url"
"sort"
"strings"
"time"

Expand Down Expand Up @@ -137,7 +138,29 @@ func submitCompactSnapshot(ctx context.Context, server *state.Server, collection
if len(msg) > 0 && collectionOpts.TestRun {
logger.PrintInfo(" %s", msg)
} else if !quiet {
logger.PrintInfo("Submitted compact %s snapshot successfully", kind)
logger.PrintVerbose("Submitted compact %s snapshot successfully", kind)
if server.CompactLogTime.IsZero() {
server.CompactLogTime = time.Now()
server.CompactLogStats = make(map[string]uint8)
} else if time.Now().Sub(server.CompactLogTime) > time.Minute {
server.CompactLogTime = time.Now()
Copy link
Contributor

Choose a reason for hiding this comment

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

Not a big deal, but since this is part of resetting the log stats state, it feels like it belongs together with resetting the map below.

Copy link
Member Author

Choose a reason for hiding this comment

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

I intentionally didn't do that, to avoid clock skew from the time it takes to build the log message. But it should never take a long time and this code path is non-critical so I'll move it down to improve readability.

Copy link
Member Author

Choose a reason for hiding this comment

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

🤔 a way to avoid the timestamp changing over time would be to truncate it to the nearest even minute, instead of simply using time.Now()

Copy link
Member Author

@seanlinsley seanlinsley Nov 8, 2023 •
edited
Loading

Choose a reason for hiding this comment

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

This would ensure we always print the log at an even minute. Though it does mean that when initially starting up the collector you may have to wait was long as 1m59s before anything is logged.

Or is it 1m30s? I'm not 100% sure what Truncate does

@@ -140,7 +140,7 @@ func submitCompactSnapshot(ctx context.Context, server *state.Server, collection
        } else if !quiet {
                logger.PrintVerbose("Submitted compact %s snapshot successfully", kind)
                if server.CompactLogTime.IsZero() {
-                       server.CompactLogTime = time.Now()
+                       server.CompactLogTime = time.Now().Truncate(time.Minute)
                        server.CompactLogStats = make(map[string]uint8)
                } else if time.Now().Sub(server.CompactLogTime) > time.Minute {
                        var keys []string
@@ -158,7 +158,7 @@ func submitCompactSnapshot(ctx context.Context, server *state.Server, collection
                        if len(details) > 0 {
                                logger.PrintInfo("Compact snapshots submitted: " + details)
                        }
-                       server.CompactLogTime = time.Now()
+                       server.CompactLogTime = time.Now().Truncate(time.Minute)
                        server.CompactLogStats = make(map[string]uint8)

Copy link
Member Author

Choose a reason for hiding this comment

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

Example output:

./pganalyze-collector
2023/11/08 15:50:00 I [server1] Compact snapshots submitted: 5 activity
2023/11/08 15:50:00 I [server1] Submitted snapshot successfully
2023/11/08 15:51:00 I [server1] Compact snapshots submitted: 5 activity
2023/11/08 15:52:00 I [server1] Compact snapshots submitted: 5 activity
2023/11/08 15:53:00 I [server1] Compact snapshots submitted: 5 activity, 1 logs
2023/11/08 15:54:00 I [server1] Compact snapshots submitted: 5 activity, 1 logs
2023/11/08 15:55:00 I [server1] Compact snapshots submitted: 5 activity

Copy link
Member Author

Choose a reason for hiding this comment

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

I went ahead and added this change; it's nice that the logs show up reliably at the same time every minute.

var keys []string
for k := range server.CompactLogStats {
keys = append(keys, k)
}
sort.Strings(keys)
details := ""
for i, kind := range keys {
details += fmt.Sprintf("%d %s", server.CompactLogStats[kind], kind)
if i < len(keys)-1 {
details += ", "
}
}
logger.PrintInfo("Compact snapshots submitted: " + details)
Copy link
Contributor

Choose a reason for hiding this comment

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

Can we ever get here with an empty CompactLogStats map? If so, that would print a weird
Compact snapshots submitted: message.

Copy link
Member Author

Choose a reason for hiding this comment

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

AFAIK that would only happen if all snapshots failed, which would be logged as errors separately. I'll go ahead and add a presence check here.

server.CompactLogStats = make(map[string]uint8)
} else {
server.CompactLogStats[kind] = server.CompactLogStats[kind] + 1
}
}

return nil
Expand Down
4 changes: 4 additions & 0 deletions state/state.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -286,6 +286,10 @@ type Server struct {
// differences (see https://groups.google.com/g/golang-nuts/c/eIqkhXh9PLg),
// as we access this in high frequency log-related code paths.
LogIgnoreFlags uint32

// State to track compact snapshot submissions, and log them routinely
CompactLogStats map[string]uint8
CompactLogTime time.Time
}

func MakeServer(config config.ServerConfig) *Server {
Expand Down
Loading