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) server-digest SHA256) (No client certificate requested) by lists.proxmox.com (Postfix) with ESMTPS id 82176B34A for ; Wed, 6 Apr 2022 14:06:07 +0200 (CEST) Received: from firstgate.proxmox.com (localhost [127.0.0.1]) by firstgate.proxmox.com (Proxmox) with ESMTP id 7151F2ACC1 for ; Wed, 6 Apr 2022 14:05:37 +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 34A942ACB5 for ; Wed, 6 Apr 2022 14:05:36 +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 ECA2C41FCF for ; Wed, 6 Apr 2022 14:05:35 +0200 (CEST) Message-ID: <83fb35bb-8e22-8400-8565-c08723173450@proxmox.com> Date: Wed, 6 Apr 2022 14:05:18 +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 To: Proxmox VE development discussion , Daniel Tschlatscher References: <20220329104710.368695-1-d.tschlatscher@proxmox.com> From: Markus Frank In-Reply-To: <20220329104710.368695-1-d.tschlatscher@proxmox.com> Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 7bit X-SPAM-LEVEL: Spam detection results: 0 AWL 0.316 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:06:07 -0000 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 */