v2.22.1 and later regression wrt display of progress indicators

v2.22.1 and later regression wrt display of progress indicators

[Charles Diza]

By 2.22.1 at the latest (and continuing into 2.23.0) there is a problem with the display of progress indication during `git pull` (and possibly other commands, I don't know).

I'm on macOS, and this happens in both Terminal.app and iTerm2.app, on both macOS 10.13.6 and 10.14.6:  In a standard 80-column wide terminal window, cd into a git repo and do `git pull`.  The chances are high (though not 100%) that one will see this:

remote:                                                                         remote: Enumerating objects: 82, done.
remote:                                                                         remote:                                                                         remote:                                                                         remote:                                                                         remote:                                                                         
[snip a large number of duplicate lines]
remote:                                                                         remote: 
remote: Counting objects: 100% (82/82), done.
remote:                                                                         remote:                                                                         remote:                                                                         remote:                                                                         remote:                                                                         remote:                                                                         remote: Compressing objects: 100% (5/5), done.
remote: Total 111 (delta 78), reused 78 (delta 77), pack-reused 29

It used to be that there were *no* lines that appear to consist just of "remote:".  I say "appear" because most occurrences of "remote:" are followed by a bunch of spaces rather than linebreaks.

Charles

Re: v2.22.1 and later regression wrt display of progress indicators

[SZEDER Gábor]

On Thu, Aug 22, 2019 at 10:20:08AM -0400, Charles Diza wrote:
> By 2.22.1 at the latest (and continuing into 2.23.0) there is a
> problem with the display of progress indication during `git pull`
> (and possibly other commands, I don't know).
> 
> I'm on macOS, and this happens in both Terminal.app and iTerm2.app,
> on both macOS 10.13.6 and 10.14.6:  In a standard 80-column wide
> terminal window, cd into a git repo and do `git pull`.  The chances
> are high (though not 100%) that one will see this:

I noticed this today when pushing to GitHub (I suppose they have very
recently upgraded?) from Linux, so this is neither specific to 'git
pull' nor to macOS.

I'm sure the culprits are commits cd1096b282 (pager: add a helper
function to clear the last line in the terminal, 2019-06-24) and
5b12e3123b (progress: use term_clear_line(), 2019-06-24) with the
added complication of communicating with a remote.

If the standard error of 'git pull/push' is connected to a terminal,
then it will tell the transport helpers and in turn to the 'git
upload-pack/receive-pack' processes on the remote to produce progress
output.  However, since those processes run on the other side of the
internet, they don't have any idea about the local terminal (smart or
dumb?  how wide?) their progress will end up on, and, consequently,
they assume the worst, i.e. standard-width dumb terminal, and use 80
spaces to cover up the previously displayed progress line.

I'm not sure how to handle the situation.  A few ideas to consider:

  1. Update 'git upload-pack/receive-pack' to use some kind of magic
     character or char sequence instead of a "real" line clearing
     sequence, and update 'git pull/push' to replace that magic with
     the line clearing sequence appropriate for the terminal.

  2. Variant of the above: leave 'git upload-pack/receive-pack' as they
     are now, and declare that those 80 spaces indicate when to clear
     progress lines.  Update 'git push/pull' to catch those 80 spaces,
     and replace them with the line clearing sequence appropriate for
     the terminal.

  3. Update 'git pull/push' to explicitly tell the remote what line
     clearing sequence to use.

  4. Revert, and go back to calculating how many spaces we need to
     append to clear the previously displayed progress line, and hope
     that we don't mess it up (or even if we do, it still won't be as
     noticable as this).

I suppose this issue affects other git clients as well, so (1), (2),
and (3) might not even be an option.

Re: v2.22.1 and later regression wrt display of progress indicators

[Jeff King]

On Thu, Aug 22, 2019 at 06:07:02PM +0200, SZEDER Gábor wrote:

> On Thu, Aug 22, 2019 at 10:20:08AM -0400, Charles Diza wrote:
> > By 2.22.1 at the latest (and continuing into 2.23.0) there is a
> > problem with the display of progress indication during `git pull`
> > (and possibly other commands, I don't know).
> > 
> > I'm on macOS, and this happens in both Terminal.app and iTerm2.app,
> > on both macOS 10.13.6 and 10.14.6:  In a standard 80-column wide
> > terminal window, cd into a git repo and do `git pull`.  The chances
> > are high (though not 100%) that one will see this:
> 
> I noticed this today when pushing to GitHub (I suppose they have very
> recently upgraded?) from Linux, so this is neither specific to 'git
> pull' nor to macOS.
> 
> I'm sure the culprits are commits cd1096b282 (pager: add a helper
> function to clear the last line in the terminal, 2019-06-24) and
> 5b12e3123b (progress: use term_clear_line(), 2019-06-24) with the
> added complication of communicating with a remote.

