From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from firstgate.proxmox.com (firstgate.proxmox.com [212.224.123.68]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits)) (No client certificate requested) by lists.proxmox.com (Postfix) with ESMTPS id 3076EB393 for ; Wed, 6 Apr 2022 14:23:55 +0200 (CEST) Received: from firstgate.proxmox.com (localhost [127.0.0.1]) by firstgate.proxmox.com (Proxmox) with ESMTP id 2914C2AF9C for ; Wed, 6 Apr 2022 14:23:55 +0200 (CEST) Received: from proxmox-new.maurer-it.com (proxmox-new.maurer-it.com [94.136.29.106]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits)) (No client certificate requested) by firstgate.proxmox.com (Proxmox) with ESMTPS id 5D5DB2AF93 for ; Wed, 6 Apr 2022 14:23:53 +0200 (CEST) Received: from proxmox-new.maurer-it.com (localhost.localdomain [127.0.0.1]) by proxmox-new.maurer-it.com (Proxmox) with ESMTP id 1DC19459B1 for ; Wed, 6 Apr 2022 14:23:53 +0200 (CEST) Message-ID: Date: Wed, 6 Apr 2022 14:23:35 +0200 MIME-Version: 1.0 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:91.0) Gecko/20100101 Thunderbird/91.7.0 Content-Language: en-US From: Markus Frank To: Proxmox VE development discussion , Daniel Tschlatscher Reply-To: Proxmox VE development discussion References: <20220329104710.368695-1-d.tschlatscher@proxmox.com> <83fb35bb-8e22-8400-8565-c08723173450@proxmox.com> In-Reply-To: <83fb35bb-8e22-8400-8565-c08723173450@proxmox.com> Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 8bit X-SPAM-LEVEL: Spam detection results: 0 AWL 0.305 Adjusted score from AWL reputation of From: address BAYES_00 -1.9 Bayes spam probability is 0 to 1% KAM_DMARC_STATUS 0.01 Test Rule for DKIM or SPF Failure with Strict Alignment NICE_REPLY_A -0.631 Looks like a legit reply (A) SPF_HELO_NONE 0.001 SPF: HELO does not publish an SPF Record SPF_PASS -0.001 SPF: sender matches SPF record T_SCC_BODY_TEXT_LINE -0.01 - Subject: Re: [pve-devel] =?utf-8?q?=5BPATCH_pve-qemu_v3=5D_fix_=233865=3A_bac?= =?utf-8?q?kup_restore_human_readable_output=E2=80=8B?= X-BeenThere: pve-devel@lists.proxmox.com X-Mailman-Version: 2.1.29 Precedence: list List-Id: Proxmox VE development discussion List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 06 Apr 2022 12:23:55 -0000 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 > > 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 >> --- >> 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 >>   #include >> +#include >>   #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 > >