ceremonyclient/pebble/tool/logs/compaction_test.go

// 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)
		})
	}
}