Yes, we moved to v2.22.1 last night. I'll revert those commits on our
servers until we come up with a more permanent solution upstream.

> I'm not sure how to handle the situation.  A few ideas to consider:
> 
>   1. Update 'git upload-pack/receive-pack' to use some kind of magic
>      character or char sequence instead of a "real" line clearing
>      sequence, and update 'git pull/push' to replace that magic with
>      the line clearing sequence appropriate for the terminal.
> 
>   2. Variant of the above: leave 'git upload-pack/receive-pack' as they
>      are now, and declare that those 80 spaces indicate when to clear
>      progress lines.  Update 'git push/pull' to catch those 80 spaces,
>      and replace them with the line clearing sequence appropriate for
>      the terminal.
> 
>   3. Update 'git pull/push' to explicitly tell the remote what line
>      clearing sequence to use.
> 
>   4. Revert, and go back to calculating how many spaces we need to
>      append to clear the previously displayed progress line, and hope
>      that we don't mess it up (or even if we do, it still won't be as
>      noticable as this).
> 
> I suppose this issue affects other git clients as well, so (1), (2),
> and (3) might not even be an option.

Yes on that final bit. We could always fall back to (4) if the terminal
information is not available, but given that the benefit is mostly in
simplifying the code, I don't know if it's worth carrying around _two_
solutions.

One interesting bit: we have traditionally used \033[K on the _client_
side of the sideband demuxer. So I think in the "remote:" case we were
already handling this correctly, even before your patch.

-Peff

Re: v2.22.1 and later regression wrt display of progress indicators

[SZEDER Gábor]

On Thu, Aug 22, 2019 at 12:29:08PM -0400, Jeff King wrote:
> On Thu, Aug 22, 2019 at 06:07:02PM +0200, SZEDER Gábor wrote:
> > I noticed this today when pushing to GitHub (I suppose they have very
> > recently upgraded?) from Linux, so this is neither specific to 'git
> > pull' nor to macOS.
> > 
> > I'm sure the culprits are commits cd1096b282 (pager: add a helper
> > function to clear the last line in the terminal, 2019-06-24) and
> > 5b12e3123b (progress: use term_clear_line(), 2019-06-24) with the
> > added complication of communicating with a remote.
> 
> Yes, we moved to v2.22.1 last night. I'll revert those commits on our
> servers until we come up with a more permanent solution upstream.

I think it's sufficient to revert only 5b12e3123b (progress: use
term_clear_line(), 2019-06-24).  I only mentioned cd1096b282 here
because it better explains the reasons for having term_clear_line(),
and an other patch depends on that function as well.

Or you can simply revert the whole series, of course :)

> One interesting bit: we have traditionally used \033[K on the _client_
> side of the sideband demuxer. So I think in the "remote:" case we were
> already handling this correctly, even before your patch.

Gah, I feared that the term "sideband multiplexer" will soon come up
in this discussion...

Re: v2.22.1 and later regression wrt display of progress indicators

[Jeff King]

On Thu, Aug 22, 2019 at 06:40:32PM +0200, SZEDER Gábor wrote:

> > Yes, we moved to v2.22.1 last night. I'll revert those commits on our
> > servers until we come up with a more permanent solution upstream.
> 
> I think it's sufficient to revert only 5b12e3123b (progress: use
> term_clear_line(), 2019-06-24).  I only mentioned cd1096b282 here
> because it better explains the reasons for having term_clear_line(),
> and an other patch depends on that function as well.

Yes, that's what we did. :) It's out now, so everybody should see the
fix.

> > One interesting bit: we have traditionally used \033[K on the _client_
> > side of the sideband demuxer. So I think in the "remote:" case we were
> > already handling this correctly, even before your patch.
> 
> Gah, I feared that the term "sideband multiplexer" will soon come up
> in this discussion...

It may open up some new options for us, though.

If we know on the server side that we are serving a remote request
(which is easy, and does not require client cooperation), can we assume
that the other side will show any sideband lines with its own
end-of-line clearing?

I'm not sure. Git does and always has (and even on a dumb terminal makes
a token effort at throwing some spaces in ;) ). But I'm not sure if
other clients do (and they of course might not even be displaying to a
terminal at all, if they're pulling sideband data into a GUI dialog or
similar).

-Peff

