Improve benchmark output

[steffen]

When troubleshooting the performance of a backup run, there are currently two ways (that I know of) for finding details about the time a backup run took:

1. Looking at the benchmark file $GHE_DATA_DIR/SNAPSHOT_TIMESTAMP/benchmarks/benchmark.SNAPSHOT_TIMESTAMP.log
2. Looking at the output of GHE_DEBUG=1 ghe-backup --verbose

This pull requests aims to improve the readability and information provided in the above mentioned benchmark file and debug output. See below for details:

1. Add timestamp and formatted time to benchmark file

With the current format, it's difficult to process the file and get a sense of when something ran and for how long. Hence I'm proposing adding a timestamp (ISO 8601) and converting the duration time into hours, minutes and seconds.

Example: Before

ghe-backup-store-version took 0s
ghe-backup-settings took 1s
ghe-export-authorized-keys took 0s
ghe-export-ssh-host-keys took 0s
ghe-backup-mysql-binary took 18s
ghe-backup-mysql took 19s
ghe-backup-redis took 1s
ghe-backup-es-audit-log took 10s
ghe-backup-es-hookshot took 1s
ghe-backup-repositories - Generating routes took 3s
ghe-backup-repositories - Fetching routes took 0s
ghe-backup-repositories - Processing routes took 0s
ghe-backup-repositories - Repo sync took 672s
ghe-backup-repositories - Special Data Directories Sync took 1s
ghe-backup-repositories - Verifying Routes took 0s
ghe-backup-repositories took 676s
ghe-backup-pages - github.example.com took 1s
ghe-backup-pages took 1s
ghe-backup-storage - Generating routes took 2s
ghe-backup-storage - Fetching routes took 0s
ghe-backup-storage - Processing routes took 0s
ghe-backup-storage - Storage object sync took 8s
ghe-backup-storage - Verifying Routes took 0s
ghe-backup-storage took 11s
ghe-backup-git-hooks took 1s
ghe-backup-es-rsync took 130s

Example: After

Completed at 2021-02-16T08:48:25+00:00 in 00h:00m:00s: ghe-backup-store-version
Completed at 2021-02-16T08:48:26+00:00 in 00h:00m:01s: ghe-backup-settings
Completed at 2021-02-16T08:48:26+00:00 in 00h:00m:00s: ghe-export-authorized-keys
Completed at 2021-02-16T08:48:27+00:00 in 00h:00m:01s: ghe-export-ssh-host-keys
Completed at 2021-02-16T08:48:45+00:00 in 00h:00m:18s: ghe-backup-mysql-binary
Completed at 2021-02-16T08:48:45+00:00 in 00h:00m:18s: ghe-backup-mysql
Completed at 2021-02-16T08:48:49+00:00 in 00h:00m:03s: ghe-backup-redis
Completed at 2021-02-16T08:48:58+00:00 in 00h:00m:09s: ghe-backup-es-audit-log
Completed at 2021-02-16T08:48:58+00:00 in 00h:00m:00s: ghe-backup-es-hookshot
Completed at 2021-02-16T08:49:01+00:00 in 00h:00m:03s: ghe-backup-repositories - Generating routes
Completed at 2021-02-16T08:49:01+00:00 in 00h:00m:00s: ghe-backup-repositories - Fetching routes
Completed at 2021-02-16T08:49:01+00:00 in 00h:00m:00s: ghe-backup-repositories - Processing routes
Completed at 2021-02-16T08:59:34+00:00 in 00h:10m:33s: ghe-backup-repositories - Repo sync
Completed at 2021-02-16T08:59:35+00:00 in 00h:00m:01s: ghe-backup-repositories - Special Data Directories Sync
Completed at 2021-02-16T08:59:35+00:00 in 00h:00m:00s: ghe-backup-repositories - Verifying Routes
Completed at 2021-02-16T08:59:35+00:00 in 00h:10m:37s: ghe-backup-repositories
Completed at 2021-02-16T08:59:36+00:00 in 00h:00m:01s: ghe-backup-pages - github.example.com
Completed at 2021-02-16T08:59:36+00:00 in 00h:00m:01s: ghe-backup-pages
Completed at 2021-02-16T08:59:40+00:00 in 00h:00m:03s: ghe-backup-storage - Generating routes
Completed at 2021-02-16T08:59:40+00:00 in 00h:00m:00s: ghe-backup-storage - Fetching routes
Completed at 2021-02-16T08:59:40+00:00 in 00h:00m:00s: ghe-backup-storage - Processing routes
Completed at 2021-02-16T08:59:47+00:00 in 00h:00m:07s: ghe-backup-storage - Storage object sync
Completed at 2021-02-16T08:59:47+00:00 in 00h:00m:00s: ghe-backup-storage - Verifying Routes
Completed at 2021-02-16T08:59:47+00:00 in 00h:00m:11s: ghe-backup-storage
Completed at 2021-02-16T08:59:48+00:00 in 00h:00m:00s: ghe-backup-git-hooks
Completed at 2021-02-16T09:01:30+00:00 in 00h:01m:42s: ghe-backup-es-rsync
Completed at 2021-02-16T09:01:30+00:00 in 00h:00m:00s: ghe-prune-snapshots

