Re: [pve-devel] [PATCH pve-qemu v3] fix #3865: backup restore human readable output​

[Markus Frank <m.frank@proxmox.com>]

Sorry, I meant that this patch works on every storage other than
pbs, not only on local storage like I wrote.
I tested it with lvm, zfs, nfs and pbs.
Only pbs prints out the old output, because of its own implementation.

On 4/6/22 14:05, Markus Frank wrote:
> 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@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@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 */
> 
> 
> _______________________________________________
> pve-devel mailing list
> pve-devel@lists.proxmox.com
> https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel
> 
>