[pve-devel] [PATCH pve-qemu v3] fix #3865: backup restore human readable output
Markus Frank
m.frank at proxmox.com
Wed Apr 6 14:05:18 CEST 2022
Works as intended. This patch works on local storage only.
When using pbs as backupstorage, it is still printing the old
output. I think this can be easily fixed in a future patch.
Tested-by: Markus Frank <m.frank at proxmox.com>
On 3/29/22 12:47, Daniel Tschlatscher wrote:
> The backup restore dialogue now displays human readable output.
> The output is adapted to match the output of the backup create
> dialogue where possible.
> For this, 2 helper methods for printing human readable byte count
> and human readable time were added. The "main" progress output
> was rewritten in its own function and the way how time is
> measured was changed from seconds to nanoseconds.
>
> Example of the output before:
> ...
> progress 16% (read 2061631488 bytes, duration 37 sec)
> progress 17% (read 2190475264 bytes, duration 38 sec)
> progress 18% (read 2319319040 bytes, duration 39 sec)
> ...
> total bytes read 12884901888, sparse bytes 8659161088 (67.2%)
>
> Example of the output now:
> ...
> Progress 27% (3.30 GiB of 12.00 GiB) in 1 m 15 s - 36.79 MiB/s
> Progress 28% (3.39 GiB of 12.00 GiB) in 1 m 17 s - 42.45 MiB/s
> Progress 29% (3.50 GiB of 12.00 GiB) in 1 m 19 s - 53.78 MiB/s
> ...
> Finished restoring 12.00 GiB bytes in 2 m 21 s with 8.06 GiB of
> sparse data. (67.2%)
>
> Signed-off-by: Daniel Tschlatscher <d.tschlatscher at proxmox.com>
> ---
> Changes from v2:
> * Changed the granularity of time measurements from seconds to nano-
> seconds (mostly because the function used gives out ns already)
> * Human readable time function does no longer use modulo
> * Human readable byte count does no longer use log() in its cal-
> culations
> * Minor fixes to formatting and changed signed value types to un-
> signed ones where applicable and useful.
> * The "main" progress print was sourced in its own function, here I
> had to decide whether this function implemented the logic of
> whether a print should be issued or whether it should be a "pure"
> printing function. I chose the former option because it keeps the
> invoking function shorter and more clear.
> > keeping track of the "last_X" variables for time and byte count
> have posed a problem which I could not solve very satisfactorily.
> For now, the function checks whether enough time for the next
> print has elapsed, therefore also I kept the 100% check. Other-
> wise the variables for "last_X" would have to be stored e.g. in
> the VMAReader struct and every invoking of print_restore_progress
> would mean quite a lot of redundant code / calculations.
> The current implementation means the function isn't as concise
> as it could be, but it needs to be called only once in one
> "central" location and is easier to read where it is invoked.
> Though I am open to input in this regard.
>
> vma-reader.c | 118 +++++++++++++++++++++++++++++++++++++++++++--------
> vma.c | 7 +++
> vma.h | 8 ++++
> 3 files changed, 115 insertions(+), 18 deletions(-)
>
> diff --git a/vma-reader.c b/vma-reader.c
> index 2b1d1cdab3..27d8e5e404 100644
> --- a/vma-reader.c
> +++ b/vma-reader.c
> @@ -14,6 +14,7 @@
> #include "qemu/osdep.h"
> #include <glib.h>
> #include <uuid/uuid.h>
> +#include <math.h>
>
> #include "qemu-common.h"
> #include "qemu/timer.h"
> @@ -42,7 +43,7 @@ struct VmaReader {
> guint8 vmstate_stream;
> uint32_t vmstate_clusters;
> /* to show restore percentage if run with -v */
> - time_t start_time;
> + uint64_t start_time;
> int64_t cluster_count;
> int64_t clusters_read;
> int64_t zero_cluster_data;
> @@ -585,15 +586,11 @@ static int restore_extent(VmaReader *vmar, unsigned char *buf,
> vmar->clusters_read++;
>
> if (verbose) {
> - time_t duration = time(NULL) - vmar->start_time;
> - int percent = (vmar->clusters_read*100)/vmar->cluster_count;
> - if (percent != vmar->clusters_read_per) {
> - printf("progress %d%% (read %zd bytes, duration %zd sec)\n",
> - percent, vmar->clusters_read*VMA_CLUSTER_SIZE,
> - duration);
> - fflush(stdout);
> - vmar->clusters_read_per = percent;
> - }
> + vmar->clusters_read_per = (vmar->clusters_read * 100) / vmar->cluster_count;
> +
> + print_restore_progress(vmar->devinfo[dev_id].size,
> + vmar->clusters_read * VMA_CLUSTER_SIZE,
> + get_timestamp_ns() - vmar->start_time);
> }
>
> /* try to write whole clusters to speedup restore */
> @@ -713,7 +710,7 @@ static int vma_reader_restore_full(VmaReader *vmar, int vmstate_fd,
> unsigned char md5sum[16];
> VmaHeader *h = (VmaHeader *)vmar->head_data;
>
> - vmar->start_time = time(NULL);
> + vmar->start_time = get_timestamp_ns();
>
> while (1) {
> int bytes = full_read(vmar->fd, buf + buf_pos, sizeof(buf) - buf_pos);
> @@ -818,13 +815,19 @@ static int vma_reader_restore_full(VmaReader *vmar, int vmstate_fd,
>
> if (verbose) {
> if (vmar->clusters_read) {
> - printf("total bytes read %zd, sparse bytes %zd (%.3g%%)\n",
> - vmar->clusters_read*VMA_CLUSTER_SIZE,
> - vmar->zero_cluster_data,
> - (double)(100.0*vmar->zero_cluster_data)/
> - (vmar->clusters_read*VMA_CLUSTER_SIZE));
> -
> - int64_t datasize = vmar->clusters_read*VMA_CLUSTER_SIZE-vmar->zero_cluster_data;
> + uint64_t total_bytes = vmar->clusters_read * VMA_CLUSTER_SIZE;
> + uint64_t duration = get_timestamp_ns() - vmar->start_time;
> + double sparse_percent = (double)(100.0 * vmar->zero_cluster_data) / total_bytes;
> +
> + printf("Finished restoring ");
> + print_human_readable_byte_count(total_bytes);
> + printf(" bytes in ");
> + print_human_readable_time(NANOSECS_TO_SECS(duration));
> + printf(" with ");
> + print_human_readable_byte_count(vmar->zero_cluster_data);
> + printf(" of sparse data. (%.3g%%)\n", sparse_percent);
> +
> + int64_t datasize = total_bytes - vmar->zero_cluster_data;
> if (datasize) { // this does not make sense for empty files
> printf("space reduction due to 4K zero blocks %.3g%%\n",
> (double)(100.0*vmar->partial_zero_cluster_data) / datasize);
> @@ -855,3 +858,82 @@ int vma_reader_verify(VmaReader *vmar, bool verbose, Error **errp)
> return vma_reader_restore_full(vmar, -1, verbose, true, errp);
> }
>
> +void print_restore_progress(uint64_t total_bytes, uint64_t restored_bytes, uint64_t duration_ns)
> +{
> + static uint64_t last_duration = 0;
> + static uint64_t last_restored_bytes = 0;
> +
> + uint64_t delta = duration_ns - last_duration;
> + float percent = ((float)restored_bytes / total_bytes) * 100;
> + if (delta > SECS_TO_NANOSECS(2) || percent == 100) {
> + uint64_t bytes_changed = restored_bytes - last_restored_bytes;
> + uint64_t byte_throughput = NANOSECS_TO_SECS((double)delta) > 0 ? bytes_changed / NANOSECS_TO_SECS((double)delta) : 0;
> +
> + printf("Progress %.0f%% (", percent);
> + print_human_readable_byte_count(restored_bytes);
> + printf(" of ");
> + print_human_readable_byte_count(total_bytes);
> + printf(") in ");
> + print_human_readable_time(NANOSECS_TO_SECS(duration_ns));
> + printf(" - ");
> + print_human_readable_byte_count(byte_throughput);
> + printf("/s\n");
> +
> + fflush(stdout);
> + last_duration = duration_ns;
> + last_restored_bytes = restored_bytes;
> + }
> +}
> +
> +void print_human_readable_time(int seconds)
> +{
> + int days, hours, mins;
> +
> + days = seconds / (24 * 3600);
> + seconds -= days * 24 * 3600;
> +
> + hours = seconds / 3600;
> + seconds -= hours * 3600;
> +
> + mins = seconds / 60;
> + seconds -= mins * 60;
> +
> + if (days)
> + printf("%d d ", days);
> + if (hours)
> + printf("%d h ", hours);
> + if (mins)
> + printf("%d m ", mins);
> + printf("%d s", seconds);
> +}
> +
> +/* This should correctly display values up to 16 Ebibytes*/
> +void print_human_readable_byte_count(uint64_t value) {
> + double calculated = (double)value;
> + const char* units = "KMGTPE";
> + char unit;
> + int maxUnit = 0;
> +
> + while (calculated >= 1024) {
> + calculated /= 1024;
> + maxUnit++;
> + }
> +
> + if (maxUnit) {
> + unit = units[maxUnit - 1];
> + printf("%.2f %ciB", calculated, unit);
> + } else {
> + printf("%zd B", value);
> + }
> +}
> +
> +/* Should be safe for any backup restore process running less than ~70 years */
> +uint64_t get_timestamp_ns(void) {
> + uint64_t timestamp;
> + struct timespec time;
> + clock_gettime(CLOCK_MONOTONIC, &time);
> +
> + timestamp = SECS_TO_NANOSECS((uint64_t)time.tv_sec);
> + timestamp += (uint64_t)time.tv_nsec;
> + return timestamp;
> +}
> \ No newline at end of file
> diff --git a/vma.c b/vma.c
> index df542b7732..9ede415ae7 100644
> --- a/vma.c
> +++ b/vma.c
> @@ -80,8 +80,15 @@ static void print_content(VmaReader *vmar)
> if (strcmp(di->devname, "vmstate") == 0) {
> printf("VMSTATE: dev_id=%d memory: %zd\n", i, di->size);
> } else {
> + /* Todo: This should have it's own 'channel' and not be sent with user output
> + This information is needed in qemu-server (PVE::QemuServer.pm)
> + Change only if you know what you are doing */
> printf("DEV: dev_id=%d size: %zd devname: %s\n",
> i, di->size, di->devname);
> +
> + printf("Info: dev_id=%d size: ", i);
> + print_human_readable_byte_count(di->size);
> + printf(" devname: %s\n", di->devname);
> }
> }
> }
> diff --git a/vma.h b/vma.h
> index c895c97f6d..0ee55e3895 100644
> --- a/vma.h
> +++ b/vma.h
> @@ -42,6 +42,9 @@
> #define VMA_MAGIC (GUINT32_TO_BE(('V'<<24)|('M'<<16)|('A'<<8)|0x00))
> #define VMA_EXTENT_MAGIC (GUINT32_TO_BE(('V'<<24)|('M'<<16)|('A'<<8)|'E'))
>
> +#define SECS_TO_NANOSECS(secs) ((secs) * 1000000000)
> +#define NANOSECS_TO_SECS(nsecs) ((nsecs) / 1000000000)
> +
> typedef struct VmaDeviceInfoHeader {
> uint32_t devname_ptr; /* offset into blob_buffer table */
> uint32_t reserved0;
> @@ -147,4 +150,9 @@ int vma_reader_restore(VmaReader *vmar, int vmstate_fd, bool verbose,
> Error **errp);
> int vma_reader_verify(VmaReader *vmar, bool verbose, Error **errp);
>
> +uint64_t get_timestamp_ns(void);
> +void print_human_readable_time(int);
> +void print_human_readable_byte_count(uint64_t);
> +void print_restore_progress(uint64_t, uint64_t, uint64_t);
> +
> #endif /* BACKUP_VMA_H */
More information about the pve-devel
mailing list