vtbackup, mysqlctl: detailed backup and restore metrics #11979

maxenglander · 2022-12-16T00:11:20Z

Description

Addresses #11977.

I would like to have better instrumentation on backups, in particular backups generated by vtbackup. While backup stats are exposed via servenv since #11388 (which is great!) ideally I would like more fine-grained stats on:

Download last backup.
Decompress last backup.
Catchup to primary with replication.
Compress new backup.
Upload new backup.

Design

There were a couple design goals that shaped the way the code is written.

No breaking interface changes

After discussion with Deepthi we decided to introduce a breaking change after all.

A quick Google/GitHub search didn't reveal any out-of-tree backupstorage plugins, but the way the backup/restore APIs are laid out makes it seem like they were designed to support out-of-tree plugins.

I tried to keep that in mind when writing this PR, in particular by not making any changes that would require anyone using out-of-tree plugins to make code changes when they upgrade to a Vitess version with these changes.

Separate policy and mechanism

It wouldn't be great if every out-of-tree backupstorage generated metrics in ways that conflicted with each other or varied widely from way Vitess users are used to consuming in-tree metrics.

In this PR, I tried to create a minimal stats mechanism that can be used by in-tree and out-of-tree code, but where the policies for stats (metric names and labels, stats sink, etc.) are kept in-tree and under the control of the Vitess user.

This approach seems similar in spirit to what is already being done with BackupParams.Logger and RestoreParams.Logger.

Changes

This PR adds several new metrics:

vtbackup_duration_by_phase_seconds with phase label
{vtbackup,vttablet}_backup_bytes with component, implementation, and operation labels
{vtbackup,vttablet}_backup_count with component, implementation, and operation labels
{vtbackup,vttablet}_backup_duration_nanoseconds with component, implementation, and operation labels
{vtbackup,vttablet}_restore_bytes with component, implementation, and operation labels
{vtbackup,vttablet}_restore_count with component, implementation, and operation labels
{vtbackup,vttablet}_restore_duration_nanoseconds with component, implementation, and operation labels

It also deprecates these older backup/restore metrics:

{vtbackup,vttablet}_backup_duration_seconds
{vtbackup,vttablet}_restore_duration_seconds

Notes

Changes to vtbackup:

Add new stat duration_seconds metric which reports durations of additional phases not covered by mysqlctl.
Reports phases like initmysqld, initialbackup, restorelastbackup, catchupreplication, etc.

Changes to mysqlctl:

Add backup_bytes, backup_count, backup_duration_nanoseconds, restore_bytes, restore_count, restore_duration_nanoseconds metrics.
These metrics each have three labels: component, implementation, and operation.
The idea is that we can re-use these metric across different components (- = unscoped, top-level, backupstorage, backupengine, etc.) across different implementations (s3, file, etc.), and across different operations (backup, restore, read, compress, encrypt).

Other notes:

An alternative design would be to just have each engine/plugin declare its own stats, or have a set of global stats that each engine/plugin/package can import.
Why nanoseconds on those two new metrics? Because as we're reporting on read/write times for individual files, if all the files are small and take less than a second to process then they end up reporting as zero.
Why backupengine.(Parameterizable)? I wasn't sure how safe it would be to break any of the APIs like BackupEngine and BackupStorage. Figured it was better to introduce changes this way until I get some guidance.

Samples

Sample metrics generated by running vtbackup from this branch against the local example cluster. Processed with jq and sorted for readability.