2. Add timestamp and formatted time to debug output

Just as for the benchmark file, this pull requests adds the timestamp and formatted duration time to the debug (GHE_DEBUG=1) output as well.

Example: Before

Starting backup of github.example.com with backup-utils v3.0.0.rc1 in snapshot 20210216T091914
Connect github.example.com:122 OK (v2.22.6)
Debug: ghe-backup-store-version (bm_start)
Debug: ghe-backup-store-version took 0s (bm_end)
Backing up GitHub settings ...
Debug: ghe-backup-settings (bm_start)
Warning: password pepper not set
Debug: ghe-backup-settings took 1s (bm_end)
Backing up SSH authorized keys ...
Debug: ghe-export-authorized-keys (bm_start)
Debug: ghe-export-authorized-keys took 0s (bm_end)
Backing up SSH host keys ...
Debug: ghe-export-ssh-host-keys (bm_start)
Debug: ghe-export-ssh-host-keys took 0s (bm_end)
Debug: ghe-backup-mysql (bm_start)
Debug: ghe-backup-mysql-binary (bm_start)
Backing up MySQL database using binary backup strategy ...
Debug: ghe-backup-mysql-binary took 18s (bm_end)
Debug: ghe-backup-mysql took 19s (bm_end)
Backing up Redis database ...
Backing up audit log ...
Debug: ghe-backup-es-audit-log (bm_start)
Debug: ghe-backup-es-audit-log took 10s (bm_end)
Backing up hookshot logs ...
Debug: ghe-backup-es-hookshot (bm_start)
Debug: ghe-backup-es-hookshot took 1s (bm_end)
Backing up Git repositories ...
Debug: ghe-backup-repositories (bm_start)
Debug: ghe-backup-repositories - Generating routes (bm_start)
Debug: ghe-backup-repositories - Generating routes took 3s (bm_end)
Debug: ghe-backup-repositories - Fetching routes (bm_start)
Debug: ghe-backup-repositories - Fetching routes took 0s (bm_end)
Debug: ghe-backup-repositories - Processing routes (bm_start)
Debug: ghe-backup-repositories - Processing routes took 0s (bm_end)
Debug: ghe-backup-repositories - Repo sync (bm_start)
Debug: ghe-backup-repositories - Repo sync took 672s (bm_end)
Debug: ghe-backup-repositories - Special Data Directories Sync (bm_start)
Debug: ghe-backup-repositories - Special Data Directories Sync took 1s (bm_end)
Debug: ghe-backup-repositories - Verifying Routes (bm_start)
Debug: ghe-backup-repositories - Verifying Routes took 0s (bm_end)
Debug: ghe-backup-repositories took 676s (bm_end)
Backing up GitHub Pages artifacts ...
Debug: ghe-backup-pages (bm_start)
Debug: ghe-backup-pages - github.example.com (bm_start)
Debug: ghe-backup-pages - github.example.com took 1s (bm_end)
Debug: ghe-backup-pages took 1s (bm_end)
Backing up storage data ...
Debug: ghe-backup-storage (bm_start)
Debug: ghe-backup-storage - Generating routes (bm_start)
Debug: ghe-backup-storage - Generating routes took 2s (bm_end)
Debug: ghe-backup-storage - Fetching routes (bm_start)
Debug: ghe-backup-storage - Fetching routes took 0s (bm_end)
Debug: ghe-backup-storage - Processing routes (bm_start)
Debug: ghe-backup-storage - Processing routes took 0s (bm_end)
Debug: ghe-backup-storage - Storage object sync (bm_start)
Debug: ghe-backup-storage - Storage object sync took 8s (bm_end)
Debug: ghe-backup-storage - Verifying Routes (bm_start)
Debug: ghe-backup-storage - Verifying Routes took 0s (bm_end)
Debug: ghe-backup-storage took 11s (bm_end)
Backing up custom Git hooks ...
Debug: ghe-backup-git-hooks (bm_start)
Debug: ghe-backup-git-hooks took 1s (bm_end)
Backing up Elasticsearch indices ...
Debug: ghe-backup-es-rsync (bm_start)
Debug: ghe-backup-es-rsync took 130s (bm_end)
Completed backup of github.example.com:122 in snapshot 20210216T091914 at 09:33:29
Checking for leaked ssh keys ...
* No leaked keys found

