Re: [PATCH] makedumpfile: Improve progress information for huge memory system.

[Vivek Goyal]

On Fri, Jan 17, 2014 at 05:39:35PM +0800, Baoquan He wrote:
> Backport from upstream.
>
> commit 20ecc0827e7837c52f3903638a59959f8bf17f9e
> Author: HATAYAMA Daisuke 
> Date:   Tue Nov 5 00:29:35 2013 +0900
> [PATCH v2] Improve progress information for huge memory system.
>
> On system with huge memory, percentage in progress information is
> updated at very slow interval, because 1 percent on 1 TiB memory is
> about 10 GiB, which looks like as if system has freezed. Then,
> confused users might get tempted to push a reset button to recover the
> system. We want to avoid such situation as much as possible.
>
> Signed-off-by: HATAYAMA Daisuke <[e-mail]>
>
> Signed-off-by: Baoquan He

Acked-by: Vivek Goyal

Vivek
> ...prove-progress-information-for-huge-memor.patch | 200 +++++++++++++++++++++
>  1 file changed, 200 insertions(+)
>  create mode 100644 kexec-tools-2.0.4-makedumpfile-Improve-progress-information-for-huge-memor.patch
>
> diff --git a/kexec-tools-2.0.4-makedumpfile-Improve-progress-information-for-huge-memor.patch b/kexec-tools-2.0.4-makedumpfile-Improve-progress-information-for-huge-memor.patch
> new file mode 100644
> index 0000000..9b15185
> --- /dev/null
> +++ b/kexec-tools-2.0.4-makedumpfile-Improve-progress-information-for-huge-memor.patch
> @@ -0,0 +1,200 @@
> +From 20ecc0827e7837c52f3903638a59959f8bf17f9e Mon Sep 17 00:00:00 2001
> +From: HATAYAMA Daisuke 
> +Date: Tue, 5 Nov 2013 00:29:35 +0900
> +Subject: [PATCH] [PATCH v2] Improve progress information for huge memory
> system.
>
> +On system with huge memory, percentage in progress information is
> +updated at very slow interval, because 1 percent on 1 TiB memory is
> +about 10 GiB, which looks like as if system has freezed. Then,
> +confused users might get tempted to push a reset button to recover the
> +system. We want to avoid such situation as much as possible.
>
> +To address the issue, this patch:
>
> +- increases the number of calling print_progress() from once in
> (written pages / 100)-pages to once in (written pages /
> 10000)-pages,
>
> +- extends precision in progress information by adding 1 digit to its
> fractional part, and
>
> +- adds spinner that rotates in the order of /, |, \ and - in next to
> the progress indicator in percentage,
>
> +which help users to get aware that system is still active and crash
> +dump process is still in progress now.
>
> +The spinner code is borrowed from diskdump code.
>
> +The ouput is changed from:
>
> +Copying data                       : [  0 %] /
> +Copying data                       : [  8 %] |
> +Copying data                       : [ 11 %] \
> +Copying data                       : [ 14 %] -
> +Copying data                       : [ 16 %] /
> +...
> +Copying data                       : [ 99 %] /
> +Copying data                       : [100 %] |
>
> +to:
>
> +Copying data                       : [  0.1 %] /
> +Copying data                       : [  8.9 %] |
> +Copying data                       : [ 11.6 %] \
> +Copying data                       : [ 14.3 %] -
> +Copying data                       : [ 16.4 %] /
> +...
> +Copying data                       : [ 99.2 %] /
> +Copying data                       : [100.0 %] |
>
> +This patch doesn't adopt purely time-based approach that records the
> +time when print_progress() is called at each invocation and print the
> +recorded time if it is strictly larger than the previous time value.
>
> +The problem is that calling time() system call amounts to
> +considertably long time in total on huge memory system. For example,
> +here is a simple bench that measures total execution time of time()
> +system call for (1TiB / 4KiB)-times:
>
> +$ ./bench
> +total: 18.360503
> +total: 34.910297
>
> +the result of which reveals that it amounts to about 20 seconds with
> +vDSO optimization and about 35 seconds without.
>
> +BTW, on our 12 TiB memory system, we collect about 300 GiB crash dump
> +in about 40 minutes with dump level 31. On 12TiB, the benchmark result
> +corresponds to about 4 minutes and 7 minutes respectively, both of which
> +affects a whole performance.
>
> +==bench.c
> +static inline double getdtime(void)
> +{
>    struct timeval tv;
>    gettimeofday(&tv, NULL);
>    return (double)tv.tv_sec + (double)tv.tv_usec * 1.0e-6;
>
> +}
>
> +int main(int argc, char **argv)
> +{
>    unsigned long i;
>    time_t t;
>    double t1, t2, total;
>    const int NR_time = 201;
>    const unsigned long nr_repeat = (1UL << 40) / 4096;
>    total = 0;
>    for (i = 0; i < nr_repeat; ++i) {
>            t1 = getdtime();
>            time(&t);
>            t2 = getdtime();
>            total += t2 - t1;
>    }
>    printf("total: %lf\n", total);
>    total = 0;
>    for (i = 0; i < nr_repeat; ++i) {
>            t1 = getdtime();
>            syscall(NR_time, &t);
>            t2 = getdtime();
>            total += t2 - t1;
>    }
>    printf("total: %lf\n", total);
>    return 0;
>
> +}
> +==
>
> +Signed-off-by: HATAYAMA Daisuke 
> +---
> makedumpfile.c |  8 ++++----
> print_info.c   | 15 +++++++++------
> 2 files changed, 13 insertions(+), 10 deletions(-)
>
> +diff --git a/makedumpfile-1.5.4/makedumpfile.c b/makedumpfile-1.5.4/makedumpfile.c
> +index dafe83b..3746cf6 100644
> +--- a/makedumpfile-1.5.4/makedumpfile.c
> ++++ b/makedumpfile-1.5.4/makedumpfile.c
> +@@ -5573,7 +5573,7 @@ write_elf_pages(struct cache_data *cd_header, struct cache_data *cd_page)
> initialize_2nd_bitmap(&bitmap2);
> num_dumpable = get_num_dumpable();
>
> +-	per = num_dumpable / 100;
> ++	per = num_dumpable / 10000;
> off_seg_load    = info->offset_load_dumpfile;
> cd_page->offset = info->offset_load_dumpfile;
>
> +@@ -5858,7 +5858,7 @@ write_elf_pages_cyclic(struct cache_data *cd_header, struct cache_data *cd_page)
> return FALSE;
> num_dumpable = info->num_dumpable;
>
> +-	per = num_dumpable / 100;
> ++	per = num_dumpable / 10000;
> off_seg_load   = info->offset_load_dumpfile;
> cd_page->offset = info->offset_load_dumpfile;
>
> +@@ -6116,7 +6116,7 @@ write_kdump_pages(struct cache_data *cd_header, struct cache_data *cd_page)
> }
> num_dumpable = get_num_dumpable();
>
> +-	per = num_dumpable / 100;
> ++	per = num_dumpable / 10000;
> /*
> * Calculate the offset of the page data.
>
> +@@ -6317,7 +6317,7 @@ write_kdump_pages_cyclic(struct cache_data *cd_header, struct cache_data *cd_pag
> goto out;
> }
>
> +-	per = info->num_dumpable / 100;
> ++	per = info->num_dumpable / 10000;
> /*
> * Set a fileoffset of Physical Address 0x0.
>
> +diff --git a/makedumpfile-1.5.4/print_info.c b/makedumpfile-1.5.4/print_info.c
> +index 3527970..d7a8600 100644
> +--- a/makedumpfile-1.5.4/print_info.c
> ++++ b/makedumpfile-1.5.4/print_info.c
> +@@ -283,27 +283,30 @@ print_usage(void)
> void
> print_progress(const char *msg, unsigned long current, unsigned long end)
> {
>
> +-	int progress;
> ++	float progress;
> time_t tm;
> static time_t last_time = 0;
>
> ++	static unsigned int lapse = 0;
> ++	static const char *spinner = "/|\-";
> if (current < end) {
> tm = time(NULL);
> if (tm - last_time < 1)
> 	return;
> last_time = tm;
>
> +-		progress = current * 100 / end;
> ++		progress = (float)current * 100 / end;
> } else
> progress = 100;
> if (flag_ignore_r_char) {
>
> +-		PROGRESS_MSG("%-" PROGRESS_MAXLEN "s: [%3d %%]\n",
> +-			     msg, progress);
> ++		PROGRESS_MSG("%-" PROGRESS_MAXLEN "s: [%5.1f %%] %c\n",
> ++			     msg, progress, spinner[lapse % 4]);
> } else {
> PROGRESS_MSG("\r");
>
> +-		PROGRESS_MSG("%-" PROGRESS_MAXLEN "s: [%3d %%] ",
> +-			     msg, progress);
> ++		PROGRESS_MSG("%-" PROGRESS_MAXLEN "s: [%5.1f %%] %c",
> ++			     msg, progress, spinner[lapse % 4]);
> }
>
> ++	lapse++;
> }
> void
>
> +-- 
> +1.8.3.1
>
> -- 
> 1.8.3.1