[PATCH v1] progress: print progress output for all operations taking longer than 2s

[PATCH v1] progress: print progress output for all operations taking longer than 2s

[lars.schneider]

From: Lars Schneider <larsxschneider@gmail.com>

In 180a9f2 we implemented a progress API which suppresses the progress
output if the progress has reached a specified percentage threshold
within a given time frame. In 8aade10 we simplified the API and set the
threshold to 0% and the time frame to 2 seconds for all delayed progress
operations. That means we would only see a progress output if we still
have 0% progress after 2 seconds. Consequently, only operations that
have a very slow start would show the progress output at all.

Remove the threshold entirely and print the progress output for all
operations that take longer than 2 seconds.

Signed-off-by: Lars Schneider <larsxschneider@gmail.com>
---

Hi,

a few weeks ago I was puzzled why the progress output is not shown in
certain situations [1]. I debugged the issue a bit today and came up
with this patch as solution. It is entirely possible that I misunderstood
the intentions of the progress API and therefore my patch is bogus.
In this case, please treat this email as RFC.

Thanks,
Lars


[1] https://public-inbox.org/git/DC84FB2E-A26E-4957-B5FA-BE6DDEC3411B@gmail.com/


Notes:
    Base Commit: 1a4e40aa5d (1a4e40aa5dc16564af879142ba9dfbbb88d1e5ff)
    Diff on Web: https://github.com/larsxschneider/git/commit/3e5fdc512a
    Checkout:    git fetch https://github.com/larsxschneider/git progress-fix-v1 && git checkout 3e5fdc512a

 progress.c | 18 +++---------------
 1 file changed, 3 insertions(+), 15 deletions(-)

diff --git a/progress.c b/progress.c
index 289678d43d..7fa1b0f235 100644
--- a/progress.c
+++ b/progress.c
@@ -34,7 +34,6 @@ struct progress {
 	unsigned total;
 	unsigned last_percent;
 	unsigned delay;
-	unsigned delayed_percent_threshold;
 	struct throughput *throughput;
 	uint64_t start_ns;
 };
@@ -86,16 +85,6 @@ static int display(struct progress *progress, unsigned n, const char *done)
 	if (progress->delay) {
 		if (!progress_update || --progress->delay)
 			return 0;
-		if (progress->total) {
-			unsigned percent = n * 100 / progress->total;
-			if (percent > progress->delayed_percent_threshold) {
-				/* inhibit this progress report entirely */
-				clear_progress_signal();
-				progress->delay = -1;
-				progress->total = 0;
-				return 0;
-			}
-		}
 	}

 	progress->last_value = n;