Example: After

Starting backup of github.example.com with backup-utils v3.0.0.rc1 in snapshot 20210216T084824
Connect github.example.com:122 OK (v2.22.6)
Debug: ghe-backup-store-version (bm_start)
Debug (Completed at 2021-02-16T08:48:25+00:00 in 00h:00m:00s): ghe-backup-store-version (bm_end)
Backing up GitHub settings ...
Debug: ghe-backup-settings (bm_start)
Warning: password pepper not set
Debug (Completed at 2021-02-16T08:48:26+00:00 in 00h:00m:01s): ghe-backup-settings (bm_end)
Backing up SSH authorized keys ...
Debug: ghe-export-authorized-keys (bm_start)
Debug (Completed at 2021-02-16T08:48:26+00:00 in 00h:00m:00s): ghe-export-authorized-keys (bm_end)
Backing up SSH host keys ...
Debug: ghe-export-ssh-host-keys (bm_start)
Debug (Completed at 2021-02-16T08:48:27+00:00 in 00h:00m:01s): ghe-export-ssh-host-keys (bm_end)
Debug: ghe-backup-mysql (bm_start)
Debug: ghe-backup-mysql-binary (bm_start)
Backing up MySQL database using binary backup strategy ...
Debug (Completed at 2021-02-16T08:48:45+00:00 in 00h:00m:18s): ghe-backup-mysql-binary (bm_end)
Debug (Completed at 2021-02-16T08:48:45+00:00 in 00h:00m:18s): ghe-backup-mysql (bm_end)
Backing up Redis database ...
Backing up audit log ...
Debug: ghe-backup-es-audit-log (bm_start)
Debug (Completed at 2021-02-16T08:48:58+00:00 in 00h:00m:09s): ghe-backup-es-audit-log (bm_end)
Backing up hookshot logs ...
Debug: ghe-backup-es-hookshot (bm_start)
Debug (Completed at 2021-02-16T08:48:58+00:00 in 00h:00m:00s): ghe-backup-es-hookshot (bm_end)
Backing up Git repositories ...
Debug: ghe-backup-repositories (bm_start)
Debug: ghe-backup-repositories - Generating routes (bm_start)
Debug (Completed at 2021-02-16T08:49:01+00:00 in 00h:00m:03s): ghe-backup-repositories - Generating routes (bm_end)
Debug: ghe-backup-repositories - Fetching routes (bm_start)
Debug (Completed at 2021-02-16T08:49:01+00:00 in 00h:00m:00s): ghe-backup-repositories - Fetching routes (bm_end)
Debug: ghe-backup-repositories - Processing routes (bm_start)
Debug (Completed at 2021-02-16T08:49:01+00:00 in 00h:00m:00s): ghe-backup-repositories - Processing routes (bm_end)
Debug: ghe-backup-repositories - Repo sync (bm_start)
Debug (Completed at 2021-02-16T08:59:34+00:00 in 00h:10m:33s): ghe-backup-repositories - Repo sync (bm_end)
Debug: ghe-backup-repositories - Special Data Directories Sync (bm_start)
Debug (Completed at 2021-02-16T08:59:35+00:00 in 00h:00m:01s): ghe-backup-repositories - Special Data Directories Sync (bm_end)
Debug: ghe-backup-repositories - Verifying Routes (bm_start)
Debug (Completed at 2021-02-16T08:59:35+00:00 in 00h:00m:00s): ghe-backup-repositories - Verifying Routes (bm_end)
Debug (Completed at 2021-02-16T08:59:35+00:00 in 00h:10m:37s): ghe-backup-repositories (bm_end)
Backing up GitHub Pages artifacts ...
Debug: ghe-backup-pages (bm_start)
Debug: ghe-backup-pages - github.example.com (bm_start)
Debug (Completed at 2021-02-16T08:59:36+00:00 in 00h:00m:01s): ghe-backup-pages - github.example.com (bm_end)
Debug (Completed at 2021-02-16T08:59:36+00:00 in 00h:00m:01s): ghe-backup-pages (bm_end)
Backing up storage data ...
Debug: ghe-backup-storage (bm_start)
Debug: ghe-backup-storage - Generating routes (bm_start)
Debug (Completed at 2021-02-16T08:59:40+00:00 in 00h:00m:03s): ghe-backup-storage - Generating routes (bm_end)
Debug: ghe-backup-storage - Fetching routes (bm_start)
Debug (Completed at 2021-02-16T08:59:40+00:00 in 00h:00m:00s): ghe-backup-storage - Fetching routes (bm_end)
Debug: ghe-backup-storage - Processing routes (bm_start)
Debug (Completed at 2021-02-16T08:59:40+00:00 in 00h:00m:00s): ghe-backup-storage - Processing routes (bm_end)
Debug: ghe-backup-storage - Storage object sync (bm_start)
Debug (Completed at 2021-02-16T08:59:47+00:00 in 00h:00m:07s): ghe-backup-storage - Storage object sync (bm_end)
Debug: ghe-backup-storage - Verifying Routes (bm_start)
Debug (Completed at 2021-02-16T08:59:47+00:00 in 00h:00m:00s): ghe-backup-storage - Verifying Routes (bm_end)
Debug (Completed at 2021-02-16T08:59:47+00:00 in 00h:00m:11s): ghe-backup-storage (bm_end)
Backing up custom Git hooks ...
Debug: ghe-backup-git-hooks (bm_start)
Debug (Completed at 2021-02-16T08:59:48+00:00 in 00h:00m:00s): ghe-backup-git-hooks (bm_end)
Backing up Elasticsearch indices ...
Debug: ghe-backup-es-rsync (bm_start)
Debug (Completed at 2021-02-16T09:01:30+00:00 in 00h:01m:42s): ghe-backup-es-rsync (bm_end)
Debug: ghe-prune-snapshots (bm_start)
Debug (Completed at 2021-02-16T09:01:30+00:00 in 00h:00m:00s): ghe-prune-snapshots (bm_end)
Completed backup of github.example.com:122 in snapshot 20210216T084824 at 2021-02-16T09:01:30+00:00
Checking for leaked ssh keys ...
* No leaked keys found