Re: v2.22.1 and later regression wrt display of progress indicators

[Taylor Blau]

On Thu, Aug 22, 2019 at 12:29:08PM -0400, Jeff King wrote:
> On Thu, Aug 22, 2019 at 06:07:02PM +0200, SZEDER Gábor wrote:
>
> > On Thu, Aug 22, 2019 at 10:20:08AM -0400, Charles Diza wrote:
> > > By 2.22.1 at the latest (and continuing into 2.23.0) there is a
> > > problem with the display of progress indication during `git pull`
> > > (and possibly other commands, I don't know).
> > >
> > > I'm on macOS, and this happens in both Terminal.app and iTerm2.app,
> > > on both macOS 10.13.6 and 10.14.6:  In a standard 80-column wide
> > > terminal window, cd into a git repo and do `git pull`.  The chances
> > > are high (though not 100%) that one will see this:
> >
> > I noticed this today when pushing to GitHub (I suppose they have very
> > recently upgraded?) from Linux, so this is neither specific to 'git
> > pull' nor to macOS.
> >
> > I'm sure the culprits are commits cd1096b282 (pager: add a helper
> > function to clear the last line in the terminal, 2019-06-24) and
> > 5b12e3123b (progress: use term_clear_line(), 2019-06-24) with the
> > added complication of communicating with a remote.
>
> Yes, we moved to v2.22.1 last night. I'll revert those commits on our
> servers until we come up with a more permanent solution upstream.
>
> > I'm not sure how to handle the situation.  A few ideas to consider:
> >
> >   1. Update 'git upload-pack/receive-pack' to use some kind of magic
> >      character or char sequence instead of a "real" line clearing
> >      sequence, and update 'git pull/push' to replace that magic with
> >      the line clearing sequence appropriate for the terminal.
> >
> >   2. Variant of the above: leave 'git upload-pack/receive-pack' as they
> >      are now, and declare that those 80 spaces indicate when to clear
> >      progress lines.  Update 'git push/pull' to catch those 80 spaces,
> >      and replace them with the line clearing sequence appropriate for
> >      the terminal.
> >
> >   3. Update 'git pull/push' to explicitly tell the remote what line
> >      clearing sequence to use.
> >
> >   4. Revert, and go back to calculating how many spaces we need to
> >      append to clear the previously displayed progress line, and hope
> >      that we don't mess it up (or even if we do, it still won't be as
> >      noticable as this).
> >
> > I suppose this issue affects other git clients as well, so (1), (2),
> > and (3) might not even be an option.
>
> Yes on that final bit. We could always fall back to (4) if the terminal
> information is not available, but given that the benefit is mostly in
> simplifying the code, I don't know if it's worth carrying around _two_
> solutions.

My thoughts exactly. I think that I prefer the solutions in the order
{2, 1, 3, 4}, but (4) seems to be the most feasible by far.

Should we revert the series?

> One interesting bit: we have traditionally used \033[K on the _client_
> side of the sideband demuxer. So I think in the "remote:" case we were
> already handling this correctly, even before your patch.
>
> -Peff
Thanks,
Taylor

[PATCH 0/2] Revert "progress: use term_clear_line()"

[SZEDER Gábor]

On Thu, Aug 22, 2019 at 12:29:08PM -0400, Jeff King wrote:
> On Thu, Aug 22, 2019 at 06:07:02PM +0200, SZEDER Gábor wrote:
> 
> > On Thu, Aug 22, 2019 at 10:20:08AM -0400, Charles Diza wrote:
> > > By 2.22.1 at the latest (and continuing into 2.23.0) there is a
> > > problem with the display of progress indication during `git pull`
> > > (and possibly other commands, I don't know).
> > > 
> > > I'm on macOS, and this happens in both Terminal.app and iTerm2.app,
> > > on both macOS 10.13.6 and 10.14.6:  In a standard 80-column wide
> > > terminal window, cd into a git repo and do `git pull`.  The chances
> > > are high (though not 100%) that one will see this:
> > 
> > I noticed this today when pushing to GitHub (I suppose they have very
> > recently upgraded?) from Linux, so this is neither specific to 'git
> > pull' nor to macOS.
> > 
> > I'm sure the culprits are commits cd1096b282 (pager: add a helper
> > function to clear the last line in the terminal, 2019-06-24) and
> > 5b12e3123b (progress: use term_clear_line(), 2019-06-24) with the
> > added complication of communicating with a remote.

> > I'm not sure how to handle the situation.  A few ideas to consider:

> >   4. Revert, and go back to calculating how many spaces we need to
> >      append to clear the previously displayed progress line, and hope
> >      that we don't mess it up (or even if we do, it still won't be as
> >      noticable as this).
> > 
> > I suppose this issue affects other git clients as well, so (1), (2),
> > and (3) might not even be an option.
> 
> Yes on that final bit. We could always fall back to (4) if the terminal
> information is not available, but given that the benefit is mostly in
> simplifying the code, I don't know if it's worth carrying around _two_
> solutions.

