From 7d267cc0c108f9c8eedf53e5bddb4de43c903954 Mon Sep 17 00:00:00 2001 From: Radu Berinde Date: Tue, 18 Jul 2023 09:45:23 -0700 Subject: [PATCH] db: improve metrics formatting This change improves the formatting of the Pebble metrics: - we no longer try to artificially fit non-tabular information in a single table - all byte figures end in B/KB/MB/etc - counts and corresponding sizes are grouped together - flushable ingests information moved under ingestions These metrics are periodically logged and can be obtained through the db console as well. Release note: Pebble metrics formatting improvements; tools that parse these logs might need updating. Fixes #1473. --- internal/humanize/humanize.go | 6 + internal/humanize/humanize_test.go | 38 +++ internal/humanize/testdata/humanize | 49 +++ metrics.go | 258 +++++++-------- metrics_test.go | 74 +---- testdata/event_listener | 92 +++--- testdata/ingest | 46 +-- testdata/metrics | 395 +++++++++++++---------- tool/logs/compaction.go | 7 +- tool/logs/compaction_test.go | 126 ++++---- tool/logs/testdata/compactions | 100 +++--- tool/logs/testdata/compactions-23-1 | 478 ++++++++++++++++++++++++++++ tool/testdata/db_lsm | 46 +-- 13 files changed, 1142 insertions(+), 573 deletions(-) create mode 100644 internal/humanize/humanize_test.go create mode 100644 internal/humanize/testdata/humanize create mode 100644 tool/logs/testdata/compactions-23-1 diff --git a/internal/humanize/humanize.go b/internal/humanize/humanize.go index 9b1d532525..57318b325b 100644 --- a/internal/humanize/humanize.go +++ b/internal/humanize/humanize.go @@ -41,6 +41,12 @@ var IEC = config{1024, []string{" B", " K", " M", " G", " T", " P", " E"}} // SI produces human readable representations of integer values in SI units. var SI = config{1000, []string{"", " K", " M", " G", " T", " P", " E"}} +// Bytes produces human readable representations of byte values in IEC units. +var Bytes = config{1024, []string{"B", "KB", "MB", "GB", "TB", "PB", "EB"}} + +// Count produces human readable representations of unitless values in SI units. +var Count = config{1000, []string{"", "K", "M", "G", "T", "P", "E"}} + // Int64 produces a human readable representation of the value. func (c *config) Int64(s int64) FormattedString { if s < 0 { diff --git a/internal/humanize/humanize_test.go b/internal/humanize/humanize_test.go new file mode 100644 index 0000000000..a4a42c3549 --- /dev/null +++ b/internal/humanize/humanize_test.go @@ -0,0 +1,38 @@ +// Copyright 2023 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 humanize + +import ( + "bytes" + "fmt" + "strconv" + "strings" + "testing" + + "github.com/cockroachdb/datadriven" +) + +func TestHumanize(t *testing.T) { + datadriven.RunTest(t, "testdata/humanize", func(t *testing.T, td *datadriven.TestData) string { + var c config + switch td.Cmd { + case "bytes": + c = Bytes + case "count": + c = Count + default: + td.Fatalf(t, "invalid command %q", td.Cmd) + } + var buf bytes.Buffer + for _, row := range strings.Split(td.Input, "\n") { + val, err := strconv.ParseInt(row, 10, 64) + if err != nil { + td.Fatalf(t, "error parsing %q: %v", row, err) + } + fmt.Fprintf(&buf, "%s\n", c.Int64(val)) + } + return buf.String() + }) +} diff --git a/internal/humanize/testdata/humanize b/internal/humanize/testdata/humanize new file mode 100644 index 0000000000..27f554aa88 --- /dev/null +++ b/internal/humanize/testdata/humanize @@ -0,0 +1,49 @@ +bytes +0 +1 +9 +99 +123 +123456 +12345678 +1234567890 +1234567890123 +123456789012345 +123456789012345678 +---- +0B +1B +9B +99B +123B +121KB +12MB +1.1GB +1.1TB +112TB +110PB + +count +0 +1 +9 +99 +123 +123456 +12345678 +1234567890 +1234567890123 +123456789012345 +123456789012345678 +---- +0 +1 +9 +99 +123 +124K +12M +1.2G +1.2T +124T +124P diff --git a/metrics.go b/metrics.go index 7749583971..ff17eac2c7 100644 --- a/metrics.go +++ b/metrics.go @@ -6,7 +6,7 @@ package pebble import ( "fmt" - "strings" + "math" "time" "github.com/cockroachdb/pebble/internal/base" @@ -28,14 +28,6 @@ type FilterMetrics = sstable.FilterMetrics // comment in base. type ThroughputMetric = base.ThroughputMetric -func formatCacheMetrics(w redact.SafePrinter, m *CacheMetrics, name redact.SafeString) { - w.Printf("%7s %9s %7s %6.1f%% (score == hit-rate)\n", - name, - humanize.SI.Int64(m.Count), - humanize.IEC.Int64(m.Size), - redact.Safe(hitRate(m.Hits, m.Misses))) -} - // LevelMetrics holds per-level metrics such as the number of files and total // size of the files, and compaction related metrics. type LevelMetrics struct { @@ -121,32 +113,6 @@ func (m *LevelMetrics) WriteAmp() float64 { return float64(m.BytesFlushed+m.BytesCompacted) / float64(m.BytesIn) } -// format generates a string of the receiver's metrics, formatting it into the -// supplied buffer. -func (m *LevelMetrics) format( - w redact.SafePrinter, score redact.SafeValue, includeValueBlocksSize bool, -) { - w.Printf("%9d %7s %7s %7s %7s %7s %7s %7s %7s %7s %7s %7d %7.1f", - redact.Safe(m.NumFiles), - humanize.IEC.Int64(m.Size), - score, - humanize.IEC.Uint64(m.BytesIn), - humanize.IEC.Uint64(m.BytesIngested), - humanize.SI.Uint64(m.TablesIngested), - humanize.IEC.Uint64(m.BytesMoved), - humanize.SI.Uint64(m.TablesMoved), - humanize.IEC.Uint64(m.BytesFlushed+m.BytesCompacted), - humanize.SI.Uint64(m.TablesFlushed+m.TablesCompacted), - humanize.IEC.Uint64(m.BytesRead), - redact.Safe(m.Sublevels), - redact.Safe(m.WriteAmp())) - if includeValueBlocksSize { - w.Printf(" %7s\n", humanize.IEC.Uint64(m.Additional.ValueBlocksSize)) - } else { - w.SafeString("\n") - } -} - // Metrics holds metrics for various subsystems of the DB such as the Cache, // Compactions, WAL, and per-Level metrics. // @@ -362,59 +328,32 @@ func (m *Metrics) Total() LevelMetrics { return total } -const notApplicable = redact.SafeString("-") - -func (m *Metrics) formatWAL(w redact.SafePrinter) { - var writeAmp float64 - if m.WAL.BytesIn > 0 { - writeAmp = float64(m.WAL.BytesWritten) / float64(m.WAL.BytesIn) - } - w.Printf(" WAL %9d %7s %7s %7s %7s %7s %7s %7s %7s %7s %7s %7s %7.1f\n", - redact.Safe(m.WAL.Files), - humanize.Uint64(m.WAL.Size), - notApplicable, - humanize.Uint64(m.WAL.BytesIn), - notApplicable, - notApplicable, - notApplicable, - notApplicable, - humanize.Uint64(m.WAL.BytesWritten), - notApplicable, - notApplicable, - notApplicable, - redact.Safe(writeAmp)) -} - -// String pretty-prints the metrics, showing a line for the WAL, a line per-level, and -// a total: +// String pretty-prints the metrics as below: // -// __level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp -// WAL 1 28 B - 17 B - - - - 56 B - - - 3.3 -// 0 1 770 B 0.25 28 B 0 B 0 0 B 0 770 B 1 0 B 1 27.5 -// 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 -// 2 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 -// 3 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 -// 4 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 -// 5 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 -// 6 0 0 B - 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 -// total 1 770 B - 56 B 0 B 0 0 B 0 826 B 1 0 B 1 14.8 -// flush 1 0 B 0 0 (ingest = ingested-as-flushable, move = tables-ingested) -// compact 0 0 B 0 B 0 (size == estimated-debt, score = in-progress-bytes, in = num-in-progress) -// ctype 0 0 0 0 0 0 0 (default, delete, elision, move, read, rewrite, multi-level) -// memtbl 1 256 K -// zmemtbl 1 256 K -// ztbl 0 0 B -// bcache 4 697 B 0.0% (score == hit-rate) -// tcache 1 696 B 0.0% (score == hit-rate) -// snaps 0 - 0 (score == earliest seq num) -// titers 1 -// filter - - 0.0% (score == utility) -// -// The WAL "in" metric is the size of the batches written to the WAL. The WAL -// "write" metric is the size of the physical data written to the WAL which -// includes record fragment overhead. Write amplification is computed as -// bytes-written / bytes-in, except for the total row where bytes-in is -// replaced with WAL-bytes-written + bytes-ingested. +// | | | | ingested | moved | written | | amp +// level | tables size val-bl | score | in | tables size | tables size | tables size | read | r w +// ------+---------------------+-------+-------+--------------+--------------+--------------+-------+--------- +// 0 | 101 102B 0B | 103.0 | 104B | 112 104B | 113 106B | 221 217B | 107B | 1 2.1 +// 1 | 201 202B 0B | 203.0 | 204B | 212 204B | 213 206B | 421 417B | 207B | 2 2.0 +// 2 | 301 302B 0B | 303.0 | 304B | 312 304B | 313 306B | 621 617B | 307B | 3 2.0 +// 3 | 401 402B 0B | 403.0 | 404B | 412 404B | 413 406B | 821 817B | 407B | 4 2.0 +// 4 | 501 502B 0B | 503.0 | 504B | 512 504B | 513 506B | 1.0K 1017B | 507B | 5 2.0 +// 5 | 601 602B 0B | 603.0 | 604B | 612 604B | 613 606B | 1.2K 1.2KB | 607B | 6 2.0 +// 6 | 701 702B 0B | - | 704B | 712 704B | 713 706B | 1.4K 1.4KB | 707B | 7 2.0 +// total | 2.8K 2.7KB 0B | - | 2.8KB | 2.9K 2.8KB | 2.9K 2.8KB | 5.7K 8.4KB | 2.8KB | 28 3.0 +// ----------------------------------------------------------------------------------------------------------- +// WAL: 22 files (24B) in: 25B written: 26B (4% overhead) +// Flushes: 8 +// Compactions: 5 estimated debt: 6B in progress: 2 (7B) +// default: 27 delete: 28 elision: 29 move: 30 read: 31 rewrite: 32 multi-level: 33 +// MemTables: 12 (11B) zombie: 14 (13B) +// Zombie tables: 16 (15B) +// Block cache: 2 entries (1B) hit rate: 42.9% +// Table cache: 18 entries (17B) hit rate: 48.7% +// Snapshots: 4 earliest seq num: 1024 +// Table iters: 21 +// Filter utility: 47.4% +// Ingestions: 27 as flushable: 36 (34B in 35 tables) func (m *Metrics) String() string { return redact.StringWithoutMarkers(m) } @@ -435,29 +374,59 @@ func (m *Metrics) SafeFormat(w redact.SafePrinter, _ rune) { // width specifiers. When the issue is fixed, we can convert these to // RedactableStrings. https://github.com/cockroachdb/redact/issues/17 - haveValueBlocks := false - var valueBlocksHeading redact.SafeString - for level := 0; level < numLevels; level++ { - if m.Levels[level].Additional.ValueBlocksSize > 0 { - haveValueBlocks = true - valueBlocksHeading = "__val-bl" - break + w.SafeString(" | | | | ingested | moved | written | | amp\n") + w.SafeString("level | tables size val-bl | score | in | tables size | tables size | tables size | read | r w\n") + w.SafeString("------+---------------------+-------+-------+--------------+--------------+--------------+-------+---------\n") + + // formatRow prints out a row of the table. + formatRow := func(m *LevelMetrics, score float64) { + scoreStr := "-" + if !math.IsNaN(score) { + // Try to keep the string no longer than 5 characters. + switch { + case score < 99.995: + scoreStr = fmt.Sprintf("%.2f", score) + case score < 999.95: + scoreStr = fmt.Sprintf("%.1f", score) + default: + scoreStr = fmt.Sprintf("%.0f", score) + } } + var wampStr string + if wamp := m.WriteAmp(); wamp > 99.5 { + wampStr = fmt.Sprintf("%.0f", wamp) + } else { + wampStr = fmt.Sprintf("%.1f", wamp) + } + + w.Printf("| %5s %6s %6s | %5s | %5s | %5s %6s | %5s %6s | %5s %6s | %5s | %3d %4s\n", + humanize.Count.Int64(m.NumFiles), + humanize.Bytes.Int64(m.Size), + humanize.Bytes.Uint64(m.Additional.ValueBlocksSize), + redact.Safe(scoreStr), + humanize.Bytes.Uint64(m.BytesIn), + humanize.Count.Uint64(m.TablesIngested), + humanize.Bytes.Uint64(m.BytesIngested), + humanize.Count.Uint64(m.TablesMoved), + humanize.Bytes.Uint64(m.BytesMoved), + humanize.Count.Uint64(m.TablesFlushed+m.TablesCompacted), + humanize.Bytes.Uint64(m.BytesFlushed+m.BytesCompacted), + humanize.Bytes.Uint64(m.BytesRead), + redact.Safe(m.Sublevels), + redact.Safe(wampStr)) } + var total LevelMetrics - w.Printf("__level_____count____size___score______in__ingest(sz_cnt)"+ - "____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp%s\n", valueBlocksHeading) - m.formatWAL(w) for level := 0; level < numLevels; level++ { l := &m.Levels[level] - w.Printf("%7d ", redact.Safe(level)) + w.Printf("%5d ", redact.Safe(level)) // Format the score. - var score redact.SafeValue = notApplicable + score := math.NaN() if level < numLevels-1 { - score = redact.Safe(fmt.Sprintf("%0.2f", l.Score)) + score = l.Score } - l.format(w, score, haveValueBlocks) + formatRow(l, score) total.Add(l) total.Sublevels += l.Sublevels } @@ -467,60 +436,75 @@ func (m *Metrics) SafeFormat(w redact.SafePrinter, _ rune) { // the bytes written to the log and bytes written externally and then // ingested. total.BytesFlushed += total.BytesIn - w.SafeString(" total ") - total.format(w, notApplicable, haveValueBlocks) + w.SafeString("total ") + formatRow(&total, math.NaN()) - w.Printf(" flush %9d %31s %7d %7d %s\n", - redact.Safe(m.Flush.Count), - humanize.IEC.Uint64(m.Flush.AsIngestBytes), - redact.Safe(m.Flush.AsIngestTableCount), - redact.Safe(m.Flush.AsIngestCount), - redact.SafeString(`(ingest = tables-ingested, move = ingested-as-flushable)`)) - w.Printf("compact %9d %7s %7s %7d %s %s\n", + w.SafeString("-----------------------------------------------------------------------------------------------------------\n") + + w.Printf("WAL: %d files (%s) in: %s written: %s (%.0f%% overhead)\n", + redact.Safe(m.WAL.Files), + humanize.Bytes.Uint64(m.WAL.Size), + humanize.Bytes.Uint64(m.WAL.BytesIn), + humanize.Bytes.Uint64(m.WAL.BytesWritten), + redact.Safe(percent(int64(m.WAL.BytesWritten)-int64(m.WAL.BytesIn), int64(m.WAL.BytesIn)))) + + w.Printf("Flushes: %d\n", redact.Safe(m.Flush.Count)) + + w.Printf("Compactions: %d estimated debt: %s in progress: %d (%s)\n", redact.Safe(m.Compact.Count), - humanize.IEC.Uint64(m.Compact.EstimatedDebt), - humanize.IEC.Int64(m.Compact.InProgressBytes), + humanize.Bytes.Uint64(m.Compact.EstimatedDebt), redact.Safe(m.Compact.NumInProgress), - redact.SafeString(strings.Repeat(" ", 24)), - redact.SafeString(`(size == estimated-debt, score = in-progress-bytes, in = num-in-progress)`)) - w.Printf(" ctype %9d %7d %7d %7d %7d %7d %7d %s\n", + humanize.Bytes.Int64(m.Compact.InProgressBytes)) + + w.Printf(" default: %d delete: %d elision: %d move: %d read: %d rewrite: %d multi-level: %d\n", redact.Safe(m.Compact.DefaultCount), redact.Safe(m.Compact.DeleteOnlyCount), redact.Safe(m.Compact.ElisionOnlyCount), redact.Safe(m.Compact.MoveCount), redact.Safe(m.Compact.ReadCount), redact.Safe(m.Compact.RewriteCount), - redact.Safe(m.Compact.MultiLevelCount), - redact.SafeString(`(default, delete, elision, move, read, rewrite, multi-level)`)) - w.Printf(" memtbl %9d %7s\n", + redact.Safe(m.Compact.MultiLevelCount)) + + w.Printf("MemTables: %d (%s) zombie: %d (%s)\n", redact.Safe(m.MemTable.Count), - humanize.IEC.Uint64(m.MemTable.Size)) - w.Printf("zmemtbl %9d %7s\n", + humanize.Bytes.Uint64(m.MemTable.Size), redact.Safe(m.MemTable.ZombieCount), - humanize.IEC.Uint64(m.MemTable.ZombieSize)) - w.Printf(" ztbl %9d %7s\n", + humanize.Bytes.Uint64(m.MemTable.ZombieSize)) + + w.Printf("Zombie tables: %d (%s)\n", redact.Safe(m.Table.ZombieCount), - humanize.IEC.Uint64(m.Table.ZombieSize)) - formatCacheMetrics(w, &m.BlockCache, "bcache") - formatCacheMetrics(w, &m.TableCache, "tcache") - w.Printf(" snaps %9d %7s %7d (score == earliest seq num)\n", + humanize.Bytes.Uint64(m.Table.ZombieSize)) + + formatCacheMetrics := func(m *CacheMetrics, name redact.SafeString) { + w.Printf("%s: %s entries (%s) hit rate: %.1f%%\n", + name, + humanize.Count.Int64(m.Count), + humanize.Bytes.Int64(m.Size), + redact.Safe(hitRate(m.Hits, m.Misses))) + } + formatCacheMetrics(&m.BlockCache, "Block cache") + formatCacheMetrics(&m.TableCache, "Table cache") + + w.Printf("Snapshots: %d earliest seq num: %d\n", redact.Safe(m.Snapshots.Count), - notApplicable, redact.Safe(m.Snapshots.EarliestSeqNum)) - w.Printf(" titers %9d\n", redact.Safe(m.TableIters)) - w.Printf(" filter %9s %7s %6.1f%% (score == utility)\n", - notApplicable, - notApplicable, - redact.Safe(hitRate(m.Filter.Hits, m.Filter.Misses))) - w.Printf(" ingest %9d\n", + + w.Printf("Table iters: %d\n", redact.Safe(m.TableIters)) + w.Printf("Filter utility: %.1f%%\n", redact.Safe(hitRate(m.Filter.Hits, m.Filter.Misses))) + w.Printf("Ingestions: %d as flushable: %d (%s in %d tables)\n", redact.Safe(m.Ingest.Count), - ) + redact.Safe(m.Flush.AsIngestCount), + humanize.Bytes.Uint64(m.Flush.AsIngestBytes), + redact.Safe(m.Flush.AsIngestTableCount)) } func hitRate(hits, misses int64) float64 { - sum := hits + misses - if sum == 0 { + return percent(hits, hits+misses) +} + +func percent(numerator, denominator int64) float64 { + if denominator == 0 { return 0 } - return 100 * float64(hits) / float64(sum) + return 100 * float64(numerator) / float64(denominator) } diff --git a/metrics_test.go b/metrics_test.go index 9bc32be54e..40f4271746 100644 --- a/metrics_test.go +++ b/metrics_test.go @@ -18,7 +18,7 @@ import ( "github.com/stretchr/testify/require" ) -func TestMetricsFormat(t *testing.T) { +func exampleMetrics() Metrics { var m Metrics m.BlockCache.Size = 1 m.BlockCache.Count = 2 @@ -79,34 +79,7 @@ func TestMetricsFormat(t *testing.T) { l.TablesIngested = base + 12 l.TablesMoved = base + 13 } - - const expected = ` -__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp - WAL 22 24 B - 25 B - - - - 26 B - - - 1.0 - 0 101 102 B 103.00 104 B 104 B 112 106 B 113 217 B 221 107 B 1 2.1 - 1 201 202 B 203.00 204 B 204 B 212 206 B 213 417 B 421 207 B 2 2.0 - 2 301 302 B 303.00 304 B 304 B 312 306 B 313 617 B 621 307 B 3 2.0 - 3 401 402 B 403.00 404 B 404 B 412 406 B 413 817 B 821 407 B 4 2.0 - 4 501 502 B 503.00 504 B 504 B 512 506 B 513 1017 B 1.0 K 507 B 5 2.0 - 5 601 602 B 603.00 604 B 604 B 612 606 B 613 1.2 K 1.2 K 607 B 6 2.0 - 6 701 702 B - 704 B 704 B 712 706 B 713 1.4 K 1.4 K 707 B 7 2.0 - total 2807 2.7 K - 2.8 K 2.8 K 2.9 K 2.8 K 2.9 K 8.4 K 5.7 K 2.8 K 28 3.0 - flush 8 34 B 35 36 (ingest = tables-ingested, move = ingested-as-flushable) -compact 5 6 B 7 B 2 (size == estimated-debt, score = in-progress-bytes, in = num-in-progress) - ctype 27 28 29 30 31 32 33 (default, delete, elision, move, read, rewrite, multi-level) - memtbl 12 11 B -zmemtbl 14 13 B - ztbl 16 15 B - bcache 2 1 B 42.9% (score == hit-rate) - tcache 18 17 B 48.7% (score == hit-rate) - snaps 4 - 1024 (score == earliest seq num) - titers 21 - filter - - 47.4% (score == utility) - ingest 27 -` - if s := "\n" + m.String(); expected != s { - t.Fatalf("expected%s\nbut found%s", expected, s) - } + return m } func TestMetrics(t *testing.T) { @@ -143,6 +116,17 @@ func TestMetrics(t *testing.T) { datadriven.RunTest(t, "testdata/metrics", func(t *testing.T, td *datadriven.TestData) string { switch td.Cmd { + case "example": + m := exampleMetrics() + res := m.String() + + // Nothing in the metrics should be redacted. + redacted := string(redact.Sprintf("%s", &m).Redact()) + if redacted != res { + td.Fatalf(t, "redacted metrics don't match\nunredacted:\n%s\nredacted:%s\n", res, redacted) + } + return res + case "batch": b := d.NewBatch() if err := runBatchDefineCmd(td, b); err != nil { @@ -270,38 +254,6 @@ func TestMetrics(t *testing.T) { }) } -func TestMetricsRedact(t *testing.T) { - const expected = ` -__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp - WAL 0 0 B - 0 B - - - - 0 B - - - 0.0 - 0 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 2 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 3 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 4 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 5 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 6 0 0 B - 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - total 0 0 B - 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - flush 0 0 B 0 0 (ingest = tables-ingested, move = ingested-as-flushable) -compact 0 0 B 0 B 0 (size == estimated-debt, score = in-progress-bytes, in = num-in-progress) - ctype 0 0 0 0 0 0 0 (default, delete, elision, move, read, rewrite, multi-level) - memtbl 0 0 B -zmemtbl 0 0 B - ztbl 0 0 B - bcache 0 0 B 0.0% (score == hit-rate) - tcache 0 0 B 0.0% (score == hit-rate) - snaps 0 - 0 (score == earliest seq num) - titers 0 - filter - - 0.0% (score == utility) - ingest 0 -` - - got := redact.Sprintf("%s", &Metrics{}).Redact() - if s := "\n" + got; expected != s { - t.Fatalf("expected%s\nbut found%s", expected, s) - } -} - func TestMetricsWAmpDisableWAL(t *testing.T) { d, err := Open("", &Options{FS: vfs.NewMem(), DisableWAL: true}) require.NoError(t, err) diff --git a/testdata/event_listener b/testdata/event_listener index c379235ad2..a7128086e6 100644 --- a/testdata/event_listener +++ b/testdata/event_listener @@ -268,28 +268,30 @@ remove: ext/0 metrics ---- -__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp - WAL 1 27 B - 48 B - - - - 108 B - - - 2.2 - 0 2 1.3 K 0.40 81 B 717 B 1 0 B 0 1.9 K 3 0 B 2 24.5 - 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 2 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 3 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 4 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 5 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 6 1 662 B - 1.3 K 0 B 0 0 B 0 662 B 1 1.3 K 1 0.5 - total 3 2.0 K - 825 B 717 B 1 0 B 0 3.4 K 4 1.3 K 3 4.2 - flush 3 0 B 0 0 (ingest = tables-ingested, move = ingested-as-flushable) -compact 1 2.0 K 0 B 0 (size == estimated-debt, score = in-progress-bytes, in = num-in-progress) - ctype 1 0 0 0 0 0 0 (default, delete, elision, move, read, rewrite, multi-level) - memtbl 1 256 K -zmemtbl 0 0 B - ztbl 0 0 B - bcache 6 1.1 K 11.1% (score == hit-rate) - tcache 1 800 B 40.0% (score == hit-rate) - snaps 0 - 0 (score == earliest seq num) - titers 0 - filter - - 0.0% (score == utility) - ingest 1 + | | | | ingested | moved | written | | amp +level | tables size val-bl | score | in | tables size | tables size | tables size | read | r w +------+---------------------+-------+-------+--------------+--------------+--------------+-------+--------- + 0 | 2 1.3KB 0B | 0.40 | 81B | 1 717B | 0 0B | 3 1.9KB | 0B | 2 24.5 + 1 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 2 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 3 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 4 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 5 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 6 | 1 662B 0B | - | 1.3KB | 0 0B | 0 0B | 1 662B | 1.3KB | 1 0.5 +total | 3 2.0KB 0B | - | 825B | 1 717B | 0 0B | 4 3.4KB | 1.3KB | 3 4.2 +----------------------------------------------------------------------------------------------------------- +WAL: 1 files (27B) in: 48B written: 108B (125% overhead) +Flushes: 3 +Compactions: 1 estimated debt: 2.0KB in progress: 0 (0B) + default: 1 delete: 0 elision: 0 move: 0 read: 0 rewrite: 0 multi-level: 0 +MemTables: 1 (256KB) zombie: 0 (0B) +Zombie tables: 0 (0B) +Block cache: 6 entries (1.1KB) hit rate: 11.1% +Table cache: 1 entries (800B) hit rate: 40.0% +Snapshots: 0 earliest seq num: 0 +Table iters: 0 +Filter utility: 0.0% +Ingestions: 1 as flushable: 0 (0B in 0 tables) # Set up a scenario where the table to be ingested overlaps with the memtable. # The table is ingested as a flushable. The flush metrics refect the flushed @@ -362,28 +364,30 @@ sync: db/MANIFEST-000023 metrics ---- -__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp - WAL 1 29 B - 82 B - - - - 110 B - - - 1.3 - 0 4 2.7 K 0.80 81 B 1.4 K 2 0 B 0 2.6 K 4 0 B 4 32.7 - 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 2 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 3 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 4 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 5 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 6 2 1.3 K - 1.3 K 717 B 1 0 B 0 662 B 1 1.3 K 1 0.5 - total 6 4.0 K - 2.2 K 2.1 K 3 0 B 0 5.4 K 5 1.3 K 5 2.5 - flush 6 1.4 K 2 1 (ingest = tables-ingested, move = ingested-as-flushable) -compact 1 4.0 K 0 B 0 (size == estimated-debt, score = in-progress-bytes, in = num-in-progress) - ctype 1 0 0 0 0 0 0 (default, delete, elision, move, read, rewrite, multi-level) - memtbl 1 512 K -zmemtbl 0 0 B - ztbl 0 0 B - bcache 12 2.3 K 14.3% (score == hit-rate) - tcache 1 800 B 50.0% (score == hit-rate) - snaps 0 - 0 (score == earliest seq num) - titers 0 - filter - - 0.0% (score == utility) - ingest 1 + | | | | ingested | moved | written | | amp +level | tables size val-bl | score | in | tables size | tables size | tables size | read | r w +------+---------------------+-------+-------+--------------+--------------+--------------+-------+--------- + 0 | 4 2.7KB 0B | 0.80 | 81B | 2 1.4KB | 0 0B | 4 2.6KB | 0B | 4 32.7 + 1 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 2 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 3 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 4 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 5 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 6 | 2 1.3KB 0B | - | 1.3KB | 1 717B | 0 0B | 1 662B | 1.3KB | 1 0.5 +total | 6 4.0KB 0B | - | 2.2KB | 3 2.1KB | 0 0B | 5 5.4KB | 1.3KB | 5 2.5 +----------------------------------------------------------------------------------------------------------- +WAL: 1 files (29B) in: 82B written: 110B (34% overhead) +Flushes: 6 +Compactions: 1 estimated debt: 4.0KB in progress: 0 (0B) + default: 1 delete: 0 elision: 0 move: 0 read: 0 rewrite: 0 multi-level: 0 +MemTables: 1 (512KB) zombie: 0 (0B) +Zombie tables: 0 (0B) +Block cache: 12 entries (2.3KB) hit rate: 14.3% +Table cache: 1 entries (800B) hit rate: 50.0% +Snapshots: 0 earliest seq num: 0 +Table iters: 0 +Filter utility: 0.0% +Ingestions: 1 as flushable: 1 (1.4KB in 2 tables) sstables ---- diff --git a/testdata/ingest b/testdata/ingest index 2cbba8efeb..62dcd7e654 100644 --- a/testdata/ingest +++ b/testdata/ingest @@ -31,28 +31,30 @@ lsm metrics ---- -__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp - WAL 1 0 B - 0 B - - - - 0 B - - - 0.0 - 0 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 2 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 3 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 4 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 5 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 6 1 696 B - 0 B 696 B 1 0 B 0 0 B 0 0 B 1 0.0 - total 1 696 B - 696 B 696 B 1 0 B 0 696 B 0 0 B 1 1.0 - flush 0 0 B 0 0 (ingest = tables-ingested, move = ingested-as-flushable) -compact 0 0 B 0 B 0 (size == estimated-debt, score = in-progress-bytes, in = num-in-progress) - ctype 0 0 0 0 0 0 0 (default, delete, elision, move, read, rewrite, multi-level) - memtbl 1 256 K -zmemtbl 0 0 B - ztbl 0 0 B - bcache 6 1.2 K 35.7% (score == hit-rate) - tcache 1 800 B 50.0% (score == hit-rate) - snaps 0 - 0 (score == earliest seq num) - titers 0 - filter - - 0.0% (score == utility) - ingest 1 + | | | | ingested | moved | written | | amp +level | tables size val-bl | score | in | tables size | tables size | tables size | read | r w +------+---------------------+-------+-------+--------------+--------------+--------------+-------+--------- + 0 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 1 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 2 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 3 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 4 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 5 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 6 | 1 696B 0B | - | 0B | 1 696B | 0 0B | 0 0B | 0B | 1 0.0 +total | 1 696B 0B | - | 696B | 1 696B | 0 0B | 0 696B | 0B | 1 1.0 +----------------------------------------------------------------------------------------------------------- +WAL: 1 files (0B) in: 0B written: 0B (0% overhead) +Flushes: 0 +Compactions: 0 estimated debt: 0B in progress: 0 (0B) + default: 0 delete: 0 elision: 0 move: 0 read: 0 rewrite: 0 multi-level: 0 +MemTables: 1 (256KB) zombie: 0 (0B) +Zombie tables: 0 (0B) +Block cache: 6 entries (1.2KB) hit rate: 35.7% +Table cache: 1 entries (800B) hit rate: 50.0% +Snapshots: 0 earliest seq num: 0 +Table iters: 0 +Filter utility: 0.0% +Ingestions: 1 as flushable: 0 (0B in 0 tables) iter diff --git a/testdata/metrics b/testdata/metrics index 0bc8cd3378..248f45e013 100644 --- a/testdata/metrics +++ b/testdata/metrics @@ -1,3 +1,30 @@ +example +---- + | | | | ingested | moved | written | | amp +level | tables size val-bl | score | in | tables size | tables size | tables size | read | r w +------+---------------------+-------+-------+--------------+--------------+--------------+-------+--------- + 0 | 101 102B 0B | 103.0 | 104B | 112 104B | 113 106B | 221 217B | 107B | 1 2.1 + 1 | 201 202B 0B | 203.0 | 204B | 212 204B | 213 206B | 421 417B | 207B | 2 2.0 + 2 | 301 302B 0B | 303.0 | 304B | 312 304B | 313 306B | 621 617B | 307B | 3 2.0 + 3 | 401 402B 0B | 403.0 | 404B | 412 404B | 413 406B | 821 817B | 407B | 4 2.0 + 4 | 501 502B 0B | 503.0 | 504B | 512 504B | 513 506B | 1.0K 1017B | 507B | 5 2.0 + 5 | 601 602B 0B | 603.0 | 604B | 612 604B | 613 606B | 1.2K 1.2KB | 607B | 6 2.0 + 6 | 701 702B 0B | - | 704B | 712 704B | 713 706B | 1.4K 1.4KB | 707B | 7 2.0 +total | 2.8K 2.7KB 0B | - | 2.8KB | 2.9K 2.8KB | 2.9K 2.8KB | 5.7K 8.4KB | 2.8KB | 28 3.0 +----------------------------------------------------------------------------------------------------------- +WAL: 22 files (24B) in: 25B written: 26B (4% overhead) +Flushes: 8 +Compactions: 5 estimated debt: 6B in progress: 2 (7B) + default: 27 delete: 28 elision: 29 move: 30 read: 31 rewrite: 32 multi-level: 33 +MemTables: 12 (11B) zombie: 14 (13B) +Zombie tables: 16 (15B) +Block cache: 2 entries (1B) hit rate: 42.9% +Table cache: 18 entries (17B) hit rate: 48.7% +Snapshots: 4 earliest seq num: 1024 +Table iters: 21 +Filter utility: 47.4% +Ingestions: 27 as flushable: 36 (34B in 35 tables) + batch set a 1 ---- @@ -17,28 +44,30 @@ iter-new b metrics ---- -__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp - WAL 1 28 B - 17 B - - - - 56 B - - - 3.3 - 0 1 633 B 0.25 28 B 0 B 0 0 B 0 633 B 1 0 B 1 22.6 - 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 2 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 3 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 4 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 5 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 6 0 0 B - 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - total 1 633 B - 56 B 0 B 0 0 B 0 689 B 1 0 B 1 12.3 - flush 1 0 B 0 0 (ingest = tables-ingested, move = ingested-as-flushable) -compact 0 0 B 0 B 0 (size == estimated-debt, score = in-progress-bytes, in = num-in-progress) - ctype 0 0 0 0 0 0 0 (default, delete, elision, move, read, rewrite, multi-level) - memtbl 1 256 K -zmemtbl 1 256 K - ztbl 0 0 B - bcache 3 528 B 0.0% (score == hit-rate) - tcache 1 800 B 0.0% (score == hit-rate) - snaps 0 - 0 (score == earliest seq num) - titers 1 - filter - - 0.0% (score == utility) - ingest 0 + | | | | ingested | moved | written | | amp +level | tables size val-bl | score | in | tables size | tables size | tables size | read | r w +------+---------------------+-------+-------+--------------+--------------+--------------+-------+--------- + 0 | 1 633B 0B | 0.25 | 28B | 0 0B | 0 0B | 1 633B | 0B | 1 22.6 + 1 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 2 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 3 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 4 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 5 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 6 | 0 0B 0B | - | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 +total | 1 633B 0B | - | 56B | 0 0B | 0 0B | 1 689B | 0B | 1 12.3 +----------------------------------------------------------------------------------------------------------- +WAL: 1 files (28B) in: 17B written: 56B (229% overhead) +Flushes: 1 +Compactions: 0 estimated debt: 0B in progress: 0 (0B) + default: 0 delete: 0 elision: 0 move: 0 read: 0 rewrite: 0 multi-level: 0 +MemTables: 1 (256KB) zombie: 1 (256KB) +Zombie tables: 0 (0B) +Block cache: 3 entries (528B) hit rate: 0.0% +Table cache: 1 entries (800B) hit rate: 0.0% +Snapshots: 0 earliest seq num: 0 +Table iters: 1 +Filter utility: 0.0% +Ingestions: 0 as flushable: 0 (0B in 0 tables) disk-usage ---- @@ -66,28 +95,30 @@ compact a-z metrics ---- -__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp - WAL 1 28 B - 34 B - - - - 84 B - - - 2.5 - 0 0 0 B 0.00 56 B 0 B 0 0 B 0 1.2 K 2 0 B 0 22.6 - 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 2 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 3 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 4 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 5 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 6 1 639 B - 1.2 K 0 B 0 0 B 0 639 B 1 1.2 K 1 0.5 - total 1 639 B - 84 B 0 B 0 0 B 0 1.9 K 3 1.2 K 1 23.7 - flush 2 0 B 0 0 (ingest = tables-ingested, move = ingested-as-flushable) -compact 1 0 B 0 B 0 (size == estimated-debt, score = in-progress-bytes, in = num-in-progress) - ctype 1 0 0 0 0 0 0 (default, delete, elision, move, read, rewrite, multi-level) - memtbl 1 256 K -zmemtbl 2 512 K - ztbl 2 1.2 K - bcache 5 1.0 K 42.9% (score == hit-rate) - tcache 2 1.6 K 66.7% (score == hit-rate) - snaps 0 - 0 (score == earliest seq num) - titers 2 - filter - - 0.0% (score == utility) - ingest 0 + | | | | ingested | moved | written | | amp +level | tables size val-bl | score | in | tables size | tables size | tables size | read | r w +------+---------------------+-------+-------+--------------+--------------+--------------+-------+--------- + 0 | 0 0B 0B | 0.00 | 56B | 0 0B | 0 0B | 2 1.2KB | 0B | 0 22.6 + 1 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 2 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 3 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 4 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 5 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 6 | 1 639B 0B | - | 1.2KB | 0 0B | 0 0B | 1 639B | 1.2KB | 1 0.5 +total | 1 639B 0B | - | 84B | 0 0B | 0 0B | 3 1.9KB | 1.2KB | 1 23.7 +----------------------------------------------------------------------------------------------------------- +WAL: 1 files (28B) in: 34B written: 84B (147% overhead) +Flushes: 2 +Compactions: 1 estimated debt: 0B in progress: 0 (0B) + default: 1 delete: 0 elision: 0 move: 0 read: 0 rewrite: 0 multi-level: 0 +MemTables: 1 (256KB) zombie: 2 (512KB) +Zombie tables: 2 (1.2KB) +Block cache: 5 entries (1.0KB) hit rate: 42.9% +Table cache: 2 entries (1.6KB) hit rate: 66.7% +Snapshots: 0 earliest seq num: 0 +Table iters: 2 +Filter utility: 0.0% +Ingestions: 0 as flushable: 0 (0B in 0 tables) disk-usage ---- @@ -100,28 +131,30 @@ iter-close a metrics ---- -__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp - WAL 1 28 B - 34 B - - - - 84 B - - - 2.5 - 0 0 0 B 0.00 56 B 0 B 0 0 B 0 1.2 K 2 0 B 0 22.6 - 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 2 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 3 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 4 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 5 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 6 1 639 B - 1.2 K 0 B 0 0 B 0 639 B 1 1.2 K 1 0.5 - total 1 639 B - 84 B 0 B 0 0 B 0 1.9 K 3 1.2 K 1 23.7 - flush 2 0 B 0 0 (ingest = tables-ingested, move = ingested-as-flushable) -compact 1 0 B 0 B 0 (size == estimated-debt, score = in-progress-bytes, in = num-in-progress) - ctype 1 0 0 0 0 0 0 (default, delete, elision, move, read, rewrite, multi-level) - memtbl 1 256 K -zmemtbl 1 256 K - ztbl 2 1.2 K - bcache 5 1.0 K 42.9% (score == hit-rate) - tcache 2 1.6 K 66.7% (score == hit-rate) - snaps 0 - 0 (score == earliest seq num) - titers 2 - filter - - 0.0% (score == utility) - ingest 0 + | | | | ingested | moved | written | | amp +level | tables size val-bl | score | in | tables size | tables size | tables size | read | r w +------+---------------------+-------+-------+--------------+--------------+--------------+-------+--------- + 0 | 0 0B 0B | 0.00 | 56B | 0 0B | 0 0B | 2 1.2KB | 0B | 0 22.6 + 1 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 2 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 3 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 4 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 5 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 6 | 1 639B 0B | - | 1.2KB | 0 0B | 0 0B | 1 639B | 1.2KB | 1 0.5 +total | 1 639B 0B | - | 84B | 0 0B | 0 0B | 3 1.9KB | 1.2KB | 1 23.7 +----------------------------------------------------------------------------------------------------------- +WAL: 1 files (28B) in: 34B written: 84B (147% overhead) +Flushes: 2 +Compactions: 1 estimated debt: 0B in progress: 0 (0B) + default: 1 delete: 0 elision: 0 move: 0 read: 0 rewrite: 0 multi-level: 0 +MemTables: 1 (256KB) zombie: 1 (256KB) +Zombie tables: 2 (1.2KB) +Block cache: 5 entries (1.0KB) hit rate: 42.9% +Table cache: 2 entries (1.6KB) hit rate: 66.7% +Snapshots: 0 earliest seq num: 0 +Table iters: 2 +Filter utility: 0.0% +Ingestions: 0 as flushable: 0 (0B in 0 tables) # Closing iter c will release one of the zombie sstables. The other # zombie sstable is still referenced by iter b. @@ -131,28 +164,30 @@ iter-close c metrics ---- -__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp - WAL 1 28 B - 34 B - - - - 84 B - - - 2.5 - 0 0 0 B 0.00 56 B 0 B 0 0 B 0 1.2 K 2 0 B 0 22.6 - 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 2 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 3 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 4 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 5 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 6 1 639 B - 1.2 K 0 B 0 0 B 0 639 B 1 1.2 K 1 0.5 - total 1 639 B - 84 B 0 B 0 0 B 0 1.9 K 3 1.2 K 1 23.7 - flush 2 0 B 0 0 (ingest = tables-ingested, move = ingested-as-flushable) -compact 1 0 B 0 B 0 (size == estimated-debt, score = in-progress-bytes, in = num-in-progress) - ctype 1 0 0 0 0 0 0 (default, delete, elision, move, read, rewrite, multi-level) - memtbl 1 256 K -zmemtbl 1 256 K - ztbl 1 633 B - bcache 3 528 B 42.9% (score == hit-rate) - tcache 1 800 B 66.7% (score == hit-rate) - snaps 0 - 0 (score == earliest seq num) - titers 1 - filter - - 0.0% (score == utility) - ingest 0 + | | | | ingested | moved | written | | amp +level | tables size val-bl | score | in | tables size | tables size | tables size | read | r w +------+---------------------+-------+-------+--------------+--------------+--------------+-------+--------- + 0 | 0 0B 0B | 0.00 | 56B | 0 0B | 0 0B | 2 1.2KB | 0B | 0 22.6 + 1 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 2 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 3 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 4 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 5 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 6 | 1 639B 0B | - | 1.2KB | 0 0B | 0 0B | 1 639B | 1.2KB | 1 0.5 +total | 1 639B 0B | - | 84B | 0 0B | 0 0B | 3 1.9KB | 1.2KB | 1 23.7 +----------------------------------------------------------------------------------------------------------- +WAL: 1 files (28B) in: 34B written: 84B (147% overhead) +Flushes: 2 +Compactions: 1 estimated debt: 0B in progress: 0 (0B) + default: 1 delete: 0 elision: 0 move: 0 read: 0 rewrite: 0 multi-level: 0 +MemTables: 1 (256KB) zombie: 1 (256KB) +Zombie tables: 1 (633B) +Block cache: 3 entries (528B) hit rate: 42.9% +Table cache: 1 entries (800B) hit rate: 66.7% +Snapshots: 0 earliest seq num: 0 +Table iters: 1 +Filter utility: 0.0% +Ingestions: 0 as flushable: 0 (0B in 0 tables) disk-usage ---- @@ -165,28 +200,30 @@ iter-close b metrics ---- -__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp - WAL 1 28 B - 34 B - - - - 84 B - - - 2.5 - 0 0 0 B 0.00 56 B 0 B 0 0 B 0 1.2 K 2 0 B 0 22.6 - 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 2 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 3 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 4 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 5 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 6 1 639 B - 1.2 K 0 B 0 0 B 0 639 B 1 1.2 K 1 0.5 - total 1 639 B - 84 B 0 B 0 0 B 0 1.9 K 3 1.2 K 1 23.7 - flush 2 0 B 0 0 (ingest = tables-ingested, move = ingested-as-flushable) -compact 1 0 B 0 B 0 (size == estimated-debt, score = in-progress-bytes, in = num-in-progress) - ctype 1 0 0 0 0 0 0 (default, delete, elision, move, read, rewrite, multi-level) - memtbl 1 256 K -zmemtbl 0 0 B - ztbl 0 0 B - bcache 0 0 B 42.9% (score == hit-rate) - tcache 0 0 B 66.7% (score == hit-rate) - snaps 0 - 0 (score == earliest seq num) - titers 0 - filter - - 0.0% (score == utility) - ingest 0 + | | | | ingested | moved | written | | amp +level | tables size val-bl | score | in | tables size | tables size | tables size | read | r w +------+---------------------+-------+-------+--------------+--------------+--------------+-------+--------- + 0 | 0 0B 0B | 0.00 | 56B | 0 0B | 0 0B | 2 1.2KB | 0B | 0 22.6 + 1 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 2 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 3 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 4 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 5 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 6 | 1 639B 0B | - | 1.2KB | 0 0B | 0 0B | 1 639B | 1.2KB | 1 0.5 +total | 1 639B 0B | - | 84B | 0 0B | 0 0B | 3 1.9KB | 1.2KB | 1 23.7 +----------------------------------------------------------------------------------------------------------- +WAL: 1 files (28B) in: 34B written: 84B (147% overhead) +Flushes: 2 +Compactions: 1 estimated debt: 0B in progress: 0 (0B) + default: 1 delete: 0 elision: 0 move: 0 read: 0 rewrite: 0 multi-level: 0 +MemTables: 1 (256KB) zombie: 0 (0B) +Zombie tables: 0 (0B) +Block cache: 0 entries (0B) hit rate: 42.9% +Table cache: 0 entries (0B) hit rate: 66.7% +Snapshots: 0 earliest seq num: 0 +Table iters: 0 +Filter utility: 0.0% +Ingestions: 0 as flushable: 0 (0B in 0 tables) disk-usage ---- @@ -225,28 +262,30 @@ flush metrics ---- -__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp__val-bl - WAL 1 93 B - 116 B - - - - 242 B - - - 2.1 - 0 3 2.1 K 0.25 149 B 0 B 0 0 B 0 3.4 K 5 0 B 1 23.2 38 B - 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 0 B - 2 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 0 B - 3 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 0 B - 4 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 0 B - 5 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 0 B - 6 1 639 B - 1.2 K 0 B 0 0 B 0 639 B 1 1.2 K 1 0.5 0 B - total 4 2.8 K - 242 B 0 B 0 0 B 0 4.2 K 6 1.2 K 2 18.0 38 B - flush 3 0 B 0 0 (ingest = tables-ingested, move = ingested-as-flushable) -compact 1 2.8 K 0 B 0 (size == estimated-debt, score = in-progress-bytes, in = num-in-progress) - ctype 1 0 0 0 0 0 0 (default, delete, elision, move, read, rewrite, multi-level) - memtbl 1 256 K -zmemtbl 0 0 B - ztbl 0 0 B - bcache 0 0 B 42.9% (score == hit-rate) - tcache 0 0 B 66.7% (score == hit-rate) - snaps 0 - 0 (score == earliest seq num) - titers 0 - filter - - 0.0% (score == utility) - ingest 0 + | | | | ingested | moved | written | | amp +level | tables size val-bl | score | in | tables size | tables size | tables size | read | r w +------+---------------------+-------+-------+--------------+--------------+--------------+-------+--------- + 0 | 3 2.1KB 38B | 0.25 | 149B | 0 0B | 0 0B | 5 3.4KB | 0B | 1 23.2 + 1 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 2 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 3 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 4 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 5 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 6 | 1 639B 0B | - | 1.2KB | 0 0B | 0 0B | 1 639B | 1.2KB | 1 0.5 +total | 4 2.8KB 38B | - | 242B | 0 0B | 0 0B | 6 4.2KB | 1.2KB | 2 18.0 +----------------------------------------------------------------------------------------------------------- +WAL: 1 files (93B) in: 116B written: 242B (109% overhead) +Flushes: 3 +Compactions: 1 estimated debt: 2.8KB in progress: 0 (0B) + default: 1 delete: 0 elision: 0 move: 0 read: 0 rewrite: 0 multi-level: 0 +MemTables: 1 (256KB) zombie: 0 (0B) +Zombie tables: 0 (0B) +Block cache: 0 entries (0B) hit rate: 42.9% +Table cache: 0 entries (0B) hit rate: 66.7% +Snapshots: 0 earliest seq num: 0 +Table iters: 0 +Filter utility: 0.0% +Ingestions: 0 as flushable: 0 (0B in 0 tables) additional-metrics ---- @@ -269,28 +308,30 @@ compact a-z metrics ---- -__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp__val-bl - WAL 1 93 B - 116 B - - - - 242 B - - - 2.1 - 0 0 0 B 0.00 149 B 0 B 0 0 B 0 3.4 K 5 0 B 0 23.2 0 B - 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 0 B - 2 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 0 B - 3 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 0 B - 4 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 0 B - 5 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 0 B - 6 3 2.1 K - 3.4 K 0 B 0 0 B 0 2.1 K 3 3.4 K 1 0.6 41 B - total 3 2.1 K - 242 B 0 B 0 0 B 0 5.8 K 8 3.4 K 1 24.4 41 B - flush 3 0 B 0 0 (ingest = tables-ingested, move = ingested-as-flushable) -compact 2 0 B 0 B 0 (size == estimated-debt, score = in-progress-bytes, in = num-in-progress) - ctype 2 0 0 0 0 0 0 (default, delete, elision, move, read, rewrite, multi-level) - memtbl 1 256 K -zmemtbl 0 0 B - ztbl 0 0 B - bcache 0 0 B 27.3% (score == hit-rate) - tcache 0 0 B 58.3% (score == hit-rate) - snaps 0 - 0 (score == earliest seq num) - titers 0 - filter - - 0.0% (score == utility) - ingest 0 + | | | | ingested | moved | written | | amp +level | tables size val-bl | score | in | tables size | tables size | tables size | read | r w +------+---------------------+-------+-------+--------------+--------------+--------------+-------+--------- + 0 | 0 0B 0B | 0.00 | 149B | 0 0B | 0 0B | 5 3.4KB | 0B | 0 23.2 + 1 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 2 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 3 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 4 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 5 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 6 | 3 2.1KB 41B | - | 3.4KB | 0 0B | 0 0B | 3 2.1KB | 3.4KB | 1 0.6 +total | 3 2.1KB 41B | - | 242B | 0 0B | 0 0B | 8 5.8KB | 3.4KB | 1 24.4 +----------------------------------------------------------------------------------------------------------- +WAL: 1 files (93B) in: 116B written: 242B (109% overhead) +Flushes: 3 +Compactions: 2 estimated debt: 0B in progress: 0 (0B) + default: 2 delete: 0 elision: 0 move: 0 read: 0 rewrite: 0 multi-level: 0 +MemTables: 1 (256KB) zombie: 0 (0B) +Zombie tables: 0 (0B) +Block cache: 0 entries (0B) hit rate: 27.3% +Table cache: 0 entries (0B) hit rate: 58.3% +Snapshots: 0 earliest seq num: 0 +Table iters: 0 +Filter utility: 0.0% +Ingestions: 0 as flushable: 0 (0B in 0 tables) additional-metrics ---- @@ -359,25 +400,27 @@ flush # table). metrics ---- -__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp__val-bl - WAL 1 26 B - 176 B - - - - 175 B - - - 1.0 - 0 4 2.7 K 0.50 149 B 2.0 K 3 0 B 0 4.0 K 6 0 B 2 27.6 0 B - 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 0 B - 2 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 0 B - 3 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 0 B - 4 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 0 B - 5 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 0 B - 6 3 2.1 K - 3.4 K 0 B 0 0 B 0 2.1 K 3 3.4 K 1 0.6 41 B - total 7 4.8 K - 2.2 K 2.0 K 3 0 B 0 8.4 K 9 3.4 K 3 3.8 41 B - flush 8 2.0 K 3 2 (ingest = tables-ingested, move = ingested-as-flushable) -compact 2 4.8 K 0 B 0 (size == estimated-debt, score = in-progress-bytes, in = num-in-progress) - ctype 2 0 0 0 0 0 0 (default, delete, elision, move, read, rewrite, multi-level) - memtbl 1 1.0 M -zmemtbl 0 0 B - ztbl 0 0 B - bcache 12 2.3 K 31.1% (score == hit-rate) - tcache 3 2.3 K 57.9% (score == hit-rate) - snaps 0 - 0 (score == earliest seq num) - titers 0 - filter - - 0.0% (score == utility) - ingest 0 + | | | | ingested | moved | written | | amp +level | tables size val-bl | score | in | tables size | tables size | tables size | read | r w +------+---------------------+-------+-------+--------------+--------------+--------------+-------+--------- + 0 | 4 2.7KB 0B | 0.50 | 149B | 3 2.0KB | 0 0B | 6 4.0KB | 0B | 2 27.6 + 1 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 2 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 3 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 4 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 5 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 6 | 3 2.1KB 41B | - | 3.4KB | 0 0B | 0 0B | 3 2.1KB | 3.4KB | 1 0.6 +total | 7 4.8KB 41B | - | 2.2KB | 3 2.0KB | 0 0B | 9 8.4KB | 3.4KB | 3 3.8 +----------------------------------------------------------------------------------------------------------- +WAL: 1 files (26B) in: 176B written: 175B (-1% overhead) +Flushes: 8 +Compactions: 2 estimated debt: 4.8KB in progress: 0 (0B) + default: 2 delete: 0 elision: 0 move: 0 read: 0 rewrite: 0 multi-level: 0 +MemTables: 1 (1.0MB) zombie: 0 (0B) +Zombie tables: 0 (0B) +Block cache: 12 entries (2.3KB) hit rate: 31.1% +Table cache: 3 entries (2.3KB) hit rate: 57.9% +Snapshots: 0 earliest seq num: 0 +Table iters: 0 +Filter utility: 0.0% +Ingestions: 0 as flushable: 2 (2.0KB in 3 tables) diff --git a/tool/logs/compaction.go b/tool/logs/compaction.go index 83c08f45ae..85f354969f 100644 --- a/tool/logs/compaction.go +++ b/tool/logs/compaction.go @@ -111,11 +111,12 @@ var ( ingestedFilePatternUnitIdx = ingestedFilePattern.SubexpIndex("unit") // Example read-amp log line: - // + // 23.1 and older: // total 31766 188 G - 257 G 187 G 48 K 3.6 G 744 536 G 49 K 278 G 5 2.1 - // + // current: + // total | 1 639B 0B | - | 84B | 0 0B | 0 0B | 3 1.9KB | 1.2KB | 1 23.7 readAmpPattern = regexp.MustCompile( - /* Read-amp */ `(?:^|\+)\s{2}total.*?(?P\d+).{8}$`, + /* Read amp */ `(?:^|\+)(?:\s{2}total|total \|).*?\s(?P\d+)\s.{4,7}$`, ) readAmpPatternValueIdx = readAmpPattern.SubexpIndex("value") ) diff --git a/tool/logs/compaction_test.go b/tool/logs/compaction_test.go index 5c85e99f68..0ae969f6d7 100644 --- a/tool/logs/compaction_test.go +++ b/tool/logs/compaction_test.go @@ -24,7 +24,8 @@ const ( 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.2 M) + L3 [445853] (8.4 M) -> L3 [445883 445887] (13 M), in 0.3s, output rate 42 M/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` 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.3 M), in 0.2s, output rate 5.8 M/s` - readAmpLine = ` total 31766 188 G - 257 G 187 G 48 K 3.6 G 744 536 G 49 K 278 G 5 2.1` + 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` 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.4 M)` 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` @@ -157,6 +158,14 @@ func TestCompactionLogs_Regex(t *testing.T) { readAmpPatternValueIdx: "5", }, }, + { + name: "read amp suffix 23.1", + re: readAmpPattern, + line: readAmpLine23_1, + matches: map[int]string{ + readAmpPatternValueIdx: "5", + }, + }, } for _, tc := range tcs { @@ -171,75 +180,76 @@ func TestCompactionLogs_Regex(t *testing.T) { } func TestCompactionLogs(t *testing.T) { - var c *logEventCollector - var logNum int - resetFn := func() { - c = newEventCollector() - logNum = 0 - } - resetFn() - dir := t.TempDir() - datadriven.RunTest(t, "testdata/compactions", 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() + 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 + if err = parseLog(f.Name(), c); err != nil { + return err.Error() + } + return basename - case "summarize": - window := 1 * time.Minute - longRunning := time.Duration(math.MaxInt64) + 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)) - } + 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)) - } + 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)) + default: + panic(errors.Newf("unknown arg %q", cmdArg.Key)) + } } - } - a := newAggregator(window, longRunning, c.events, c.readAmps) - windows := a.aggregate() + a := newAggregator(window, longRunning, c.events, c.readAmps) + windows := a.aggregate() - var b bytes.Buffer - for _, w := range windows { - b.WriteString(w.String()) - } + var b bytes.Buffer + for _, w := range windows { + b.WriteString(w.String()) + } - return b.String() + return b.String() - case "reset": - resetFn() - return "" + case "reset": + resetFn() + return "" - default: - return fmt.Sprintf("unknown command %q", td.Cmd) - } + default: + return fmt.Sprintf("unknown command %q", td.Cmd) + } + }) }) } diff --git a/tool/logs/testdata/compactions b/tool/logs/testdata/compactions index ceb4928ffe..1de13a368f 100644 --- a/tool/logs/testdata/compactions +++ b/tool/logs/testdata/compactions @@ -87,27 +87,19 @@ I211215 00:00:20.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compacti log I211215 00:00:15.000000 434 kv/kvserver/store.go:3251 ⋮ [n1,s1] 31356 -__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp - WAL 1 54 M - 65 G - - - - 70 G - - - 1.1 - 0 0 0 B 0.00 70 G 77 M 133 0 B 0 24 G 19 K 4.2 G 0 0.3 - 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 2 14 34 M 0.96 18 G 0 B 0 17 M 10 49 G 14 K 55 G 1 2.7 - 3 42 207 M 0.96 12 G 0 B 0 939 M 280 43 G 7.3 K 46 G 1 3.4 - 4 264 1.5 G 0.99 9.1 G 18 M 6 824 M 152 31 G 4.5 K 35 G 1 3.4 - 5 7474 23 G 1.00 2.8 G 116 G 26 K 1.8 G 301 3.2 G 604 3.2 G 1 1.2 - 6 23972 164 G - 98 G 70 G 22 K 1.6 K 1 129 G 3.8 K 135 G 1 1.3 - total 31766 188 G - 257 G 187 G 48 K 3.6 G 744 536 G 49 K 278 G 5 2.1 -I211215 00:01:15.000000 434 kv/kvserver/store.go:3251 ⋮ [n1,s1] 31356 -__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp - WAL 1 35 M - 65 G - - - - 70 G - - - 1.1 - 0 0 0 B 0.00 70 G 77 M 133 0 B 0 24 G 19 K 4.2 G 0 0.3 - 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 2 14 34 M 0.95 18 G 0 B 0 17 M 10 49 G 14 K 55 G 1 2.7 - 3 42 207 M 0.96 12 G 0 B 0 939 M 280 43 G 7.3 K 46 G 1 3.4 - 4 264 1.5 G 0.99 9.1 G 18 M 6 824 M 152 31 G 4.5 K 35 G 1 3.4 - 5 7474 23 G 1.00 2.8 G 116 G 26 K 1.8 G 301 3.2 G 604 3.2 G 1 1.2 - 6 23972 164 G - 98 G 70 G 22 K 1.6 K 1 129 G 3.8 K 135 G 1 1.3 - total 31766 188 G - 257 G 187 G 48 K 3.6 G 744 536 G 49 K 278 G 5 2.1 + | | | | ingested | moved | written | | amp +level | tables size val-bl | score | in | tables size | tables size | tables size | read | r w +------+---------------------+-------+-------+--------------+--------------+--------------+-------+--------- + 0 | 0 0B 0B | 0.00 | 70GB | 133 77MB | 0 0B | 19K 24GB | 4.2GB | 0 0.3 + 1 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 2 | 14 34MB 0B | 0.96 | 18GB | 0 0B | 10 17MB | 14K 49GB | 55GB | 1 2.7 + 3 | 42 207MB 0B | 0.96 | 12GB | 0 0B | 280 939MB | 7.3K 43GB | 46GB | 1 3.4 + 4 | 264 1.5GB 0B | 0.99 | 9.1GB | 6 18MB | 152 824MB | 4.5K 31GB | 35GB | 1 3.4 + 5 | 7.5K 23GB 0B | 1.00 | 2.8GB | 26K 116GB | 301 1.8GB | 604 3.2GB | 3.2GB | 1 1.2 + 6 | 24K 164GB 0B | - | 98GB | 22K 70GB | 1 1.6KB | 3.8K 128GB | 135GB | 1 1.3 +total | 32K 188GB 0B | - | 257GB | 48K 187GB | 744 3.6GB | 49K 536GB | 278GB | 5 2.1 +----------------------------------------------------------------------------------------------------------- +WAL: 1 files (54MB) in: 65GB written: 70B (8% overhead) ---- 1.log @@ -278,16 +270,19 @@ I211215 00:01:20.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compacti log I211215 00:01:15.000000 434 kv/kvserver/store.go:3251 ⋮ [n?,s?] 31356 -__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp - WAL 1 54 M - 65 G - - - - 70 G - - - 1.1 - 0 0 0 B 0.00 70 G 77 M 133 0 B 0 24 G 19 K 4.2 G 0 0.3 - 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 2 14 34 M 0.96 18 G 0 B 0 17 M 10 49 G 14 K 55 G 1 2.7 - 3 42 207 M 0.96 12 G 0 B 0 939 M 280 43 G 7.3 K 46 G 1 3.4 - 4 264 1.5 G 0.99 9.1 G 18 M 6 824 M 152 31 G 4.5 K 35 G 1 3.4 - 5 7474 23 G 1.00 2.8 G 116 G 26 K 1.8 G 301 3.2 G 604 3.2 G 1 1.2 - 6 23972 164 G - 98 G 70 G 22 K 1.6 K 1 129 G 3.8 K 135 G 1 1.3 - total 31766 188 G - 257 G 187 G 48 K 3.6 G 744 536 G 49 K 278 G 5 2.1 + | | | | ingested | moved | written | | amp +level | tables size val-bl | score | in | tables size | tables size | tables size | read | r w +------+---------------------+-------+-------+--------------+--------------+--------------+-------+--------- + 0 | 0 0B 0B | 0.00 | 70GB | 133 77MB | 0 0B | 19K 24GB | 4.2GB | 0 0.3 + 1 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 2 | 14 34MB 0B | 0.96 | 18GB | 0 0B | 10 17MB | 14K 49GB | 55GB | 1 2.7 + 3 | 42 207MB 0B | 0.96 | 12GB | 0 0B | 280 939MB | 7.3K 43GB | 46GB | 1 3.4 + 4 | 264 1.5GB 0B | 0.99 | 9.1GB | 6 18MB | 152 824MB | 4.5K 31GB | 35GB | 1 3.4 + 5 | 7.5K 23GB 0B | 1.00 | 2.8GB | 26K 116GB | 301 1.8GB | 604 3.2GB | 3.2GB | 1 1.2 + 6 | 24K 164GB 0B | - | 98GB | 22K 70GB | 1 1.6KB | 3.8K 128GB | 135GB | 1 1.3 +total | 32K 188GB 0B | - | 257GB | 48K 187GB | 744 3.6GB | 49K 536GB | 278GB | 5 2.1 +----------------------------------------------------------------------------------------------------------- +WAL: 1 files (54MB) in: 65GB written: 70B (8% overhead) ---- 1.log @@ -348,25 +343,30 @@ I220301 00:00:30.000000 200 kv/kvserver/stores.go:269 ⋮ [n1] 75 wrote 0 node I220301 00:00:30.000000 319 2@server/status/runtime.go:569 ⋮ [n1] 76 runtime stats: 154 MiB RSS, 273 goroutines (stacks: 2.5 MiB), 42 MiB/71 MiB Go alloc/total (heap fragmentation: 11 MiB, heap reserved: 3.9 MiB, heap released: 4.2 MiB), 3.2 MiB/5.6 MiB CGO alloc/total (0.0 CGO/sec), 0.0/0.0 %(u/s)time, 0.0 %gc (0x), 425 KiB/500 KiB (r/w)net I220301 00:00:30.000000 319 2@server/status/runtime.go:569 ⋮ [n1] 77 runtime stats: 159 MiB RSS, 266 goroutines (stacks: 3.3 MiB), 42 MiB/78 MiB Go alloc/total (heap fragmentation: 12 MiB, heap reserved: 6.7 MiB, heap released: 64 MiB), 4.4 MiB/6.8 MiB CGO alloc/total (0.4 CGO/sec), 2.9/2.1 %(u/s)time, 0.0 %gc (0x), 335 KiB/323 KiB (r/w)net I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 -I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 +__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp -I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + WAL 3 779 K - 773 K - - - - 779 K - - - 1.0 -I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + 0 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 -I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 -I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + 2 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 -I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + 3 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 -I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + 4 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 -I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + 5 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 -I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + 6 0 0 B - 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 -I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + total 0 0 B - 779 K 0 B 0 0 B 0 779 K 0 0 B 1 1.0 -I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + flush 0 -I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 +compact 0 0 B 0 B (size == estimated-debt, in = in-progress-bytes) -I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + memtbl 3 1.8 M -I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 +zmemtbl 0 0 B -I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + ztbl 0 0 B -I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + bcache 0 0 B 0.0% (score == hit-rate) -I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + tcache 0 0 B 0.0% (score == hit-rate) -I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + titers 0 -I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + filter - - 0.0% (score == utility) +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + | | | | ingested | moved | written | | amp +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 +level | tables size val-bl | score | in | tables size | tables size | tables size | read | r w +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 +------+---------------------+-------+-------+--------------+--------------+--------------+-------+--------- +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + 0 | 0 0B 0B | 0.00 | 56B | 0 0B | 0 0B | 2 1.2KB | 0B | 0 22.6 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + 1 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + 2 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + 3 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + 4 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + 5 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + 6 | 1 639B 0B | - | 1.2KB | 0 0B | 0 0B | 1 639B | 1.2KB | 1 0.5 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 +total | 1 639B 0B | - | 84B | 0 0B | 0 0B | 3 1.9KB | 1.2KB | 1 23.7 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 +----------------------------------------------------------------------------------------------------------- +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 +WAL: 1 files (28B) in: 34B written: 84B (147% overhead) +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 +Flushes: 2 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 +Compactions: 1 estimated debt: 0B in progress: 0 (0B) +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + default: 1 delete: 0 elision: 0 move: 0 read: 0 rewrite: 0 multi-level: 0 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 +MemTables: 1 (256KB) zombie: 2 (512KB) +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 +Zombie tables: 2 (1.2KB) +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 +Block cache: 5 entries (1.0KB) hit rate: 42.9% +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 +Table cache: 2 entries (1.6KB) hit rate: 66.7% +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 +Snapshots: 0 earliest seq num: 0 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 +Table iters: 2 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 +Filter utility: 0.0% +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 +Ingestions: 0 as flushable: 0 (0B in 0 tables) ---- 1.log diff --git a/tool/logs/testdata/compactions-23-1 b/tool/logs/testdata/compactions-23-1 new file mode 100644 index 0000000000..ceb4928ffe --- /dev/null +++ b/tool/logs/testdata/compactions-23-1 @@ -0,0 +1,478 @@ +# Single compaction and flush pair for a single node / store combination. +# +# Use a combination of [n1,pebble,s1] and [n1,s1,pebble] to mimic the two +# formats we see in production. + + +log +I211215 00:00:10.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [n1,pebble,s1] 1216510 [JOB 1] compacting(default) L2 [442555] (4.2 M) + L3 [445853] (8.4 M) +I211215 00:00:20.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1886 ⋮ [n1,s1,pebble] 1216554 [JOB 1] 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 + +I211215 00:01:10.000000 21136 3@vendor/github.com/cockroachdb/pebble/event.go:599 ⋮ [n1,s1,pebble] 24 [JOB 2] flushing 2 memtables to L0 +I211215 00:01:20.000000 21136 3@vendor/github.com/cockroachdb/pebble/event.go:603 ⋮ [n1,pebble,s1] 26 [JOB 2] flushed 2 memtables to L0 [1535806] (1.3 M), in 0.2s, output rate 5.8 M/s +---- +0.log + +summarize +---- +node: 1, store: 1 + from: 211215 00:00 + to: 211215 00:01 + r-amp: NaN +_kind______from______to___default____move___elide__delete___count___in(B)__out(B)__mov(B)__del(B)______time +compact L2 L3 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +total 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +node: 1, store: 1 + from: 211215 00:01 + to: 211215 00:02 + r-amp: NaN +_kind______from______to_____________________________________count___bytes______time +flush L0 1 1.0 M 10s +total 1 1.0 M 10s + +# Same as the previous case, except that the start and end events are are split +# across multiple files (one log line per file). + +reset +---- + +log +I211215 00:00:10.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [n1,bars,s1,foos] 1216510 [JOB 1] compacting(default) L2 [442555] (4.2 M) + L3 [445853] (8.4 M) +---- +0.log + +log +I211215 00:00:20.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1886 ⋮ [n1,s1,foos] 1216554 [JOB 1] 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 +---- +1.log + +log +I211215 00:01:10.000000 21136 3@vendor/github.com/cockroachdb/pebble/event.go:599 ⋮ [n1,s1] 24 [JOB 2] flushing 2 memtables to L0 +---- +2.log + +log +I211215 00:01:20.000000 21136 3@vendor/github.com/cockroachdb/pebble/event.go:603 ⋮ [n1,pebble,s1] 26 [JOB 2] flushed 2 memtables to L0 [1535806] (1.3 M), in 0.2s, output rate 5.8 M/s +---- +3.log + +summarize +---- +node: 1, store: 1 + from: 211215 00:00 + to: 211215 00:01 + r-amp: NaN +_kind______from______to___default____move___elide__delete___count___in(B)__out(B)__mov(B)__del(B)______time +compact L2 L3 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +total 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +node: 1, store: 1 + from: 211215 00:01 + to: 211215 00:02 + r-amp: NaN +_kind______from______to_____________________________________count___bytes______time +flush L0 1 1.0 M 10s +total 1 1.0 M 10s + +# Read amplification from the Cockroach log, one within an existing window, +# another outside of the existing window. The latter is not included. + +reset +---- + +log +I211215 00:00:10.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [n1,pebble,s1] 1216510 [JOB 1] compacting(default) L2 [442555] (4.2 M) + L3 [445853] (8.4 M) +I211215 00:00:20.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1886 ⋮ [n1,pebble,s1] 1216554 [JOB 1] 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 +---- +0.log + +log +I211215 00:00:15.000000 434 kv/kvserver/store.go:3251 ⋮ [n1,s1] 31356 +__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp + WAL 1 54 M - 65 G - - - - 70 G - - - 1.1 + 0 0 0 B 0.00 70 G 77 M 133 0 B 0 24 G 19 K 4.2 G 0 0.3 + 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 + 2 14 34 M 0.96 18 G 0 B 0 17 M 10 49 G 14 K 55 G 1 2.7 + 3 42 207 M 0.96 12 G 0 B 0 939 M 280 43 G 7.3 K 46 G 1 3.4 + 4 264 1.5 G 0.99 9.1 G 18 M 6 824 M 152 31 G 4.5 K 35 G 1 3.4 + 5 7474 23 G 1.00 2.8 G 116 G 26 K 1.8 G 301 3.2 G 604 3.2 G 1 1.2 + 6 23972 164 G - 98 G 70 G 22 K 1.6 K 1 129 G 3.8 K 135 G 1 1.3 + total 31766 188 G - 257 G 187 G 48 K 3.6 G 744 536 G 49 K 278 G 5 2.1 +I211215 00:01:15.000000 434 kv/kvserver/store.go:3251 ⋮ [n1,s1] 31356 +__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp + WAL 1 35 M - 65 G - - - - 70 G - - - 1.1 + 0 0 0 B 0.00 70 G 77 M 133 0 B 0 24 G 19 K 4.2 G 0 0.3 + 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 + 2 14 34 M 0.95 18 G 0 B 0 17 M 10 49 G 14 K 55 G 1 2.7 + 3 42 207 M 0.96 12 G 0 B 0 939 M 280 43 G 7.3 K 46 G 1 3.4 + 4 264 1.5 G 0.99 9.1 G 18 M 6 824 M 152 31 G 4.5 K 35 G 1 3.4 + 5 7474 23 G 1.00 2.8 G 116 G 26 K 1.8 G 301 3.2 G 604 3.2 G 1 1.2 + 6 23972 164 G - 98 G 70 G 22 K 1.6 K 1 129 G 3.8 K 135 G 1 1.3 + total 31766 188 G - 257 G 187 G 48 K 3.6 G 744 536 G 49 K 278 G 5 2.1 +---- +1.log + +summarize +---- +node: 1, store: 1 + from: 211215 00:00 + to: 211215 00:01 + r-amp: 5.0 +_kind______from______to___default____move___elide__delete___count___in(B)__out(B)__mov(B)__del(B)______time +compact L2 L3 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +total 1 0 0 0 1 12 M 13 M 0 B 0 B 10s + +# Long running compaction. + +reset +---- + +log +I211215 00:01:10.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [n1,s1,pebble] 1216510 [JOB 1] compacting(default) L2 [442555] (4.2 M) + L3 [445853] (8.4 M) +I211215 00:03:20.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1886 ⋮ [n1,pebble,s1] 1216554 [JOB 1] 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 +---- +0.log + +summarize long-running=1m +---- +node: 1, store: 1 + from: 211215 00:01 + to: 211215 00:02 + r-amp: NaN +_kind______from______to___default____move___elide__delete___count___in(B)__out(B)__mov(B)__del(B)______time +compact L2 L3 1 0 0 0 1 12 M 13 M 0 B 0 B 2m10s +total 1 0 0 0 1 12 M 13 M 0 B 0 B 2m10s +long-running events (descending runtime): +_kind________from________to_______job______type_____start_______end____dur(s)_____bytes: +compact L2 L3 1 default 00:01:10 00:03:20 130 13 M + +# Single node, multiple stores. + +reset +---- + +log +I211215 00:01:10.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [n1,pebble,s1] 1216510 [JOB 1] compacting(default) L2 [442555] (4.2 M) + L3 [445853] (8.4 M) +I211215 00:01:20.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1886 ⋮ [n1,pebble,s1] 1216554 [JOB 1] 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 + +I211215 00:01:10.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [n1,pebble,s2] 1216510 [JOB 2] compacting(default) L3 [442555] (4.2 M) + L4 [445853] (8.4 M) +I211215 00:01:20.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1886 ⋮ [n1,pebble,s2] 1216554 [JOB 2] compacted(default) L3 [442555] (4.2 M) + L4 [445853] (8.4 M) -> L4 [445883 445887] (13 M), in 0.3s, output rate 42 M/s +---- +0.log + +summarize +---- +node: 1, store: 1 + from: 211215 00:01 + to: 211215 00:02 + r-amp: NaN +_kind______from______to___default____move___elide__delete___count___in(B)__out(B)__mov(B)__del(B)______time +compact L2 L3 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +total 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +node: 1, store: 2 + from: 211215 00:01 + to: 211215 00:02 + r-amp: NaN +_kind______from______to___default____move___elide__delete___count___in(B)__out(B)__mov(B)__del(B)______time +compact L3 L4 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +total 1 0 0 0 1 12 M 13 M 0 B 0 B 10s + +# Multiple nodes, single stores. Two separate pebble logs. + +reset +---- + +log +I211215 00:01:10.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [n1,pebble,s1] 1216510 [JOB 1] compacting(default) L2 [442555] (4.2 M) + L3 [445853] (8.4 M) +I211215 00:01:20.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1886 ⋮ [n1,pebble,s1] 1216554 [JOB 1] 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 +---- +0.log + +log +I211215 00:01:10.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [n2,pebble,s1] 1216510 [JOB 1] compacting(default) L3 [442555] (4.2 M) + L4 [445853] (8.4 M) +I211215 00:01:20.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1886 ⋮ [n2,pebble,s1] 1216554 [JOB 1] compacted(default) L3 [442555] (4.2 M) + L4 [445853] (8.4 M) -> L4 [445883 445887] (13 M), in 0.3s, output rate 42 M/s +---- +1.log + +summarize +---- +node: 1, store: 1 + from: 211215 00:01 + to: 211215 00:02 + r-amp: NaN +_kind______from______to___default____move___elide__delete___count___in(B)__out(B)__mov(B)__del(B)______time +compact L2 L3 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +total 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +node: 2, store: 1 + from: 211215 00:01 + to: 211215 00:02 + r-amp: NaN +_kind______from______to___default____move___elide__delete___count___in(B)__out(B)__mov(B)__del(B)______time +compact L3 L4 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +total 1 0 0 0 1 12 M 13 M 0 B 0 B 10s + +# Multiple nodes, multiple stores. Two separate pebble logs. Output is sorted by +# (time, node, store). + +reset +---- + +log +I211215 00:01:10.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [n1,pebble,s1] 1216510 [JOB 1] compacting(default) L2 [442555] (4.2 M) + L3 [445853] (8.4 M) +I211215 00:01:20.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1886 ⋮ [n1,pebble,s1] 1216554 [JOB 1] 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 + +I211215 00:02:10.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [n1,pebble,s2] 1216510 [JOB 2] compacting(default) L1 [442555] (4.2 M) + L2 [445853] (8.4 M) +I211215 00:02:20.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1886 ⋮ [n1,pebble,s2] 1216554 [JOB 2] compacted(default) L1 [442555] (4.2 M) + L2 [445853] (8.4 M) -> L2 [445883 445887] (13 M), in 0.3s, output rate 42 M/s +---- +0.log + +log +I211215 00:00:10.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [n2,pebble,s1] 1216510 [JOB 1] compacting(default) L3 [442555] (4.2 M) + L4 [445853] (8.4 M) +I211215 00:00:20.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1886 ⋮ [n2,pebble,s1] 1216554 [JOB 1] compacted(default) L3 [442555] (4.2 M) + L4 [445853] (8.4 M) -> L4 [445883 445887] (13 M), in 0.3s, output rate 42 M/s + +I211215 00:02:10.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [n2,pebble,s2] 1216510 [JOB 2] compacting(default) L4 [442555] (4.2 M) + L5 [445853] (8.4 M) +I211215 00:02:20.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1886 ⋮ [n2,pebble,s2] 1216554 [JOB 2] compacted(default) L4 [442555] (4.2 M) + L5 [445853] (8.4 M) -> L5 [445883 445887] (13 M), in 0.3s, output rate 42 M/s +---- +1.log + +summarize +---- +node: 2, store: 1 + from: 211215 00:00 + to: 211215 00:01 + r-amp: NaN +_kind______from______to___default____move___elide__delete___count___in(B)__out(B)__mov(B)__del(B)______time +compact L3 L4 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +total 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +node: 1, store: 1 + from: 211215 00:01 + to: 211215 00:02 + r-amp: NaN +_kind______from______to___default____move___elide__delete___count___in(B)__out(B)__mov(B)__del(B)______time +compact L2 L3 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +total 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +node: 1, store: 2 + from: 211215 00:02 + to: 211215 00:03 + r-amp: NaN +_kind______from______to___default____move___elide__delete___count___in(B)__out(B)__mov(B)__del(B)______time +compact L1 L2 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +total 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +node: 2, store: 2 + from: 211215 00:02 + to: 211215 00:03 + r-amp: NaN +_kind______from______to___default____move___elide__delete___count___in(B)__out(B)__mov(B)__del(B)______time +compact L4 L5 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +total 1 0 0 0 1 12 M 13 M 0 B 0 B 10s + +# Log lines with an absent node / store are aggregated. + +reset +---- + +log +I211215 00:01:10.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [n?,pebble,s?] 1216510 [JOB 1] compacting(default) L2 [442555] (4.2 M) + L3 [445853] (8.4 M) +I211215 00:01:20.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1886 ⋮ [n?,pebble,s?] 1216554 [JOB 1] 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 +---- +0.log + +log +I211215 00:01:15.000000 434 kv/kvserver/store.go:3251 ⋮ [n?,s?] 31356 +__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp + WAL 1 54 M - 65 G - - - - 70 G - - - 1.1 + 0 0 0 B 0.00 70 G 77 M 133 0 B 0 24 G 19 K 4.2 G 0 0.3 + 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 + 2 14 34 M 0.96 18 G 0 B 0 17 M 10 49 G 14 K 55 G 1 2.7 + 3 42 207 M 0.96 12 G 0 B 0 939 M 280 43 G 7.3 K 46 G 1 3.4 + 4 264 1.5 G 0.99 9.1 G 18 M 6 824 M 152 31 G 4.5 K 35 G 1 3.4 + 5 7474 23 G 1.00 2.8 G 116 G 26 K 1.8 G 301 3.2 G 604 3.2 G 1 1.2 + 6 23972 164 G - 98 G 70 G 22 K 1.6 K 1 129 G 3.8 K 135 G 1 1.3 + total 31766 188 G - 257 G 187 G 48 K 3.6 G 744 536 G 49 K 278 G 5 2.1 +---- +1.log + +summarize +---- +node: ?, store: ? + from: 211215 00:01 + to: 211215 00:02 + r-amp: 5.0 +_kind______from______to___default____move___elide__delete___count___in(B)__out(B)__mov(B)__del(B)______time +compact L2 L3 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +total 1 0 0 0 1 12 M 13 M 0 B 0 B 10s + +# The same Job ID interleaved for multiple nodes / stores. + +reset +---- + +log +I211215 00:01:10.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [n1,pebble,s1] 1216510 [JOB 1] compacting(default) L2 [442555] (4.2 M) + L3 [445853] (8.4 M) +I211215 00:02:10.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [n2,pebble,s2] 1216510 [JOB 1] compacting(default) L4 [442555] (4.2 M) + L5 [445853] (8.4 M) +I211215 00:01:20.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1886 ⋮ [n1,pebble,s1] 1216554 [JOB 1] 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 +I211215 00:02:20.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1886 ⋮ [n2,pebble,s2] 1216554 [JOB 1] compacted(default) L4 [442555] (4.2 M) + L5 [445853] (8.4 M) -> L5 [445883 445887] (13 M), in 0.3s, output rate 42 M/s +---- +0.log + +summarize +---- +node: 1, store: 1 + from: 211215 00:01 + to: 211215 00:02 + r-amp: NaN +_kind______from______to___default____move___elide__delete___count___in(B)__out(B)__mov(B)__del(B)______time +compact L2 L3 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +total 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +node: 2, store: 2 + from: 211215 00:02 + to: 211215 00:03 + r-amp: NaN +_kind______from______to___default____move___elide__delete___count___in(B)__out(B)__mov(B)__del(B)______time +compact L4 L5 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +total 1 0 0 0 1 12 M 13 M 0 B 0 B 10s + +# Read amp matching should remain backwards compatible. + +reset +---- + +log +I220301 00:00:10.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1845 ⋮ [n1,pebble,s1] 1216510 [JOB 1] compacting(default) L2 [442555] (4.2 M) + L3 [445853] (8.4 M) +I220301 00:00:20.000000 51831533 3@vendor/github.com/cockroachdb/pebble/compaction.go:1886 ⋮ [n1,pebble,s1] 1216554 [JOB 1] 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 +---- +0.log + +log +I220301 00:00:30.000000 200 1@gossip/gossip.go:1500 ⋮ [n1] 74 node has connected to cluster via gossip +I220301 00:00:30.000000 200 kv/kvserver/stores.go:269 ⋮ [n1] 75 wrote 0 node addresses to persistent storage +I220301 00:00:30.000000 319 2@server/status/runtime.go:569 ⋮ [n1] 76 runtime stats: 154 MiB RSS, 273 goroutines (stacks: 2.5 MiB), 42 MiB/71 MiB Go alloc/total (heap fragmentation: 11 MiB, heap reserved: 3.9 MiB, heap released: 4.2 MiB), 3.2 MiB/5.6 MiB CGO alloc/total (0.0 CGO/sec), 0.0/0.0 %(u/s)time, 0.0 %gc (0x), 425 KiB/500 KiB (r/w)net +I220301 00:00:30.000000 319 2@server/status/runtime.go:569 ⋮ [n1] 77 runtime stats: 159 MiB RSS, 266 goroutines (stacks: 3.3 MiB), 42 MiB/78 MiB Go alloc/total (heap fragmentation: 12 MiB, heap reserved: 6.7 MiB, heap released: 64 MiB), 4.4 MiB/6.8 MiB CGO alloc/total (0.4 CGO/sec), 2.9/2.1 %(u/s)time, 0.0 %gc (0x), 335 KiB/323 KiB (r/w)net +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 +__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + WAL 3 779 K - 773 K - - - - 779 K - - - 1.0 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + 0 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + 2 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + 3 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + 4 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + 5 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + 6 0 0 B - 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + total 0 0 B - 779 K 0 B 0 0 B 0 779 K 0 0 B 1 1.0 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + flush 0 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 +compact 0 0 B 0 B (size == estimated-debt, in = in-progress-bytes) +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + memtbl 3 1.8 M +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 +zmemtbl 0 0 B +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + ztbl 0 0 B +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + bcache 0 0 B 0.0% (score == hit-rate) +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + tcache 0 0 B 0.0% (score == hit-rate) +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + titers 0 +I220301 00:00:30.000000 315 kv/kvserver/store.go:2713 ⋮ [n1,s1] 78 + filter - - 0.0% (score == utility) +---- +1.log + +summarize +---- +node: 1, store: 1 + from: 220301 00:00 + to: 220301 00:01 + r-amp: 1.0 +_kind______from______to___default____move___elide__delete___count___in(B)__out(B)__mov(B)__del(B)______time +compact L2 L3 1 0 0 0 1 12 M 13 M 0 B 0 B 10s +total 1 0 0 0 1 12 M 13 M 0 B 0 B 10s + +reset +---- + +log +I220228 14:44:31.497272 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1366 ⋮ [n24,pebble,s24] 33267888 [JOB 10197855] flushing 1 memtable to L0 +I220228 14:44:31.497485 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267889 [JOB 10197855] flushing: sstable created 21731018 +I220228 14:44:31.527038 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267892 [JOB 10197855] flushing: sstable created 21731020 +I220228 14:44:31.542944 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267894 [JOB 10197855] flushing: sstable created 21731021 +I220228 14:44:31.553581 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267895 [JOB 10197855] flushing: sstable created 21731022 +I220228 14:44:31.554585 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267896 [JOB 10197855] flushing: sstable created 21731023 +I220228 14:44:31.569928 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267897 [JOB 10197855] flushing: sstable created 21731024 +I220228 14:44:31.624309 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267899 [JOB 10197855] flushing: sstable created 21731025 +I220228 14:44:31.685531 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267901 [JOB 10197855] flushing: sstable created 21731026 +I220228 14:44:31.686009 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267902 [JOB 10197855] flushing: sstable created 21731027 +I220228 14:44:31.686415 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267903 [JOB 10197855] flushing: sstable created 21731028 +I220228 14:44:31.780892 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267906 [JOB 10197855] flushing: sstable created 21731030 +I220228 14:44:31.790911 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267907 [JOB 10197855] flushing: sstable created 21731031 +I220228 14:44:31.904614 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267911 [JOB 10197855] flushing: sstable created 21731033 +I220228 14:44:31.905835 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267912 [JOB 10197855] flushing: sstable created 21731034 +I220228 14:44:31.906860 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267913 [JOB 10197855] flushing: sstable created 21731035 +I220228 14:44:31.907602 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267914 [JOB 10197855] flushing: sstable created 21731036 +I220228 14:44:32.019173 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267920 [JOB 10197855] flushing: sstable created 21731037 +I220228 14:44:32.019714 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267921 [JOB 10197855] flushing: sstable created 21731038 +I220228 14:44:32.020161 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267922 [JOB 10197855] flushing: sstable created 21731039 +I220228 14:44:32.100117 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267925 [JOB 10197855] flushing: sstable created 21731040 +I220228 14:44:32.100609 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267926 [JOB 10197855] flushing: sstable created 21731041 +I220228 14:44:32.101065 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267927 [JOB 10197855] flushing: sstable created 21731042 +I220228 14:44:32.101494 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267928 [JOB 10197855] flushing: sstable created 21731043 +I220228 14:44:32.102569 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267929 [JOB 10197855] flushing: sstable created 21731044 +I220228 14:44:32.106284 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1985 ⋮ [n24,pebble,s24] 33267930 [JOB 10197855] flushing: sstable created 21731045 +I220228 14:44:32.138686 18460916022 3@vendor/github.com/cockroachdb/pebble/compaction.go:1423 ⋮ [n24,pebble,s24] 33267931 [JOB 10197855] flushed 1 memtable to L0 [21731018 21731020 21731021 21731022 21731023 21731024 21731025 21731026 21731027 21731028 21731030 21731031 21731033 21731034 21731035 21731036 21731037 21731038 21731039 21731040 21731041 21731042 21731043 21731044 21731045] (19 M), in 0.6s, output rate 31 M/s +---- +0.log + +summarize +---- +node: 24, store: 24 + from: 220228 14:44 + to: 220228 14:45 + r-amp: NaN +_kind______from______to_____________________________________count___bytes______time +flush L0 1 19 M 0s +total 1 19 M 0s + +reset +---- + +log +I220228 16:01:22.487906 18476248525 3@vendor/github.com/cockroachdb/pebble/ingest.go:637 ⋮ [n24,pebble,s24] 33430782 [JOB 10211226] ingested L0:21818678 (1.8 K), L0:21818683 (1.2 K), L0:21818679 (1.6 K), L0:21818680 (1.1 K), L0:21818681 (1.1 K), L0:21818682 (160 M) +45127:I220228 15:58:45.538681 18475981755 3@vendor/github.com/cockroachdb/pebble/ingest.go:637 ⋮ [n24,pebble,s24] 33424719 [JOB 10210743] ingested L0:21814543 (1.4 K), L0:21814548 (1.2 K), L5:21814544 (1.4 K), L5:21814545 (1.1 K), L5:21814546 (1.1 K), L0:21814547 (140 M) +---- +0.log + +summarize +---- +node: 24, store: 24 + from: 220228 15:58 + to: 220228 15:59 + r-amp: NaN +_kind______from______to_____________________________________count___bytes______time +ingest L0 9 140 M +ingest L5 3 3.0 K +total 12 140 M 0s +node: 24, store: 24 + from: 220228 16:01 + to: 220228 16:02 + r-amp: NaN +_kind______from______to_____________________________________count___bytes______time +ingest L0 12 160 M +total 12 160 M 0s + +reset +---- + +log +I220907 00:27:21.579807 15082709999 3@vendor/github.com/cockroachdb/pebble/event.go:587 ⋮ [n15,pebble,s15] 2736197 [JOB 743692] compacting(delete-only) L6 [18323385] (11 M) +I220907 00:27:21.580169 15082709999 3@vendor/github.com/cockroachdb/pebble/event.go:591 ⋮ [n15,pebble,s15] 2736198 [JOB 743692] compacted(delete-only) L6 [18323385] (11 M) -> L6 [] (0 B), in 0.0s, output rate 0 B/s + +I220907 00:27:21.631145 15082710355 3@vendor/github.com/cockroachdb/pebble/event.go:587 ⋮ [n15,pebble,s15] 2736201 [JOB 743694] compacting(default) L5 [18323582] (1.8 K) + L6 [17770912] (128 M) +I220907 00:27:22.729839 15082710355 3@vendor/github.com/cockroachdb/pebble/event.go:591 ⋮ [n15,pebble,s15] 2736208 [JOB 743694] compacted(default) L5 [18323582] (1.8 K) + L6 [17770912] (128 M) -> L6 [18323586] (3.6 M), in 1.1s, output rate 3.3 M/s + +I220907 00:27:21.630546 15082710354 3@vendor/github.com/cockroachdb/pebble/event.go:587 ⋮ [n15,pebble,s15] 2736199 [JOB 743693] compacting(move) L5 [18323585] (4.0 M) + L6 [] (0 B) +I220907 00:27:21.631002 15082710354 3@vendor/github.com/cockroachdb/pebble/event.go:591 ⋮ [n15,pebble,s15] 2736200 [JOB 743693] compacted(move) L5 [18323585] (4.0 M) + L6 [] (0 B) -> L6 [18323585] (4.0 M), in 0.0s, output rate 50 G/s +---- +0.log + +summarize +---- +node: 15, store: 15 + from: 220907 00:27 + to: 220907 00:28 + r-amp: NaN +_kind______from______to___default____move___elide__delete___count___in(B)__out(B)__mov(B)__del(B)______time +compact L5 L6 1 1 0 0 2 128 M 3.0 M 4.0 M 0 B 1s +compact L6 L6 0 0 0 1 1 0 B 0 B 0 B 11 M 0s +total 1 1 0 1 3 128 M 3.0 M 4.0 M 11 M 1s diff --git a/tool/testdata/db_lsm b/tool/testdata/db_lsm index cca58ab774..5981049e63 100644 --- a/tool/testdata/db_lsm +++ b/tool/testdata/db_lsm @@ -10,25 +10,27 @@ pebble: database "non-existent" does not exist db lsm ../testdata/db-stage-4 ---- -__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp - WAL 1 0 B - 0 B - - - - 0 B - - - 0.0 - 0 1 986 B 0.50 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 2 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 3 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 4 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 5 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - 6 0 0 B - 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - total 1 986 B - 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0 - flush 0 0 B 0 0 (ingest = tables-ingested, move = ingested-as-flushable) -compact 0 0 B 0 B 0 (size == estimated-debt, score = in-progress-bytes, in = num-in-progress) - ctype 0 0 0 0 0 0 0 (default, delete, elision, move, read, rewrite, multi-level) - memtbl 1 256 K -zmemtbl 0 0 B - ztbl 0 0 B - bcache 0 0 B 0.0% (score == hit-rate) - tcache 0 0 B 0.0% (score == hit-rate) - snaps 0 - 0 (score == earliest seq num) - titers 0 - filter - - 0.0% (score == utility) - ingest 0 + | | | | ingested | moved | written | | amp +level | tables size val-bl | score | in | tables size | tables size | tables size | read | r w +------+---------------------+-------+-------+--------------+--------------+--------------+-------+--------- + 0 | 1 986B 0B | 0.50 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 1 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 2 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 3 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 4 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 5 | 0 0B 0B | 0.00 | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 + 6 | 0 0B 0B | - | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 +total | 1 986B 0B | - | 0B | 0 0B | 0 0B | 0 0B | 0B | 0 0.0 +----------------------------------------------------------------------------------------------------------- +WAL: 1 files (0B) in: 0B written: 0B (0% overhead) +Flushes: 0 +Compactions: 0 estimated debt: 0B in progress: 0 (0B) + default: 0 delete: 0 elision: 0 move: 0 read: 0 rewrite: 0 multi-level: 0 +MemTables: 1 (256KB) zombie: 0 (0B) +Zombie tables: 0 (0B) +Block cache: 0 entries (0B) hit rate: 0.0% +Table cache: 0 entries (0B) hit rate: 0.0% +Snapshots: 0 earliest seq num: 0 +Table iters: 0 +Filter utility: 0.0% +Ingestions: 0 as flushable: 0 (0B in 0 tables)