3. Display date and time on backup completion

Currently we only display the time at which a backup has completed. This can give a false sense of duration if a backup runs longer than 24 hours. Hence this pull request adds the complete date and time in ISO 8601 format.

Example: Before

Completed backup of github.example.com:122 in snapshot 20210201T220000 at 02:30:00

Example: After

Completed backup of github.example.com:122 in snapshot 20210201T220000 at 2021-02-03T02:30:00+00:00

4. Add duration for ghe-prune-snapshots

For large backups, the pruning of expired snapshots can take a considerable part of the whole backup run time. Hence this pull request adds the duration of the pruning of expired snapshots step to the benchmark file to avoid confusion of the whole backup process taking considerably longer than the benchmark file indicates. This pull request also adds the completion timestamp and duration to the debug output.

Example

Completed at 2021-02-16T08:26:37+00:00 in 02h:42m:15s: ghe-prune-snapshots

[lildude]

I no longer work on backup-utils @steffen so I've deferred review to the @github/ghes-infrastructure peeps

[steffen]

Thanks @lildude! (You were suggested by the GitHub UI, hence I picked you. 😊)

[jianghao0718]

@steffen Change looks generally good to me! Please fix the test since it is failing on

[ "$(grep took $GHE_DATA_DIR/current/benchmarks/benchmark.foo.log | wc -l)" -gt 1 ]

Probably a good chance to improve this test to check the format of your output as well. 😏

[drmanoj009]

@ https://github.com/github/backup-utils/tree/improve-benchmark-output

[gamefiend]

Will add these changes to benchmark in line with the timestamp format we are using with the rest of the app.