Ok, so here is a patch to revert 5b12e3123b (progress: use
term_clear_line(), 2019-06-24) with proper explanation.

As a bonus there is a new test script exercising the progress display
as well, in particular how it covers up the previous progress line, so
we may have a bit more confidence in it.


SZEDER Gábor (2):
  Revert "progress: use term_clear_line()"
  Test the progress display

 Makefile                    |   1 +
 progress.c                  |  61 ++++++--
 t/helper/test-progress.c    |  81 ++++++++++
 t/helper/test-tool.c        |   1 +
 t/helper/test-tool.h        |   1 +
 t/t0500-progress-display.sh | 286 ++++++++++++++++++++++++++++++++++++
 t/t5541-http-push-smart.sh  |   6 +-
 7 files changed, 421 insertions(+), 16 deletions(-)
 create mode 100644 t/helper/test-progress.c
 create mode 100755 t/t0500-progress-display.sh

-- 
2.23.0.331.g4e51dcdf11

[PATCH 1/2] Revert "progress: use term_clear_line()"

[SZEDER Gábor]

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: <many-spaces>' 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 <szeder.dev@gmail.com>
---
 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' '
-- 
2.23.0.331.g4e51dcdf11

[PATCH 2/2] Test the progress display

[SZEDER Gábor]

'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 <szeder.dev@gmail.com>
---
 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 ad71ae1219..3ca48ec4b0 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 <items>" - Call display_progress() with the given item count
+ *                        as parameter.
+ *   "throughput <bytes> <millis> - 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=<n>] <progress-title>",
+		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/<CR>\\$LF/g"
+}
+
+test_expect_success 'simple progress display' '
+	cat >expect <<-\EOF &&
+	Working hard: 1<CR>
+	Working hard: 2<CR>
+	Working hard: 5<CR>
+	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" <in 2>stderr &&
+
+	show_cr <stderr >out &&
+	test_i18ncmp expect out
+'
+
+test_expect_success 'progress display with total' '
+	cat >expect <<-\EOF &&
+	Working hard:  33% (1/3)<CR>
+	Working hard:  66% (2/3)<CR>
+	Working hard: 100% (3/3)<CR>
+	Working hard: 100% (3/3), done.
+	EOF
+
+	cat >in <<-\EOF &&
+	progress 1
+	progress 2
+	progress 3
+	EOF
+	test-tool progress --total=3 "Working hard" <in 2>stderr &&
+
+	show_cr <stderr >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)<CR>
+Working hard.......2.........3.........4.........5.........6:   1% (1000/100000)<CR>
+Working hard.......2.........3.........4.........5.........6:                   Z
+   10% (10000/100000)<CR>
+  100% (100000/100000)<CR>
+  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" \
+		<in 2>stderr &&
+
+	show_cr <stderr >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)<CR>
+Working hard.......2.........3.........4.........5.........6:   0% (2/100000)<CR>
+Working hard.......2.........3.........4.........5.........6:                   Z
+   10% (10000/100000)<CR>
+  100% (100000/100000)<CR>
+  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" \
+		<in 2>stderr &&
+
+	show_cr <stderr >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)<CR>
+   50% (50000/100000)<CR>
+   75% (75000/100000)<CR>
+  100% (100000/100000)<CR>
+  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" \
+		<in 2>stderr &&
+
+	show_cr <stderr >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)<CR>
+   50% (50000/100000)<CR>
+   75% (75000/100000)<CR>
+  100% (100000/100000)<CR>
+  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........." \
+		<in 2>stderr &&
+
+	show_cr <stderr >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)<CR>
+	Working hard:  20% (200/1000)<CR>
+	Working hard:   0% (1/1000)  <CR>
+	Working hard: 100% (1000/1000)<CR>
+	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" <in 2>stderr &&
+
+	show_cr <stderr >out &&
+	test_i18ncmp expect out
+'
+
+test_expect_success 'progress display with throughput' '
+	cat >expect <<-\EOF &&
+	Working hard: 10<CR>
+	Working hard: 20, 200.00 KiB | 100.00 KiB/s<CR>
+	Working hard: 30, 300.00 KiB | 100.00 KiB/s<CR>
+	Working hard: 40, 400.00 KiB | 100.00 KiB/s<CR>
+	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" <in 2>stderr &&
+
+	show_cr <stderr >out &&
+	test_i18ncmp expect out
+'
+
+test_expect_success 'progress display with throughput and total' '
+	cat >expect <<-\EOF &&
+	Working hard:  25% (10/40)<CR>
+	Working hard:  50% (20/40), 200.00 KiB | 100.00 KiB/s<CR>
+	Working hard:  75% (30/40), 300.00 KiB | 100.00 KiB/s<CR>
+	Working hard: 100% (40/40), 400.00 KiB | 100.00 KiB/s<CR>
+	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" <in 2>stderr &&
+
+	show_cr <stderr >out &&
+	test_i18ncmp expect out
+'
+
+test_expect_success 'cover up after throughput shortens' '
+	cat >expect <<-\EOF &&
+	Working hard: 1<CR>
+	Working hard: 2, 800.00 KiB | 400.00 KiB/s<CR>
+	Working hard: 3, 1.17 MiB | 400.00 KiB/s  <CR>
+	Working hard: 4, 1.56 MiB | 400.00 KiB/s<CR>
+	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" <in 2>stderr &&
+
+	show_cr <stderr >out &&
+	test_i18ncmp expect out
+'
+
+test_expect_success 'cover up after throughput shortens a lot' '
+	cat >expect <<-\EOF &&
+	Working hard: 1<CR>
+	Working hard: 2, 1000.00 KiB | 1000.00 KiB/s<CR>
+	Working hard: 3, 3.00 MiB | 1.50 MiB/s      <CR>
+	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" <in 2>stderr &&
+
+	show_cr <stderr >out &&
+	test_i18ncmp expect out
+'
+
+test_done
-- 
2.23.0.331.g4e51dcdf11