{
  "BackupBytes": {
    "BackupEngine.Builtin.Source:Read": 4777,
    "BackupEngine.Builtin.Compressor:Write": 4616,
    "BackupEngine.Builtin.Destination:Write": 162,
    "BackupStorage.File.File:Write": 163
  },
  "BackupCount": {
    "-.-.Backup": 1,
    "BackupEngine.Builtin.Source:Open": 161,
    "BackupEngine.Builtin.Source:Close": 322,
    "BackupEngine.Builtin.Compressor:Close": 161,
    "BackupEngine.Builtin.Destination:Open": 161,
    "BackupEngine.Builtin.Destination:Close": 322
  },
  "BackupDurationNanoseconds": {
    "-.-.Backup": 4188508542,
    "BackupEngine.Builtin.Source:Open": 10649832,
    "BackupEngine.Builtin.Source:Read": 55901067,
    "BackupEngine.Builtin.Source:Close": 960826,
    "BackupEngine.Builtin.Compressor:Write": 278358826,
    "BackupEngine.Builtin.Compressor:Close": 79358372,
    "BackupEngine.Builtin.Destination:Open": 16456627,
    "BackupEngine.Builtin.Destination:Write": 11021043,
    "BackupEngine.Builtin.Destination:Close": 17144630,
    "BackupStorage.File.File:Write": 10743169
  },
  "DurationByPhaseSeconds": {
    "InitMySQLd": 2,
    "RestoreLastBackup": 6,
    "CatchUpReplication": 1,
    "TakeNewBackup": 4
  },
  "RestoreBytes": {
    "BackupEngine.Builtin.Source:Read": 1095,
    "BackupEngine.Builtin.Decompressor:Read": 950,
    "BackupEngine.Builtin.Destination:Write": 209,
    "BackupStorage.File.File:Read": 1113
  },
  "RestoreCount": {
    "-.-.Restore": 1,
    "BackupEngine.Builtin.Source:Open": 161,
    "BackupEngine.Builtin.Source:Close": 322,
    "BackupEngine.Builtin.Decompressor:Close": 161,
    "BackupEngine.Builtin.Destination:Open": 161,
    "BackupEngine.Builtin.Destination:Close": 322
  },
  "RestoreDurationNanoseconds": {
    "-.-.Restore": 6204765541,
    "BackupEngine.Builtin.Source:Open": 10542539,
    "BackupEngine.Builtin.Source:Read": 104658370,
    "BackupEngine.Builtin.Source:Close": 773038,
    "BackupEngine.Builtin.Decompressor:Read": 165692120,
    "BackupEngine.Builtin.Decompressor:Close": 51040,
    "BackupEngine.Builtin.Destination:Open": 22715122,
    "BackupEngine.Builtin.Destination:Write": 41679581,
    "BackupEngine.Builtin.Destination:Close": 26954624,
    "BackupStorage.File.File:Read": 102416075
  },
  "backup_duration_seconds": 4,
  "restore_duration_seconds": 6
}

Performance

At @deepthi suggestion I compared performance of backups on main versus this branch.

I set up the commerce example cluster, and created a table with ~20 GiB of data, then ran:

$ vtctlclient BackupShard -- --allow_primary --concurrency=1 commerce/0

Multiple times with this branch and main, comparing the values of vttablet_backup_duration_seconds.

#	`main` branch (`7fc1b48`)	this branch (`d5364e6`)
1	21	21
2	20	23
3	22	21
4	21	22
5	21	22

Assuming the differences aren't due to vagaries of CPU and disk usage on my Mac M1, this branch adds a roughly 3.8% performance overhead.

Out-of-scope

This PR doesn't add new metrics to all backup engines or storage engines. Would like to get buy-in on this approach (or a different one) first, and then expand whatever approach we adopt in follow-on PRs to cover additional backup engines & storages.

Checklist

Implement.
Write tests.
Docs

vitess-bot · 2022-12-16T00:11:22Z

maxenglander · 2022-12-17T02:19:27Z

go/cmd/vtbackup/vtbackup.go

