[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