@@ -206,7 +195,7 @@ int display_progress(struct progress *progress, unsigned n)
 }

 static struct progress *start_progress_delay(const char *title, unsigned total,
-					     unsigned percent_threshold, unsigned delay)
+					     unsigned delay)
 {
 	struct progress *progress = malloc(sizeof(*progress));
 	if (!progress) {
@@ -219,7 +208,6 @@ static struct progress *start_progress_delay(const char *title, unsigned total,
 	progress->total = total;
 	progress->last_value = -1;
 	progress->last_percent = -1;
-	progress->delayed_percent_threshold = percent_threshold;
 	progress->delay = delay;
 	progress->throughput = NULL;
 	progress->start_ns = getnanotime();
@@ -229,12 +217,12 @@ static struct progress *start_progress_delay(const char *title, unsigned total,

 struct progress *start_delayed_progress(const char *title, unsigned total)
 {
-	return start_progress_delay(title, total, 0, 2);
+	return start_progress_delay(title, total, 2);
 }

 struct progress *start_progress(const char *title, unsigned total)
 {
-	return start_progress_delay(title, total, 0, 0);
+	return start_progress_delay(title, total, 0);
 }

 void stop_progress(struct progress **p_progress)
--
2.15.1

Re: [PATCH v1] progress: print progress output for all operations taking longer than 2s

[Jeff King]

On Mon, Dec 04, 2017 at 09:36:47PM +0100, lars.schneider@autodesk.com wrote:

> From: Lars Schneider <larsxschneider@gmail.com>
> 
> In 180a9f2 we implemented a progress API which suppresses the progress
> output if the progress has reached a specified percentage threshold
> within a given time frame. In 8aade10 we simplified the API and set the
> threshold to 0% and the time frame to 2 seconds for all delayed progress
> operations. That means we would only see a progress output if we still
> have 0% progress after 2 seconds. Consequently, only operations that
> have a very slow start would show the progress output at all.
> 
> Remove the threshold entirely and print the progress output for all
> operations that take longer than 2 seconds.

Good catch.

I was surprised at first to see 8aade10 as the culprit here, because it
was supposed to be a mechanical conversion. I.e.:

  start_progress_delay("foo", 0, 0, 2);
  start_progress_delay("bar", nr, 50, 1);

would both call the wrapper with a 0-percent delay threshold.

And now call sites like the first one still works, but the second one is
broken.

The problem is that commit got the meaning of the threshold parameter
totally backwards. It is "only show progress if we have not gotten past
this percent". Which means that passing "0" is nonsense, as you
discovered.

But wait, why did we have all those calls using "0" in the first place,
and why did they work? The answer is that we can only look at the
threshold at all when we know the total, since otherwise we can't
compute a percentage. So that first call should logically have been:

  start_progress_delay("foo", 0, 100, 2);

I.e., 100% to indicate that we always show the progress after 2 seconds
regardless. But since our total was "0", we never looked at the
threshold at all. But they misled us into thinking that "0" was the way
to say "always show this progress after 2 seconds".

So the minimal fix is actually:

diff --git a/progress.c b/progress.c
index 289678d43d..b774cb1cd1 100644
--- a/progress.c
+++ b/progress.c
@@ -229,7 +229,7 @@ static struct progress *start_progress_delay(const char *title, unsigned total,
 
 struct progress *start_delayed_progress(const char *title, unsigned total)
 {
-	return start_progress_delay(title, total, 0, 2);
+	return start_progress_delay(title, total, 100, 2);
 }
 
 struct progress *start_progress(const char *title, unsigned total)

That keeps "start_progress_delay" functioning properly, but makes
callers of the wrapper use a sane threshold.

That said, after 8aade10 there are literally no callers that use a
threshold other than what is set here. So we could just rip out the
"threshold" feature entirely, which is what your patch is doing.

I'm OK with that route, but I think we would want to explain that
decision in the commit message a bit better.

> a few weeks ago I was puzzled why the progress output is not shown in
> certain situations [1]. I debugged the issue a bit today and came up
> with this patch as solution. It is entirely possible that I misunderstood
> the intentions of the progress API and therefore my patch is bogus.
> In this case, please treat this email as RFC.

No, I think 8aade10 misunderstood the progress API. ;)

-Peff

Re: [PATCH v1] progress: print progress output for all operations taking longer than 2s

[Junio C Hamano]

Jeff King <peff@peff.net> writes:

> So the minimal fix is actually:
>
> diff --git a/progress.c b/progress.c
> index 289678d43d..b774cb1cd1 100644
> --- a/progress.c
> +++ b/progress.c
> @@ -229,7 +229,7 @@ static struct progress *start_progress_delay(const char *title, unsigned total,
>  
>  struct progress *start_delayed_progress(const char *title, unsigned total)
>  {
> -	return start_progress_delay(title, total, 0, 2);
> +	return start_progress_delay(title, total, 100, 2);
>  }

That makes a lot more sense to me (at least from a cursory
comparison between the two approaches).

[PATCH 0/2] fix v2.15 progress regression

[Jeff King]

On Mon, Dec 04, 2017 at 01:38:41PM -0800, Junio C Hamano wrote:

> Jeff King <peff@peff.net> writes:
> 
> > So the minimal fix is actually:
> >
> > diff --git a/progress.c b/progress.c
> > index 289678d43d..b774cb1cd1 100644
> > --- a/progress.c
> > +++ b/progress.c
> > @@ -229,7 +229,7 @@ static struct progress *start_progress_delay(const char *title, unsigned total,
> >  
> >  struct progress *start_delayed_progress(const char *title, unsigned total)
> >  {
> > -	return start_progress_delay(title, total, 0, 2);
> > +	return start_progress_delay(title, total, 100, 2);
> >  }
> 
> That makes a lot more sense to me (at least from a cursory
> comparison between the two approaches).

Here's what I think we should do: fix the bug in the minimal way, and
then drop the useless code. It's worth doing in two steps, because we
may decide to resurrect the feature later, and it would then just be a
straight revert of the second commit.

  [1/2]: progress: set default delay threshold to 100%, not 0%
  [2/2]: progress: drop delay-threshold code

 progress.c | 24 +++++-------------------
 1 file changed, 5 insertions(+), 19 deletions(-)

This regression is in v2.15, so this probably ought to go to maint (at
least the first part, though I think the second should have no
user-visible effects).

-Peff

[PATCH 1/2] progress: set default delay threshold to 100%, not 0%

[Jeff King]

Commit 8aade107dd (progress: simplify "delayed" progress
API, 2017-08-19) dropped the parameter by which callers
could say "show my progress only if I haven't passed M%
progress after N seconds". The intent was to just show
nothing for 2 seconds, and then always progress after that.

But we flipped the logic in the wrapper: it sets M=0,
meaning that we'd almost _never_ show progress after 2
seconds, since we'd generally have made some progress. This
should have been 100%, not 0%.

We were fooled by existing calls like:

  start_progress_delay("foo", 0, 0, 2);

which behaved this way. The trick is that the first "0"
there is "how many items total", and there zero means "we
don't know". And without knowing that, we cannot compute a
completed percent at all, and we ignored the threshold
parameter entirely! Modeling our wrapper after that broke
callers which pass a non-zero value for "total".

We can switch to the intended behavior by using "100" in the
wrapper call.

Reported-by: Lars Schneider <larsxschneider@gmail.com>
Signed-off-by: Jeff King <peff@peff.net>
---
 progress.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/progress.c b/progress.c
index 289678d43d..b774cb1cd1 100644
--- a/progress.c
+++ b/progress.c
@@ -229,7 +229,7 @@ static struct progress *start_progress_delay(const char *title, unsigned total,
 
 struct progress *start_delayed_progress(const char *title, unsigned total)
 {
-	return start_progress_delay(title, total, 0, 2);
+	return start_progress_delay(title, total, 100, 2);
 }
 
 struct progress *start_progress(const char *title, unsigned total)
-- 
2.15.0.691.g622df76569

[PATCH 2/2] progress: drop delay-threshold code

[Jeff King]

From: Lars Schneider <larsxschneider@gmail.com>

Since 180a9f2268 (provide a facility for "delayed" progress
reporting, 2007-04-20), the progress code has allowed
callers to skip showing progress if they have reached a
percentage-threshold of the total work before the delay
period passes.

But since 8aade107dd (progress: simplify "delayed" progress
API, 2017-08-19), that parameter is not available to outside
callers (we always passed zero after that commit, though
that was corrected in the previous commit to "100%").

Let's drop the threshold code, which never triggers in
any meaningful way.

Signed-off-by: Jeff King <peff@peff.net>
---
I tweaked your patch slightly to clean up the now-simplified
conditional.

 progress.c | 24 +++++-------------------
 1 file changed, 5 insertions(+), 19 deletions(-)

diff --git a/progress.c b/progress.c
index b774cb1cd1..5f87f4568f 100644
--- a/progress.c
+++ b/progress.c
@@ -34,7 +34,6 @@ struct progress {
 	unsigned total;
 	unsigned last_percent;
 	unsigned delay;
-	unsigned delayed_percent_threshold;
 	struct throughput *throughput;
 	uint64_t start_ns;
 };
@@ -83,20 +82,8 @@ static int display(struct progress *progress, unsigned n, const char *done)
 {
 	const char *eol, *tp;
 
-	if (progress->delay) {
-		if (!progress_update || --progress->delay)
-			return 0;
-		if (progress->total) {
-			unsigned percent = n * 100 / progress->total;
-			if (percent > progress->delayed_percent_threshold) {
-				/* inhibit this progress report entirely */
-				clear_progress_signal();
-				progress->delay = -1;
-				progress->total = 0;
-				return 0;
-			}
-		}
-	}
+	if (progress->delay && (!progress_update || --progress->delay))
+		return 0;
 
 	progress->last_value = n;
 	tp = (progress->throughput) ? progress->throughput->display.buf : "";
@@ -206,7 +193,7 @@ int display_progress(struct progress *progress, unsigned n)
 }
 
 static struct progress *start_progress_delay(const char *title, unsigned total,
-					     unsigned percent_threshold, unsigned delay)
+					     unsigned delay)
 {
 	struct progress *progress = malloc(sizeof(*progress));
 	if (!progress) {
@@ -219,7 +206,6 @@ static struct progress *start_progress_delay(const char *title, unsigned total,
 	progress->total = total;
 	progress->last_value = -1;
 	progress->last_percent = -1;
-	progress->delayed_percent_threshold = percent_threshold;
 	progress->delay = delay;
 	progress->throughput = NULL;
 	progress->start_ns = getnanotime();
@@ -229,12 +215,12 @@ static struct progress *start_progress_delay(const char *title, unsigned total,
 
 struct progress *start_delayed_progress(const char *title, unsigned total)
 {
-	return start_progress_delay(title, total, 100, 2);
+	return start_progress_delay(title, total, 2);
 }
 
 struct progress *start_progress(const char *title, unsigned total)
 {
-	return start_progress_delay(title, total, 0, 0);
+	return start_progress_delay(title, total, 0);
 }
 
 void stop_progress(struct progress **p_progress)
-- 
2.15.0.691.g622df76569

Re: [PATCH 2/2] progress: drop delay-threshold code

[Lars Schneider]

> On 04 Dec 2017, at 23:07, Jeff King <peff@peff.net> wrote:
> 
> From: Lars Schneider <larsxschneider@gmail.com>
> 
> Since 180a9f2268 (provide a facility for "delayed" progress
> reporting, 2007-04-20), the progress code has allowed
> callers to skip showing progress if they have reached a
> percentage-threshold of the total work before the delay
> period passes.
> 
> But since 8aade107dd (progress: simplify "delayed" progress
> API, 2017-08-19), that parameter is not available to outside
> callers (we always passed zero after that commit, though
> that was corrected in the previous commit to "100%").
> 
> Let's drop the threshold code, which never triggers in
> any meaningful way.
> 
> Signed-off-by: Jeff King <peff@peff.net>
> ---
> I tweaked your patch slightly to clean up the now-simplified
> conditional.

Your first patch ("progress: set default delay threshold to 100%, not 0%")
as well as the modifications to this one look good to me. Feel free
to add my "Signed-off-by: Lars Schneider <larsxschneider@gmail.com>".

Thanks,
Lars


PS: How do you generate the commit references "hash (first line, date)"?
Git log pretty print?

Re: [PATCH 2/2] progress: drop delay-threshold code

[Ævar Arnfjörð Bjarmason]

On Tue, Dec 5, 2017 at 11:37 AM, Lars Schneider
<larsxschneider@gmail.com> wrote:
>
>> On 04 Dec 2017, at 23:07, Jeff King <peff@peff.net> wrote:
>>
>> From: Lars Schneider <larsxschneider@gmail.com>
>>
>> Since 180a9f2268 (provide a facility for "delayed" progress
>> reporting, 2007-04-20), the progress code has allowed
>> callers to skip showing progress if they have reached a
>> percentage-threshold of the total work before the delay
>> period passes.
>>
>> But since 8aade107dd (progress: simplify "delayed" progress
>> API, 2017-08-19), that parameter is not available to outside
>> callers (we always passed zero after that commit, though
>> that was corrected in the previous commit to "100%").
>>
>> Let's drop the threshold code, which never triggers in
>> any meaningful way.
>>
>> Signed-off-by: Jeff King <peff@peff.net>
>> ---
>> I tweaked your patch slightly to clean up the now-simplified
>> conditional.
>
> Your first patch ("progress: set default delay threshold to 100%, not 0%")
> as well as the modifications to this one look good to me. Feel free
> to add my "Signed-off-by: Lars Schneider <larsxschneider@gmail.com>".
>
> Thanks,
> Lars
>
>
> PS: How do you generate the commit references "hash (first line, date)"?
> Git log pretty print?

$ git grep -A5 'Copy commit summary' Documentation/SubmittingPatches
Documentation/SubmittingPatches:151:The "Copy commit summary" command
of gitk can be used to obtain this
Documentation/SubmittingPatches-152-format, or this invocation of `git show`:
Documentation/SubmittingPatches-153-
Documentation/SubmittingPatches-154-....
Documentation/SubmittingPatches-155-    git show -s --date=short
--pretty='format:%h ("%s", %ad)' <commit>

Re: [PATCH 2/2] progress: drop delay-threshold code

[Lars Schneider]

> On 05 Dec 2017, at 12:10, Ævar Arnfjörð Bjarmason <avarab@gmail.com> wrote:
> 
> On Tue, Dec 5, 2017 at 11:37 AM, Lars Schneider
> <larsxschneider@gmail.com> wrote:
>> 
>>> On 04 Dec 2017, at 23:07, Jeff King <peff@peff.net> wrote:
>>> 
>>> From: Lars Schneider <larsxschneider@gmail.com>
>>> 
>>> Since 180a9f2268 (provide a facility for "delayed" progress
>>> reporting, 2007-04-20), the progress code has allowed
>>> callers to skip showing progress if they have reached a
>>> percentage-threshold of the total work before the delay
>>> period passes.
>>> 
>>> But since 8aade107dd (progress: simplify "delayed" progress
>>> API, 2017-08-19), that parameter is not available to outside
>>> callers (we always passed zero after that commit, though
>>> that was corrected in the previous commit to "100%").
>>> 
>>> Let's drop the threshold code, which never triggers in
>>> any meaningful way.
>>> 
>>> Signed-off-by: Jeff King <peff@peff.net>
>>> ---
>>> I tweaked your patch slightly to clean up the now-simplified
>>> conditional.
>> 
>> Your first patch ("progress: set default delay threshold to 100%, not 0%")
>> as well as the modifications to this one look good to me. Feel free
>> to add my "Signed-off-by: Lars Schneider <larsxschneider@gmail.com>".
>> 
>> Thanks,
>> Lars
>> 
>> 
>> PS: How do you generate the commit references "hash (first line, date)"?
>> Git log pretty print?
> 
> $ git grep -A5 'Copy commit summary' Documentation/SubmittingPatches
> Documentation/SubmittingPatches:151:The "Copy commit summary" command
> of gitk can be used to obtain this
> Documentation/SubmittingPatches-152-format, or this invocation of `git show`:
> Documentation/SubmittingPatches-153-
> Documentation/SubmittingPatches-154-....
> Documentation/SubmittingPatches-155-    git show -s --date=short
> --pretty='format:%h ("%s", %ad)' <commit>

Thanks :-)

Re: [PATCH 0/2] fix v2.15 progress regression

[Junio C Hamano]

Jeff King <peff@peff.net> writes:

> Here's what I think we should do: fix the bug in the minimal way, and
> then drop the useless code. It's worth doing in two steps, because we
> may decide to resurrect the feature later, and it would then just be a
> straight revert of the second commit.

Yup.  Thanks; will queue.

Re: [PATCH v1] progress: print progress output for all operations taking longer than 2s

[Junio C Hamano]

lars.schneider@autodesk.com writes:

> In 180a9f2 we implemented a progress API which suppresses the progress
> output if the progress has reached a specified percentage threshold
> within a given time frame. In 8aade10 we simplified the API and set the
> threshold to 0% and the time frame to 2 seconds for all delayed progress
> operations. That means we would only see a progress output if we still
> have 0% progress after 2 seconds. Consequently, only operations that
> have a very slow start would show the progress output at all.
>
> Remove the threshold entirely and print the progress output for all
> operations that take longer than 2 seconds.

Isn't this likely to result in much chattier progress output (read:
regression) forplaces whose the (P, N) was (0%, 2s) before 8aade107
("progress: simplify "delayed" progress API", 2017-08-19)?

Before or after that change, the places that passed (0%, 2s)
refrained from showing any progress, if at least 1 per-cent of the
work has finished at 2-second mark.  With this change, they will
suddenly start showing progress after 2-second mark, even if they
completed that much work already.

The places that did change the behaviour with the cited change are
the ones that used parameters different from (0%, 2s).  "git blame",
"diffcore-rename" and "unpack-trees" seem to be among them; they
used (50%, 1s), and we'd have seen the progress meter after 1s,
unless half of the work is already done by that time.  By replacing
that with (0%, 2s), the change made it a lot less likely to trigger.

The analysis in the cited commit log claims that (50%, 1s) is
equivalent to (0%, 2s) when the workload is smooth, but I think that
math is bogus X-<.

And the one in prune-packed, which used to be (95%, 2s), is quite
different from the value after the simplification.  We deliberately
made it 95 times more unlikely to trigger with that commit---it used
to be that unless 95% of work is already done, we saw progress
starting at 2-second mark, but now we see progress only when less
than 1% of work is done at 2-second mark.