* [pve-devel] [PATCH pve-qemu v3] fix #3865: backup restore human readable output
@ 2022-03-29 10:47 Daniel Tschlatscher
2022-04-06 12:05 ` Markus Frank
0 siblings, 1 reply; 3+ messages in thread
From: Daniel Tschlatscher @ 2022-03-29 10:47 UTC (permalink / raw)
To: pve-devel
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 */
--
2.30.2
^ permalink raw reply [flat|nested] 3+ messages in thread* Re: [pve-devel] [PATCH pve-qemu v3] fix #3865: backup restore human readable output
2022-03-29 10:47 [pve-devel] [PATCH pve-qemu v3] fix #3865: backup restore human readable output Daniel Tschlatscher
@ 2022-04-06 12:05 ` Markus Frank
2022-04-06 12:23 ` Markus Frank
0 siblings, 1 reply; 3+ messages in thread
From: Markus Frank @ 2022-04-06 12:05 UTC (permalink / raw)
To: Proxmox VE development discussion, Daniel Tschlatscher
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 */
^ permalink raw reply [flat|nested] 3+ messages in thread* Re: [pve-devel] [PATCH pve-qemu v3] fix #3865: backup restore human readable output
2022-04-06 12:05 ` Markus Frank
@ 2022-04-06 12:23 ` Markus Frank
0 siblings, 0 replies; 3+ messages in thread
From: Markus Frank @ 2022-04-06 12:23 UTC (permalink / raw)
To: Proxmox VE development discussion, Daniel Tschlatscher
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
>
>
^ permalink raw reply [flat|nested] 3+ messages in thread
end of thread, other threads:[~2022-04-06 12:23 UTC | newest]
Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-03-29 10:47 [pve-devel] [PATCH pve-qemu v3] fix #3865: backup restore human readable output Daniel Tschlatscher
2022-04-06 12:05 ` Markus Frank
2022-04-06 12:23 ` Markus Frank
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox