From bbf47568ad7e91ab0962b314c054a2da03232c72 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?SZEDER=20G=C3=A1bor?= Date: Mon, 16 Sep 2019 22:54:11 +0200 Subject: [PATCH 1/2] Revert "progress: use term_clear_line()" MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This reverts commit 5b12e3123b (progress: use term_clear_line(), 2019-06-24), because covering up the entire last line while refreshing the progress line caused unexpected problems during 'git clone/fetch/push': $ git clone ssh://localhost/home/szeder/src/tmp/linux.git/ Cloning into 'linux'... remote: remote: remote: remote: Enumerating objects: 999295 The length of the progress bar line can shorten when it includes throughput and the unit changes, or when its length exceeds the width of the terminal and is broken into two lines. In these cases the previously displayed longer progress line should be covered up, because otherwise the leftover characters from the previous progress line make the output look weird [1]. term_clear_line() makes this quite simple, as it covers up the entire last line either by using an ANSI control sequence or by printing a terminal width worth of space characters, depending on whether the terminal is smart or dumb. Unfortunately, when accessing a remote repository via any non-local protocol the remote 'git receive-pack/upload-pack' processes can't possibly have any idea about the local terminal (smart of dumb? how wide?) their progress will end up on. Consequently, they assume the worst, i.e. standard-width dumb terminal, and print 80 spaces to cover up the previously displayed progress line. The local 'git clone/fetch/push' processes then display the remote's progress, including these coverup spaces, with the 'remote: ' prefix, resulting in a total line length of 88 characters. If the local terminal is narrower than that, then the coverup gets line-wrapped, and after that the CR at the end doesn't return to the beginning of the progress line, but to the first column of its last line, resulting in those repeated 'remote: ' lines. By reverting 5b12e3123b (progress: use term_clear_line(), 2019-06-24) we won't cover up the entire last line, but go back to comparing the length of the current progress bar line with the previous one, and cover up as many characters as needed. [1] See commits 545dc345eb (progress: break too long progress bar lines, 2019-04-12) and 9f1fd84e15 (progress: clear previous progress update dynamically, 2019-04-12). Signed-off-by: SZEDER Gábor Signed-off-by: Junio C Hamano --- progress.c | 29 ++++++++++++++++++----------- t/t5541-http-push-smart.sh | 6 +++--- 2 files changed, 21 insertions(+), 14 deletions(-) diff --git a/progress.c b/progress.c index 277db8afa2..0eddf1804d 100644 --- a/progress.c +++ b/progress.c @@ -88,6 +88,7 @@ static void display(struct progress *progress, uint64_t n, const char *done) const char *tp; struct strbuf *counters_sb = &progress->counters_sb; int show_update = 0; + int last_count_len = counters_sb->len; if (progress->delay && (!progress_update || --progress->delay)) return; @@ -115,21 +116,27 @@ static void display(struct progress *progress, uint64_t n, const char *done) if (show_update) { if (is_foreground_fd(fileno(stderr)) || done) { const char *eol = done ? done : "\r"; + size_t clear_len = counters_sb->len < last_count_len ? + last_count_len - counters_sb->len + 1 : + 0; + /* The "+ 2" accounts for the ": ". */ + size_t progress_line_len = progress->title_len + + counters_sb->len + 2; + int cols = term_columns(); - term_clear_line(); if (progress->split) { - fprintf(stderr, " %s%s", counters_sb->buf, - eol); - } else if (!done && - /* The "+ 2" accounts for the ": ". */ - term_columns() < progress->title_len + - counters_sb->len + 2) { - fprintf(stderr, "%s:\n %s%s", - progress->title, counters_sb->buf, eol); + fprintf(stderr, " %s%*s", counters_sb->buf, + (int) clear_len, eol); + } else if (!done && cols < progress_line_len) { + clear_len = progress->title_len + 1 < cols ? + cols - progress->title_len - 1 : 0; + fprintf(stderr, "%s:%*s\n %s%s", + progress->title, (int) clear_len, "", + counters_sb->buf, eol); progress->split = 1; } else { - fprintf(stderr, "%s: %s%s", progress->title, - counters_sb->buf, eol); + fprintf(stderr, "%s: %s%*s", progress->title, + counters_sb->buf, (int) clear_len, eol); } fflush(stderr); } diff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh index b86ddb60f2..92bac43257 100755 --- a/t/t5541-http-push-smart.sh +++ b/t/t5541-http-push-smart.sh @@ -262,7 +262,7 @@ test_expect_success TTY 'push shows progress when stderr is a tty' ' cd "$ROOT_PATH"/test_repo_clone && test_commit noisy && test_terminal git push >output 2>&1 && - test_i18ngrep "Writing objects" output + test_i18ngrep "^Writing objects" output ' test_expect_success TTY 'push --quiet silences status and progress' ' @@ -277,7 +277,7 @@ test_expect_success TTY 'push --no-progress silences progress but not status' ' test_commit no-progress && test_terminal git push --no-progress >output 2>&1 && test_i18ngrep "^To http" output && - test_i18ngrep ! "Writing objects" output + test_i18ngrep ! "^Writing objects" output ' test_expect_success 'push --progress shows progress to non-tty' ' @@ -285,7 +285,7 @@ test_expect_success 'push --progress shows progress to non-tty' ' test_commit progress && git push --progress >output 2>&1 && test_i18ngrep "^To http" output && - test_i18ngrep "Writing objects" output + test_i18ngrep "^Writing objects" output ' test_expect_success 'http push gives sane defaults to reflog' ' From 2bb74b53a49f92d433057f4d560b33f1fe2f770a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?SZEDER=20G=C3=A1bor?= Date: Mon, 16 Sep 2019 22:54:12 +0200 Subject: [PATCH 2/2] Test the progress display MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 'progress.c' has seen a few fixes recently [1], and, unfortunately, some of those fixes required further fixes [2]. It seems it's time to have a few tests focusing on the subtleties of the progress display. Add the 'test-tool progress' subcommand to help testing the progress display, reading instructions from standard input and turning them into calls to the display_progress() and display_throughput() functions with the given parameters. The progress display is, however, critically dependent on timing, because it's only updated once every second or, if the toal is known in advance, every 1%, and there is the throughput rate as well. These make the progress display far too undeterministic for testing as-is. To address this, add a few testing-specific variables and functions to 'progress.c', allowing the the new test helper to: - Disable the triggered-every-second SIGALRM and set the 'progress_update' flag explicitly based in the input instructions. This way the progress line will be updated deterministically when the test wants it to be updated. - Specify the time elapsed since start_progress() to make the throughput rate calculations deterministic. Add the new test script 't0500-progress-display.sh' to check a few simple cases with and without throughput, and that a shorter progress line properly covers up the previously displayed line in different situations. [1] See commits 545dc345eb (progress: break too long progress bar lines, 2019-04-12) and 9f1fd84e15 (progress: clear previous progress update dynamically, 2019-04-12). [2] 1aed1a5f25 (progress: avoid empty line when breaking the progress line, 2019-05-19) Signed-off-by: SZEDER Gábor Signed-off-by: Junio C Hamano --- Makefile | 1 + progress.c | 32 +++- t/helper/test-progress.c | 81 ++++++++++ t/helper/test-tool.c | 1 + t/helper/test-tool.h | 1 + t/t0500-progress-display.sh | 286 ++++++++++++++++++++++++++++++++++++ 6 files changed, 400 insertions(+), 2 deletions(-) create mode 100644 t/helper/test-progress.c create mode 100755 t/t0500-progress-display.sh diff --git a/Makefile b/Makefile index f9255344ae..a83532e29d 100644 --- a/Makefile +++ b/Makefile @@ -728,6 +728,7 @@ TEST_BUILTINS_OBJS += test-parse-options.o TEST_BUILTINS_OBJS += test-path-utils.o TEST_BUILTINS_OBJS += test-pkt-line.o TEST_BUILTINS_OBJS += test-prio-queue.o +TEST_BUILTINS_OBJS += test-progress.o TEST_BUILTINS_OBJS += test-reach.o TEST_BUILTINS_OBJS += test-read-cache.o TEST_BUILTINS_OBJS += test-read-midx.o diff --git a/progress.c b/progress.c index 0eddf1804d..0063559aab 100644 --- a/progress.c +++ b/progress.c @@ -45,6 +45,19 @@ struct progress { static volatile sig_atomic_t progress_update; +/* + * These are only intended for testing the progress output, i.e. exclusively + * for 'test-tool progress'. + */ +int progress_testing; +uint64_t progress_test_ns = 0; +void progress_test_force_update(void); /* To silence -Wmissing-prototypes */ +void progress_test_force_update(void) +{ + progress_update = 1; +} + + static void progress_interval(int signum) { progress_update = 1; @@ -55,6 +68,9 @@ static void set_progress_signal(void) struct sigaction sa; struct itimerval v; + if (progress_testing) + return; + progress_update = 0; memset(&sa, 0, sizeof(sa)); @@ -72,6 +88,10 @@ static void set_progress_signal(void) static void clear_progress_signal(void) { struct itimerval v = {{0,},}; + + if (progress_testing) + return; + setitimer(ITIMER_REAL, &v, NULL); signal(SIGALRM, SIG_IGN); progress_update = 0; @@ -154,6 +174,14 @@ static void throughput_string(struct strbuf *buf, uint64_t total, strbuf_humanise_rate(buf, rate * 1024); } +static uint64_t progress_getnanotime(struct progress *progress) +{ + if (progress_testing) + return progress->start_ns + progress_test_ns; + else + return getnanotime(); +} + void display_throughput(struct progress *progress, uint64_t total) { struct throughput *tp; @@ -164,7 +192,7 @@ void display_throughput(struct progress *progress, uint64_t total) return; tp = progress->throughput; - now_ns = getnanotime(); + now_ns = progress_getnanotime(progress); if (!tp) { progress->throughput = tp = xcalloc(1, sizeof(*tp)); @@ -296,7 +324,7 @@ void stop_progress_msg(struct progress **p_progress, const char *msg) struct throughput *tp = progress->throughput; if (tp) { - uint64_t now_ns = getnanotime(); + uint64_t now_ns = progress_getnanotime(progress); unsigned int misecs, rate; misecs = ((now_ns - progress->start_ns) * 4398) >> 32; rate = tp->curr_total / (misecs ? misecs : 1); diff --git a/t/helper/test-progress.c b/t/helper/test-progress.c new file mode 100644 index 0000000000..4e9f7fafdf --- /dev/null +++ b/t/helper/test-progress.c @@ -0,0 +1,81 @@ +/* + * A test helper to exercise the progress display. + * + * Reads instructions from standard input, one instruction per line: + * + * "progress " - Call display_progress() with the given item count + * as parameter. + * "throughput - Call display_throughput() with the given + * byte count as parameter. The 'millis' + * specify the time elapsed since the + * start_progress() call. + * "update" - Set the 'progress_update' flag. + * + * See 't0500-progress-display.sh' for examples. + */ +#include "test-tool.h" +#include "gettext.h" +#include "parse-options.h" +#include "progress.h" +#include "strbuf.h" + +/* + * These are defined in 'progress.c', but are not exposed in 'progress.h', + * because they are exclusively for testing. + */ +extern int progress_testing; +extern uint64_t progress_test_ns; +void progress_test_force_update(void); + +int cmd__progress(int argc, const char **argv) +{ + uint64_t total = 0; + const char *title; + struct strbuf line = STRBUF_INIT; + struct progress *progress; + + const char *usage[] = { + "test-tool progress [--total=] ", + NULL + }; + struct option options[] = { + OPT_INTEGER(0, "total", &total, "total number of items"), + OPT_END(), + }; + + argc = parse_options(argc, argv, NULL, options, usage, 0); + if (argc != 1) + die("need a title for the progress output"); + title = argv[0]; + + progress_testing = 1; + progress = start_progress(title, total); + while (strbuf_getline(&line, stdin) != EOF) { + char *end; + + if (skip_prefix(line.buf, "progress ", (const char **) &end)) { + uint64_t item_count = strtoull(end, &end, 10); + if (*end != '\0') + die("invalid input: '%s'\n", line.buf); + display_progress(progress, item_count); + } else if (skip_prefix(line.buf, "throughput ", + (const char **) &end)) { + uint64_t byte_count, test_ms; + + byte_count = strtoull(end, &end, 10); + if (*end != ' ') + die("invalid input: '%s'\n", line.buf); + test_ms = strtoull(end + 1, &end, 10); + if (*end != '\0') + die("invalid input: '%s'\n", line.buf); + progress_test_ns = test_ms * 1000 * 1000; + display_throughput(progress, byte_count); + } else if (!strcmp(line.buf, "update")) + progress_test_force_update(); + else + die("invalid input: '%s'\n", line.buf); + } + stop_progress(&progress); + + return 0; +} diff --git a/t/helper/test-tool.c b/t/helper/test-tool.c index ce7e89028c..19ee26d931 100644 --- a/t/helper/test-tool.c +++ b/t/helper/test-tool.c @@ -42,6 +42,7 @@ static struct test_cmd cmds[] = { { "path-utils", cmd__path_utils }, { "pkt-line", cmd__pkt_line }, { "prio-queue", cmd__prio_queue }, + { "progress", cmd__progress }, { "reach", cmd__reach }, { "read-cache", cmd__read_cache }, { "read-midx", cmd__read_midx }, diff --git a/t/helper/test-tool.h b/t/helper/test-tool.h index f805bb39ae..c2aa56ef50 100644 --- a/t/helper/test-tool.h +++ b/t/helper/test-tool.h @@ -32,6 +32,7 @@ int cmd__parse_options(int argc, const char **argv); int cmd__path_utils(int argc, const char **argv); int cmd__pkt_line(int argc, const char **argv); int cmd__prio_queue(int argc, const char **argv); +int cmd__progress(int argc, const char **argv); int cmd__reach(int argc, const char **argv); int cmd__read_cache(int argc, const char **argv); int cmd__read_midx(int argc, const char **argv); diff --git a/t/t0500-progress-display.sh b/t/t0500-progress-display.sh new file mode 100755 index 0000000000..24ccbd8d3b --- /dev/null +++ b/t/t0500-progress-display.sh @@ -0,0 +1,286 @@ +#!/bin/sh + +test_description='progress display' + +. ./test-lib.sh + +show_cr () { + tr '\015' Q | sed -e "s/Q/\\$LF/g" +} + +test_expect_success 'simple progress display' ' + cat >expect <<-\EOF && + Working hard: 1 + Working hard: 2 + Working hard: 5 + Working hard: 5, done. + EOF + + cat >in <<-\EOF && + update + progress 1 + update + progress 2 + progress 3 + progress 4 + update + progress 5 + EOF + test-tool progress "Working hard" stderr && + + show_cr out && + test_i18ncmp expect out +' + +test_expect_success 'progress display with total' ' + cat >expect <<-\EOF && + Working hard: 33% (1/3) + Working hard: 66% (2/3) + Working hard: 100% (3/3) + Working hard: 100% (3/3), done. + EOF + + cat >in <<-\EOF && + progress 1 + progress 2 + progress 3 + EOF + test-tool progress --total=3 "Working hard" stderr && + + show_cr out && + test_i18ncmp expect out +' + +test_expect_success 'progress display breaks long lines #1' ' + sed -e "s/Z$//" >expect <<\EOF && +Working hard.......2.........3.........4.........5.........6: 0% (100/100000) +Working hard.......2.........3.........4.........5.........6: 1% (1000/100000) +Working hard.......2.........3.........4.........5.........6: Z + 10% (10000/100000) + 100% (100000/100000) + 100% (100000/100000), done. +EOF + + cat >in <<-\EOF && + progress 100 + progress 1000 + progress 10000 + progress 100000 + EOF + test-tool progress --total=100000 \ + "Working hard.......2.........3.........4.........5.........6" \ + stderr && + + show_cr out && + test_i18ncmp expect out +' + +test_expect_success 'progress display breaks long lines #2' ' + # Note: we dont need that many spaces after the title to cover up + # the last line before breaking the progress line. + sed -e "s/Z$//" >expect <<\EOF && +Working hard.......2.........3.........4.........5.........6: 0% (1/100000) +Working hard.......2.........3.........4.........5.........6: 0% (2/100000) +Working hard.......2.........3.........4.........5.........6: Z + 10% (10000/100000) + 100% (100000/100000) + 100% (100000/100000), done. +EOF + + cat >in <<-\EOF && + update + progress 1 + update + progress 2 + progress 10000 + progress 100000 + EOF + test-tool progress --total=100000 \ + "Working hard.......2.........3.........4.........5.........6" \ + stderr && + + show_cr out && + test_i18ncmp expect out +' + +test_expect_success 'progress display breaks long lines #3 - even the first is too long' ' + # Note: we dont actually need any spaces at the end of the title + # line, because there is no previous progress line to cover up. + sed -e "s/Z$//" >expect <<\EOF && +Working hard.......2.........3.........4.........5.........6: Z + 25% (25000/100000) + 50% (50000/100000) + 75% (75000/100000) + 100% (100000/100000) + 100% (100000/100000), done. +EOF + + cat >in <<-\EOF && + progress 25000 + progress 50000 + progress 75000 + progress 100000 + EOF + test-tool progress --total=100000 \ + "Working hard.......2.........3.........4.........5.........6" \ + stderr && + + show_cr out && + test_i18ncmp expect out +' + +test_expect_success 'progress display breaks long lines #4 - title line matches terminal width' ' + cat >expect <<\EOF && +Working hard.......2.........3.........4.........5.........6.........7.........: + 25% (25000/100000) + 50% (50000/100000) + 75% (75000/100000) + 100% (100000/100000) + 100% (100000/100000), done. +EOF + + cat >in <<-\EOF && + progress 25000 + progress 50000 + progress 75000 + progress 100000 + EOF + test-tool progress --total=100000 \ + "Working hard.......2.........3.........4.........5.........6.........7........." \ + stderr && + + show_cr out && + test_i18ncmp expect out +' + +# Progress counter goes backwards, this should not happen in practice. +test_expect_success 'progress shortens - crazy caller' ' + cat >expect <<-\EOF && + Working hard: 10% (100/1000) + Working hard: 20% (200/1000) + Working hard: 0% (1/1000) + Working hard: 100% (1000/1000) + Working hard: 100% (1000/1000), done. + EOF + + cat >in <<-\EOF && + progress 100 + progress 200 + progress 1 + progress 1000 + EOF + test-tool progress --total=1000 "Working hard" stderr && + + show_cr out && + test_i18ncmp expect out +' + +test_expect_success 'progress display with throughput' ' + cat >expect <<-\EOF && + Working hard: 10 + Working hard: 20, 200.00 KiB | 100.00 KiB/s + Working hard: 30, 300.00 KiB | 100.00 KiB/s + Working hard: 40, 400.00 KiB | 100.00 KiB/s + Working hard: 40, 400.00 KiB | 100.00 KiB/s, done. + EOF + + cat >in <<-\EOF && + throughput 102400 1000 + update + progress 10 + throughput 204800 2000 + update + progress 20 + throughput 307200 3000 + update + progress 30 + throughput 409600 4000 + update + progress 40 + EOF + test-tool progress "Working hard" stderr && + + show_cr out && + test_i18ncmp expect out +' + +test_expect_success 'progress display with throughput and total' ' + cat >expect <<-\EOF && + Working hard: 25% (10/40) + Working hard: 50% (20/40), 200.00 KiB | 100.00 KiB/s + Working hard: 75% (30/40), 300.00 KiB | 100.00 KiB/s + Working hard: 100% (40/40), 400.00 KiB | 100.00 KiB/s + Working hard: 100% (40/40), 400.00 KiB | 100.00 KiB/s, done. + EOF + + cat >in <<-\EOF && + throughput 102400 1000 + progress 10 + throughput 204800 2000 + progress 20 + throughput 307200 3000 + progress 30 + throughput 409600 4000 + progress 40 + EOF + test-tool progress --total=40 "Working hard" stderr && + + show_cr out && + test_i18ncmp expect out +' + +test_expect_success 'cover up after throughput shortens' ' + cat >expect <<-\EOF && + Working hard: 1 + Working hard: 2, 800.00 KiB | 400.00 KiB/s + Working hard: 3, 1.17 MiB | 400.00 KiB/s + Working hard: 4, 1.56 MiB | 400.00 KiB/s + Working hard: 4, 1.56 MiB | 400.00 KiB/s, done. + EOF + + cat >in <<-\EOF && + throughput 409600 1000 + update + progress 1 + throughput 819200 2000 + update + progress 2 + throughput 1228800 3000 + update + progress 3 + throughput 1638400 4000 + update + progress 4 + EOF + test-tool progress "Working hard" stderr && + + show_cr out && + test_i18ncmp expect out +' + +test_expect_success 'cover up after throughput shortens a lot' ' + cat >expect <<-\EOF && + Working hard: 1 + Working hard: 2, 1000.00 KiB | 1000.00 KiB/s + Working hard: 3, 3.00 MiB | 1.50 MiB/s + Working hard: 3, 3.00 MiB | 1024.00 KiB/s, done. + EOF + + cat >in <<-\EOF && + throughput 1 1000 + update + progress 1 + throughput 1024000 2000 + update + progress 2 + throughput 3145728 3000 + update + progress 3 + EOF + test-tool progress "Working hard" stderr && + + show_cr out && + test_i18ncmp expect out +' + +test_done