@@ -120,6 +121,11 @@ var (
 	detachedMode     bool
 	keepAliveTimeout = 0 * time.Second
 	disableRedoLog   = false
+	durationByPhase  = stats.NewGaugesWithSingleLabel(
+		"duration_seconds",
+		"How long it took vtbackup to perform a each phase of operation (in seconds).",


Because vtbackup also picks up stats from mysqlctl, there will be some overlap between this metric and those metrics. I think that's OK, personally, but if we want I can take more care to avoid any overlap.

go/stats/timings.go

maxenglander · 2022-12-17T02:23:10Z

go/vt/mysqlctl/backup.go

@@ -92,9 +92,6 @@ var (
 	// backupCompressBlocks is the number of blocks that are processed
 	// once before the writer blocks
 	backupCompressBlocks = 2
-
-	backupDuration  = stats.NewGauge("backup_duration_seconds", "How long it took to complete the last backup operation (in seconds)")


Not deleted, just moved to backupstats package.

go/vt/mysqlctl/backup.go

maxenglander · 2022-12-17T02:28:48Z

go/vt/mysqlctl/backup.go

 	// Take the backup, and either AbortBackup or EndBackup.
-	usable, err := be.ExecuteBackup(ctx, params, bh)
+	beParams := params.Copy()


This is a bit awkward, and copying structs makes me uncomfortable. Is there a way to lint for exhaustive field copying?

just thinking out loud here.. can we have tow stats , enginestats and storagestats in backupparam.. so you won't end up copy

I think if we did that approach we might end up needing three stats, one for the engine, one for the storage, and one for the controlling function (mysqlctl.Backup).

Overall I think I am OK with the copy, and one thing I didn't know about Golang when I wrote the comment above is that this kind of struct creation is exhaustive:

a1 := A{ "hello", true, 3, }

It won't let you omit any struct fields. So I at least feel good about that. The only risk now is if someone swaps the order of two struct fields that have the same type 😬

go/vt/mysqlctl/backupstats/defaults.go

go/vt/mysqlctl/builtinbackupengine.go

maxenglander · 2022-12-17T02:38:16Z

go/vt/mysqlctl/builtinbackupengine_test.go

@@ -100,7 +100,7 @@ func TestExecuteBackup(t *testing.T) {
 	oldDeadline := setBuiltinBackupMysqldDeadline(time.Second)
 	defer setBuiltinBackupMysqldDeadline(oldDeadline)

-	bh := filebackupstorage.FileBackupHandle{}
+	bh := filebackupstorage.NewBackupHandle(nil, "", "", false)


Not strictly necessary, but makes a bit easier to avoid nil dereferences.

go/vt/mysqlctl/compression.go

go/vt/mysqlctl/filebackupstorage/file.go

go/vt/mysqlctl/backupengine.go

go/vt/mysqlctl/backupstats/component.go

go/ioutil/reader.go

go/vt/mysqlctl/backupstats/stats.go

maxenglander · 2022-12-17T18:38:37Z

go/vt/vttablet/tabletmanager/restore.go

@@ -191,6 +192,7 @@ func (tm *TabletManager) restoreDataLocked(ctx context.Context, logger logutil.L
 		Shard:               tablet.Shard,
 		StartTime:           logutil.ProtoToTime(request.BackupTime),
 		DryRun:              request.DryRun,
+		Stats:               backupstats.RestoreStats(),


If Stats is not set then mysqlctl will use backupstats.NopStats. This way any out-of-tree code can opt in to the new stats, or not (and not have to worry about nil deference errors).

go/vt/mysqlctl/backupstats/stats.go

Signed-off-by: Max Englander <[email protected]>

go/cmd/vtbackup/vtbackup.go

Signed-off-by: Max Englander <[email protected]>

rsajwani · 2023-02-10T01:33:54Z

go/ioutil/meter.go

+	duration time.Duration
+}
+
+// Bytes reports the total bytes read in calls to f so far.


Hm this refers to the argument f in func measure, but it's not very helpful here. Let me reword this.

maxenglander

Improve code comments in ioutil/meter

go/ioutil/meter.go

Signed-off-by: Max Englander <[email protected]>

go/vt/mysqlctl/backupstats/constants.go

go/vt/mysqlctl/backup.go

go/vt/mysqlctl/backupstats/deprecated.go

Signed-off-by: Max Englander <[email protected]>

go/vt/mysqlctl/filebackupstorage/file.go

doc/releasenotes/17_0_0_summary.md

Signed-off-by: Max Englander <[email protected]>

maxenglander

@rsajwani thanks for all the helpful suggestions. I think I addressed all of your feedback, ready for another look!

doc/releasenotes/17_0_0_summary.md

rsajwani

LGTM. Thanks Max. This is awesome work.

maxenglander added Type: Enhancement Logical improvement (somewhere between a bug and feature) Component: Backup and Restore labels Dec 16, 2022

maxenglander force-pushed the maxeng-details-backup-stats branch 4 times, most recently from e79b3f5 to 651a278 Compare December 17, 2022 02:14