Re: [PATCH 0/2] Revert "progress: use term_clear_line()"

[Jeff King]

On Mon, Sep 16, 2019 at 10:54:10PM +0200, SZEDER Gábor wrote:

> > Yes on that final bit. We could always fall back to (4) if the terminal
> > information is not available, but given that the benefit is mostly in
> > simplifying the code, I don't know if it's worth carrying around _two_
> > solutions.
> 
> Ok, so here is a patch to revert 5b12e3123b (progress: use
> term_clear_line(), 2019-06-24) with proper explanation.
> 
> As a bonus there is a new test script exercising the progress display
> as well, in particular how it covers up the previous progress line, so
> we may have a bit more confidence in it.

Thanks for doing this. It's especially nice to get test coverage for the
progress meters, which have traditionally been neglected.

I'm a little late on my review, as it looks like this has already hit
next, but it looks pretty good to me.

My only complaint is that I think putting the new "private" bits of the
progress API into the header (with a comment) is a lesser evil than
re-declaring them in test-progress.c (if only because the compiler could
tell us if the two get out of sync). But I can live with it either way.

-Peff

Re: v2.22.1 and later regression wrt display of progress indicators

[Taylor Blau]

Hi,

On Thu, Aug 22, 2019 at 06:07:02PM +0200, SZEDER Gábor wrote:
> On Thu, Aug 22, 2019 at 10:20:08AM -0400, Charles Diza wrote:
> > By 2.22.1 at the latest (and continuing into 2.23.0) there is a
> > problem with the display of progress indication during `git pull`
> > (and possibly other commands, I don't know).
> >
> > I'm on macOS, and this happens in both Terminal.app and iTerm2.app,
> > on both macOS 10.13.6 and 10.14.6:  In a standard 80-column wide
> > terminal window, cd into a git repo and do `git pull`.  The chances
> > are high (though not 100%) that one will see this:
>
> I noticed this today when pushing to GitHub (I suppose they have very
> recently upgraded?) from Linux, so this is neither specific to 'git
> pull' nor to macOS.

There's already lots of discussion later on in the thread (which I'm
reading now), but I just wanted to reply to this hunk to say 'thanks'
for pointing out the issue in the first place.

> I'm sure the culprits are commits cd1096b282 (pager: add a helper
> function to clear the last line in the terminal, 2019-06-24) and
> 5b12e3123b (progress: use term_clear_line(), 2019-06-24) with the
> added complication of communicating with a remote.

Thanks also for pointing out the culprits here and saving me a
bisection.

If you're curious, I only reverted 5b12e3123b (progress: use
term_clear_line(), 2019-06-24), not the former.

> [snip]


Thanks,
Taylor