Skip to content

Commit

Permalink
db: introduce TotalDuration to FlushInfo and CompactionInfo events
Browse files Browse the repository at this point in the history 
When a compaction or flush completes, we emit a CompactionEnd or FlushEnd
event. When configured with the logging event listener, these durations are
written to logs.

Previously, these events only contained 1 duration recording the time elapsed
during reading and writing sstables, but it did not include the time to write
the version edit to the manifest or construct the new in-memory representation
of the Version.  With a sufficiently large number of files in L0, this work at
the end of a compaction can be expensive. This change introduces a
TotalDuration field, computed just before the event is emitted. This field
ensures Pebble logs a comprehensive record of the end-to-end wall-time duration
of a compaction too.
  • Loading branch information
@jbowens
jbowens committed Dec 13, 2021
1 parent 6c6ca21 commit cf6c474
Show file tree
Hide file tree
Showing 6 changed files with 39 additions and 22 deletions.
4 changes: 4 additions & 0 deletions compaction.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1532,6 +1532,8 @@ func (d *DB) flush1() error {
d.removeInProgressCompaction(c)
d.mu.versions.incrementCompactions(c.kind)
d.mu.versions.incrementCompactionBytes(-c.bytesWritten)

info.TotalDuration = d.timeNow().Sub(startTime)
d.opts.EventListener.FlushEnd(info)

// Refresh bytes flushed count.
Expand Down Expand Up @@ -1955,6 +1957,8 @@ func (d *DB) compact1(c *compaction, errChannel chan error) (err error) {
d.removeInProgressCompaction(c)
d.mu.versions.incrementCompactions(c.kind)
d.mu.versions.incrementCompactionBytes(-c.bytesWritten)

info.TotalDuration = d.timeNow().Sub(startTime)
d.opts.EventListener.CompactionEnd(info)

// Update the read state before deleting obsolete files because the
Expand Down
29 changes: 21 additions & 8 deletions event.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -61,10 +61,16 @@ type CompactionInfo struct {
Input []LevelInfo
// Output contains the output tables generated by the compaction. The output
// tables are empty for the compaction begin event.
Output LevelInfo
Output LevelInfo
// Duration is the time spent compacting, including reading and writing
// sstables.
Duration time.Duration
Done bool
Err error
// TotalDuration is the total wall-time duration of the compaction,
// including applying the compaction to the database. TotalDuration is
// always ≥ Duration.
TotalDuration time.Duration
Done bool
Err error
}

func (i CompactionInfo) String() string {
Expand All @@ -87,11 +93,12 @@ func (i CompactionInfo) SafeFormat(w redact.SafePrinter, _ rune) {
outputSize := tablesTotalSize(i.Output.Tables)
w.Printf("[JOB %d] compacted(%s) ", redact.Safe(i.JobID), redact.SafeString(i.Reason))
w.Print(levelInfos(i.Input))
w.Printf(" -> L%d [%s] (%s), in %.1fs, output rate %s/s",
w.Printf(" -> L%d [%s] (%s), in %.1fs (%.1fs total), output rate %s/s",
redact.Safe(i.Output.Level),
redact.Safe(formatFileNums(i.Output.Tables)),
redact.Safe(humanize.Uint64(outputSize)),
redact.Safe(i.Duration.Seconds()),
redact.Safe(i.TotalDuration.Seconds()),
redact.Safe(humanize.Uint64(uint64(float64(outputSize)/i.Duration.Seconds()))))
}

Expand Down Expand Up @@ -135,10 +142,15 @@ type FlushInfo struct {
Input int
// Output contains the ouptut table generated by the flush. The output info
// is empty for the flush begin event.
Output []TableInfo
Output []TableInfo
// Duration is the time spent flushing. This duration includes writing and
// syncing all of the flushed keys to sstables.
Duration time.Duration
Done bool
Err error
// TotalDuration is the total wall-time duration of the flush, including
// applying the flush to the database. TotalDuration is always ≥ Duration.
TotalDuration time.Duration
Done bool
Err error
}

func (i FlushInfo) String() string {
Expand All @@ -164,11 +176,12 @@ func (i FlushInfo) SafeFormat(w redact.SafePrinter, _ rune) {
}

outputSize := tablesTotalSize(i.Output)
w.Printf("[JOB %d] flushed %d memtable%s to L0 [%s] (%s), in %.1fs, output rate %s/s",
w.Printf("[JOB %d] flushed %d memtable%s to L0 [%s] (%s), in %.1fs (%.1fs total), output rate %s/s",
redact.Safe(i.JobID), redact.Safe(i.Input), plural,
redact.Safe(formatFileNums(i.Output)),
redact.Safe(humanize.Uint64(outputSize)),
redact.Safe(i.Duration.Seconds()),
redact.Safe(i.TotalDuration.Seconds()),
redact.Safe(humanize.Uint64(uint64(float64(outputSize)/i.Duration.Seconds()))))
}

Expand Down
6 changes: 3 additions & 3 deletions testdata/compaction_delete_only_hints
View file
Original file line number Diff line number Diff line change
Expand Up @@ -89,7 +89,7 @@ maybe-compact
Deletion hints:
(none)
Compactions:
[JOB 100] compacted(delete-only) L2 [000005] (784 B) + L3 [000006] (784 B) -> L6 [] (0 B), in 1.0s, output rate 0 B/s
[JOB 100] compacted(delete-only) L2 [000005] (784 B) + L3 [000006] (784 B) -> L6 [] (0 B), in 1.0s (2.0s total), output rate 0 B/s

# Verify that compaction correctly handles the presence of multiple
# overlapping hints which might delete a file multiple times. All of the
Expand Down Expand Up @@ -130,7 +130,7 @@ maybe-compact
Deletion hints:
(none)
Compactions:
[JOB 100] compacted(delete-only) L2 [000006] (784 B) + L3 [000007] (784 B) -> L6 [] (0 B), in 1.0s, output rate 0 B/s
[JOB 100] compacted(delete-only) L2 [000006] (784 B) + L3 [000007] (784 B) -> L6 [] (0 B), in 1.0s (2.0s total), output rate 0 B/s

# Test a range tombstone that is already compacted into L6.

Expand Down Expand Up @@ -221,7 +221,7 @@ L0.000001 a-z seqnums(tombstone=5-27, file-smallest=0)
close-snapshot
10
----
[JOB 100] compacted(elision-only) L6 [000004] (850 B) + L6 [] (0 B) -> L6 [000005] (771 B), in 1.0s, output rate 771 B/s
[JOB 100] compacted(elision-only) L6 [000004] (850 B) + L6 [] (0 B) -> L6 [000005] (771 B), in 1.0s (2.0s total), output rate 771 B/s

# The deletion hint was removed by the elision-only compaction.
get-hints
Expand Down
4 changes: 2 additions & 2 deletions testdata/compaction_read_triggered
View file
Original file line number Diff line number Diff line change
Expand Up @@ -20,7 +20,7 @@ show-read-compactions

maybe-compact
----
[JOB 100] compacted(read) L5 [000004] (784 B) + L6 [000005] (784 B) -> L6 [000006] (778 B), in 1.0s, output rate 778 B/s
[JOB 100] compacted(read) L5 [000004] (784 B) + L6 [000005] (784 B) -> L6 [000006] (778 B), in 1.0s (2.0s total), output rate 778 B/s

show-read-compactions
----
Expand Down Expand Up @@ -81,7 +81,7 @@ show-read-compactions

maybe-compact
----
[JOB 100] compacted(read) L5 [000004] (784 B) + L6 [000005] (784 B) -> L6 [000006] (778 B), in 1.0s, output rate 778 B/s
[JOB 100] compacted(read) L5 [000004] (784 B) + L6 [000005] (784 B) -> L6 [000006] (778 B), in 1.0s (2.0s total), output rate 778 B/s

show-read-compactions
----
Expand Down
10 changes: 5 additions & 5 deletions testdata/compaction_tombstones
View file
Original file line number Diff line number Diff line change
Expand Up @@ -39,7 +39,7 @@ range-deletions-bytes-estimate: 0

maybe-compact
----
[JOB 100] compacted(elision-only) L6 [000004] (853 B) + L6 [] (0 B) -> L6 [] (0 B), in 1.0s, output rate 0 B/s
[JOB 100] compacted(elision-only) L6 [000004] (853 B) + L6 [] (0 B) -> L6 [] (0 B), in 1.0s (2.0s total), output rate 0 B/s

# Test a table that straddles a snapshot. It should not be compacted.
define snapshots=(50)
Expand Down Expand Up @@ -81,7 +81,7 @@ range-deletions-bytes-estimate: 0

maybe-compact
----
[JOB 100] compacted(elision-only) L6 [000004] (783 B) + L6 [] (0 B) -> L6 [000005] (771 B), in 1.0s, output rate 771 B/s
[JOB 100] compacted(elision-only) L6 [000004] (783 B) + L6 [] (0 B) -> L6 [000005] (771 B), in 1.0s (2.0s total), output rate 771 B/s

version
----
Expand Down Expand Up @@ -129,7 +129,7 @@ close-snapshot
close-snapshot
103
----
[JOB 100] compacted(elision-only) L6 [000004] (901 B) + L6 [] (0 B) -> L6 [] (0 B), in 1.0s, output rate 0 B/s
[JOB 100] compacted(elision-only) L6 [000004] (901 B) + L6 [] (0 B) -> L6 [] (0 B), in 1.0s (2.0s total), output rate 0 B/s

# Test a table that contains both deletions and non-deletions, but whose
# non-deletions well outnumber its deletions. The table should not be
Expand Down Expand Up @@ -201,7 +201,7 @@ range-deletions-bytes-estimate: 16488

maybe-compact
----
[JOB 100] compacted(default) L5 [000004 000005] (26 K) + L6 [000007] (17 K) -> L6 [000009] (25 K), in 1.0s, output rate 25 K/s
[JOB 100] compacted(default) L5 [000004 000005] (26 K) + L6 [000007] (17 K) -> L6 [000009] (25 K), in 1.0s (2.0s total), output rate 25 K/s

define level-max-bytes=(L5 : 1000) auto-compactions=off
L5
Expand Down Expand Up @@ -235,4 +235,4 @@ range-deletions-bytes-estimate: 0

maybe-compact
----
[JOB 100] compacted(default) L5 [000004] (794 B) + L6 [000006] (13 K) -> L6 [] (0 B), in 1.0s, output rate 0 B/s
[JOB 100] compacted(default) L5 [000004] (794 B) + L6 [000006] (13 K) -> L6 [] (0 B), in 1.0s (2.0s total), output rate 0 B/s
8 changes: 4 additions & 4 deletions testdata/event_listener
View file
Original file line number Diff line number Diff line change
Expand Up @@ -75,7 +75,7 @@ create: db/marker.manifest.000003.MANIFEST-000007
close: db/marker.manifest.000003.MANIFEST-000007
sync: db
[JOB 3] MANIFEST created 000007
[JOB 3] flushed 1 memtable to L0 [000006] (770 B), in 1.0s, output rate 770 B/s
[JOB 3] flushed 1 memtable to L0 [000006] (770 B), in 1.0s (2.0s total), output rate 770 B/s
[JOB 3] MANIFEST deleted 000001

compact
Expand All @@ -99,7 +99,7 @@ create: db/marker.manifest.000004.MANIFEST-000010
close: db/marker.manifest.000004.MANIFEST-000010
sync: db
[JOB 5] MANIFEST created 000010
[JOB 5] flushed 1 memtable to L0 [000009] (770 B), in 1.0s, output rate 770 B/s
[JOB 5] flushed 1 memtable to L0 [000009] (770 B), in 1.0s (2.0s total), output rate 770 B/s
[JOB 5] MANIFEST deleted 000003
[JOB 6] compacting(default) L0 [000006 000009] (1.5 K) + L6 [] (0 B)
create: db/000011.sst
Expand All @@ -114,7 +114,7 @@ create: db/marker.manifest.000005.MANIFEST-000012
close: db/marker.manifest.000005.MANIFEST-000012
sync: db
[JOB 6] MANIFEST created 000012
[JOB 6] compacted(default) L0 [000006 000009] (1.5 K) + L6 [] (0 B) -> L6 [000011] (770 B), in 1.0s, output rate 770 B/s
[JOB 6] compacted(default) L0 [000006 000009] (1.5 K) + L6 [] (0 B) -> L6 [000011] (770 B), in 1.0s (2.0s total), output rate 770 B/s
[JOB 6] sstable deleted 000006
[JOB 6] sstable deleted 000009
[JOB 6] MANIFEST deleted 000007
Expand Down Expand Up @@ -143,7 +143,7 @@ create: db/marker.manifest.000006.MANIFEST-000015
close: db/marker.manifest.000006.MANIFEST-000015
sync: db
[JOB 8] MANIFEST created 000015
[JOB 8] flushed 1 memtable to L0 [000014] (770 B), in 1.0s, output rate 770 B/s
[JOB 8] flushed 1 memtable to L0 [000014] (770 B), in 1.0s (2.0s total), output rate 770 B/s

enable-file-deletions
----
Expand Down

0 comments on commit cf6c474

Please sign in to comment.