// Copyright 2021 The LevelDB-Go and Pebble Authors. All rights reserved. Use // of this source code is governed by a BSD-style license that can be found in // the LICENSE file. package logs import ( "bytes" "fmt" "math" "os" "path/filepath" "regexp" "testing" "time" "github.com/cockroachdb/datadriven" "github.com/cockroachdb/errors" "github.com/stretchr/testify/require" ) const ( compactionStartLine23_1 = `I211215 14:26:56.012382 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [n5,pebble,s6] 1216510 [JOB 284925] compacting(default) L2 [442555] (4.2 M) + L3 [445853] (8.4 M)` compactionStartLine = `I211215 14:26:56.012382 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [n5,pebble,s6] 1216510 [JOB 284925] compacting(default) L2 [442555] (4.2MB) Score=1.01 + L3 [445853] (8.4MB) Score=0.99; OverlappingRatio: Single 8.03, Multi 25.05;` compactionEndLine23_1 = `I211215 14:26:56.318543 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1886 ⋮ [n5,pebble,s6] 1216554 [JOB 284925] compacted(default) L2 [442555] (4.2 M) + L3 [445853] (8.4 M) -> L3 [445883 445887] (13 M), in 0.3s, output rate 42 M/s` compactionEndLine = `I211215 14:26:56.318543 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1886 ⋮ [n5,pebble,s6] 1216554 [JOB 284925] compacted(default) L2 [442555] (4.2MB) Score=1.01 + L3 [445853] (8.4MB) Score=1.01 -> L3 [445883 445887] (13MB), in 0.3s, output rate 42MB/s` compactionMultiLevelStartLine = `I211215 14:26:56.318543 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1886 ⋮ [n5,pebble,s6] 1216554 [JOB 11] compacting(default) [multilevel] L2 [250858] (2.1MB) Score=1.09 + L3 [247985 247989 247848] (17MB) Score=0.99 + L4 [250817 250834 238396] (28MB) Score=1.00; OverlappingRatio: Single 3.77, Multi 1.46;` compactionMultiLevelEndline = `I211215 14:26:56.318543 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1886 ⋮ [n5,pebble,s6] 1216554 [JOB 11] compacted(default) [multilevel] L2 [250858] (2.1MB) Score=1.09 + L3 [247985 247989 247848] (17MB) Score=0.99 + L4 [250817 250834 238396] (28MB) Score=1.00 -> L4 [250859 250860 250861 250862 250863] (46MB), in 0.2s (0.2s total), output rate 185MB/s` flushStartLine = `I211213 16:23:48.903751 21136 3@vendor/github.com/cockroachdb/pebble/event.go:599 ⋮ [n9,pebble,s8] 24 [JOB 10] flushing 2 memtables to L0` flushEndLine23_1 = `I211213 16:23:49.134464 21136 3@vendor/github.com/cockroachdb/pebble/event.go:603 ⋮ [n9,pebble,s8] 26 [JOB 10] flushed 2 memtables to L0 [1535806] (1.3 M), in 0.2s, output rate 5.8 M/s` flushEndLine = `I211213 16:23:49.134464 21136 3@vendor/github.com/cockroachdb/pebble/event.go:603 ⋮ [n9,pebble,s8] 26 [JOB 10] flushed 2 memtables to L0 [1535806] (1.3MB), in 0.2s, output rate 5.8MB/s` readAmpLine23_1 = ` total 31766 188 G - 257 G 187 G 48 K 3.6 G 744 536 G 49 K 278 G 5 2.1` readAmpLine = `total | 32K 188GB 0B | - | 257GB | 48K 187GB | 744 3.6GB | 49K 536GB | 278GB | 5 2.1` compactionStartNoNodeStoreLine23_1 = `I211215 14:26:56.012382 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [n?,pebble,s?] 1216510 [JOB 284925] compacting(default) L2 [442555] (4.2 M) + L3 [445853] (8.4 M)` compactionStartNoNodeStoreLine = `I211215 14:26:56.012382 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [n?,pebble,s?] 1216510 [JOB 284925] compacting(default) L2 [442555] (4.2 M) + L3 [445853] (8.4MB)` flushStartNoNodeStoreLine = `I211213 16:23:48.903751 21136 3@vendor/github.com/cockroachdb/pebble/event.go:599 ⋮ [n?,pebble,s?] 24 [JOB 10] flushing 2 memtables to L0` flushableIngestionLine23_1 = `I230831 04:13:28.824280 3780 3@pebble/event.go:685 ⋮ [n10,s10,pebble] 365 [JOB 226] flushed 6 ingested flushables L0:024334 (1.5 K) + L0:024339 (1.0 K) + L0:024335 (1.9 K) + L0:024336 (1.1 K) + L0:024337 (1.1 K) + L0:024338 (12 K) in 0.0s (0.0s total), output rate 67 M/s` flushableIngestionLine = `I230831 04:13:28.824280 3780 3@pebble/event.go:685 ⋮ [n10,s10,pebble] 365 [JOB 226] flushed 6 ingested flushables L0:024334 (1.5KB) + L0:024339 (1.0KB) + L0:024335 (1.9KB) + L0:024336 (1.1KB) + L0:024337 (1.1KB) + L0:024338 (12KB) in 0.0s (0.0s total), output rate 67MB/s` ) func TestCompactionLogs_Regex(t *testing.T) { tcs := []struct { name string re *regexp.Regexp line string matches map[int]string }{ { name: "compaction start - sentinel", re: sentinelPattern, line: compactionStartLine23_1, matches: map[int]string{ sentinelPatternPrefixIdx: "compact", sentinelPatternSuffixIdx: "ing", }, }, { name: "compaction start - sentinel", re: sentinelPattern, line: compactionStartLine, matches: map[int]string{ sentinelPatternPrefixIdx: "compact", sentinelPatternSuffixIdx: "ing", }, }, { name: "compaction end - sentinel", re: sentinelPattern, line: compactionEndLine23_1, matches: map[int]string{ sentinelPatternPrefixIdx: "compact", sentinelPatternSuffixIdx: "ed", }, }, { name: "compaction end - sentinel", re: sentinelPattern, line: compactionEndLine, matches: map[int]string{ sentinelPatternPrefixIdx: "compact", sentinelPatternSuffixIdx: "ed", }, }, { name: "flush start - sentinel", re: sentinelPattern, line: flushStartLine, matches: map[int]string{ sentinelPatternPrefixIdx: "flush", sentinelPatternSuffixIdx: "ing", }, }, { name: "flush end - sentinel", re: sentinelPattern, line: flushEndLine23_1, matches: map[int]string{ sentinelPatternPrefixIdx: "flush", sentinelPatternSuffixIdx: "ed", }, }, { name: "flush end - sentinel", re: sentinelPattern, line: flushEndLine, matches: map[int]string{ sentinelPatternPrefixIdx: "flush", sentinelPatternSuffixIdx: "ed", }, }, { name: "compaction start", re: compactionPattern, line: compactionStartLine23_1, matches: map[int]string{ compactionPatternJobIdx: "284925", compactionPatternSuffixIdx: "ing", compactionPatternTypeIdx: "default", compactionPatternFromIdx: "2", compactionPatternToIdx: "3", compactionPatternLevels: "L2 [442555] (4.2 M) + L3 [445853] (8.4 M)", }, }, { name: "compaction start", re: compactionPattern, line: compactionStartLine, matches: map[int]string{ compactionPatternJobIdx: "284925", compactionPatternSuffixIdx: "ing", compactionPatternTypeIdx: "default", compactionPatternFromIdx: "2", compactionPatternToIdx: "3", compactionPatternLevels: "L2 [442555] (4.2MB) Score=1.01 + L3 [445853] (8.4MB) Score=0.99", }, }, { name: "compaction start multilevel", re: compactionPattern, line: compactionMultiLevelStartLine, matches: map[int]string{ compactionPatternJobIdx: "11", compactionPatternSuffixIdx: "ing", compactionPatternTypeIdx: "default", compactionPatternFromIdx: "2", compactionPatternToIdx: "4", compactionPatternLevels: "L2 [250858] (2.1MB) Score=1.09 + L3 [247985 247989 247848] (17MB) Score=0.99 + L4 [250817 250834 238396] (28MB) Score=1.00", }, }, { name: "compaction start - no node / store", re: compactionPattern, line: compactionStartNoNodeStoreLine, matches: map[int]string{ compactionPatternJobIdx: "284925", compactionPatternSuffixIdx: "ing", compactionPatternTypeIdx: "default", compactionPatternFromIdx: "2", compactionPatternToIdx: "3", }, }, { name: "compaction end", re: compactionPattern, line: compactionEndLine, matches: map[int]string{ compactionPatternJobIdx: "284925", compactionPatternSuffixIdx: "ed", compactionPatternTypeIdx: "default", compactionPatternFromIdx: "2", compactionPatternToIdx: "3", compactionPatternBytesIdx: "13MB", }, }, { name: "compaction end", re: compactionPattern, line: compactionMultiLevelEndline, matches: map[int]string{ compactionPatternJobIdx: "11", compactionPatternSuffixIdx: "ed", compactionPatternTypeIdx: "default", compactionPatternFromIdx: "2", compactionPatternToIdx: "4", compactionPatternBytesIdx: "46MB", }, }, { name: "flush start", re: flushPattern, line: flushStartLine, matches: map[int]string{ flushPatternJobIdx: "10", flushPatternSuffixIdx: "ing", flushPatternBytesIdx: "", }, }, { name: "flush start - no node / store", re: flushPattern, line: flushStartNoNodeStoreLine, matches: map[int]string{ flushPatternJobIdx: "10", flushPatternSuffixIdx: "ing", flushPatternBytesIdx: "", }, }, { name: "flush end", re: flushPattern, line: flushEndLine, matches: map[int]string{ flushPatternJobIdx: "10", flushPatternSuffixIdx: "ed", flushPatternBytesIdx: "1.3MB", }, }, { name: "read amp suffix", re: readAmpPattern, line: readAmpLine, matches: map[int]string{ readAmpPatternValueIdx: "5", }, }, { name: "read amp suffix 23.1", re: readAmpPattern, line: readAmpLine23_1, matches: map[int]string{ readAmpPatternValueIdx: "5", }, }, { name: "ingestion during flush job 23.1", re: flushableIngestedPattern, line: flushableIngestionLine23_1, matches: map[int]string{ flushableIngestedPatternJobIdx: "226", }, }, { name: "ingestion during flush 23.1", re: ingestedFilePattern, line: flushableIngestionLine23_1, matches: map[int]string{ // Just looking at the first match for these. ingestedFilePatternLevelIdx: "0", ingestedFilePatternFileIdx: "024334", ingestedFilePatternBytesIdx: "1.5 K", }, }, { name: "ingestion during flush job", re: flushableIngestedPattern, line: flushableIngestionLine, matches: map[int]string{ flushableIngestedPatternJobIdx: "226", }, }, { name: "ingestion during flush", re: ingestedFilePattern, line: flushableIngestionLine, matches: map[int]string{ // Just looking at the first match for these. ingestedFilePatternLevelIdx: "0", ingestedFilePatternFileIdx: "024334", ingestedFilePatternBytesIdx: "1.5KB", }, }, } for _, tc := range tcs { t.Run(tc.name, func(t *testing.T) { matches := tc.re.FindStringSubmatch(tc.line) require.NotNil(t, matches) for idx, want := range tc.matches { require.Equal(t, want, matches[idx]) } }) } } func TestParseLogContext(t *testing.T) { testCases := []struct { line string timestamp string node int store int }{ { line: `I211215 14:26:56.012382 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [n5,pebble,s6] foo`, timestamp: "211215 14:26:56.012382", node: 5, store: 6, }, { line: `I211215 14:26:56.012382 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [T?,n5,pebble,s6] foo`, timestamp: "211215 14:26:56.012382", node: 5, store: 6, }, { line: `I211215 14:26:56.012382 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [T15,n5,pebble,s6] foo`, timestamp: "211215 14:26:56.012382", node: 5, store: 6, }, { line: `I211215 14:26:56.012382 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [T1,n?,pebble,s6] foo`, timestamp: "211215 14:26:56.012382", node: -1, store: 6, }, { line: `I211215 14:26:56.012382 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [n5,pebble,s?] foo`, timestamp: "211215 14:26:56.012382", node: 5, store: -1, }, } for _, tc := range testCases { t.Run("", func(t *testing.T) { var b logEventCollector require.NoError(t, parseLogContext(tc.line, &b)) expT, err := time.Parse(timeFmt, tc.timestamp) require.NoError(t, err) require.Equal(t, expT, b.ctx.timestamp) require.Equal(t, tc.node, b.ctx.node) require.Equal(t, tc.store, b.ctx.store) }) } } func TestCompactionLogs(t *testing.T) { dir := t.TempDir() datadriven.Walk(t, "testdata", func(t *testing.T, path string) { var c *logEventCollector var logNum int resetFn := func() { c = newEventCollector() logNum = 0 } resetFn() datadriven.RunTest(t, path, func(t *testing.T, td *datadriven.TestData) string { switch td.Cmd { case "log": basename := fmt.Sprintf("%d.log", logNum) logNum++ f, err := os.Create(filepath.Join(dir, basename)) if err != nil { panic(err) } if _, err = f.WriteString(td.Input); err != nil { panic(err) } _ = f.Close() if err = parseLog(f.Name(), c); err != nil { return err.Error() } return basename case "summarize": window := 1 * time.Minute longRunning := time.Duration(math.MaxInt64) var err error for _, cmdArg := range td.CmdArgs { switch cmdArg.Key { case "window": window, err = time.ParseDuration(cmdArg.Vals[0]) if err != nil { panic(errors.Newf("could not parse window: %s", err)) } case "long-running": longRunning, err = time.ParseDuration(cmdArg.Vals[0]) if err != nil { panic(errors.Newf("could not parse long-running: %s", err)) } default: panic(errors.Newf("unknown arg %q", cmdArg.Key)) } } a := newAggregator(window, longRunning, c.events, c.readAmps) windows := a.aggregate() var b bytes.Buffer for _, w := range windows { b.WriteString(w.String()) } return b.String() case "reset": resetFn() return "" default: return fmt.Sprintf("unknown command %q", td.Cmd) } }) }) } func TestParseInputBytes(t *testing.T) { testCases := []struct { s string want uint64 }{ // Test both 23.1 and current formats. { "(10 B)", 10, }, { "(10B)", 10, }, { "(10 M)", 10 << 20, }, { "(10MB)", 10 << 20, }, { "(10 M) + (20 M)", 30 << 20, }, { "(10MB) + (20MB)", 30 << 20, }, { "(10 M) + (20 M) + (30 M)", 60 << 20, }, { "(10MB) + (20MB) + (30MB)", 60 << 20, }, { "foo", 0, }, } for _, tc := range testCases { t.Run(tc.s, func(t *testing.T) { got, err := sumInputBytes(tc.s) require.NoError(t, err) require.Equal(t, tc.want, got) }) } }