threads / patch / 47374

patchprogress: print progress output for all operations taking longer than 2s

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

## tl;dr

11 messages between Dec 4, 2017 and Dec 5, 2017. Diffs are folded; open one to read it.

replies: 10people: 5as markdown or json

lars.schneider@autodesk.com· Dec 4, 2017, 20:36 UTC · lore
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(-)
Show changes to progress.c +3 −16
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
Jeff King· Dec 4, 2017, 21:33 UTC · re: lars.schneider@autodesk.com · lore

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

On Mon, Dec 04, 2017 at 09:36:47PM +0100, lars.schneider@autodesk.com wrote:
Show 12 quoted lines
> 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:
Show changes to progress.c +1 −2
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
Junio C Hamano· Dec 4, 2017, 21:38 UTC · re: Jeff King · lore

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

Jeff King <peff@peff.net> writes:
Show 13 quoted lines
> 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).

Jeff King· Dec 4, 2017, 22:02 UTC · re: Junio C Hamano · lore

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

On Mon, Dec 04, 2017 at 01:38:41PM -0800, Junio C Hamano wrote:
Show 18 quoted lines
> 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
Jeff King· Dec 4, 2017, 22:05 UTC · re: Jeff King · lore

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

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(-)
Show changes to progress.c +1 −1
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
Jeff King· Dec 4, 2017, 22:07 UTC · re: Jeff King · lore

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

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(-)
Show changes to progress.c +5 −19
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
Lars Schneider· Dec 5, 2017, 10:37 UTC · re: Jeff King · lore

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

Show 22 quoted lines
> 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?
Ævar Arnfjörð Bjarmason· Dec 5, 2017, 11:10 UTC · re: Lars Schneider · lore

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

On Tue, Dec 5, 2017 at 11:37 AM, Lars Schneider <larsxschneider@gmail.com> wrote:

Show 34 quoted lines
>
>> 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>

Lars Schneider· Dec 5, 2017, 12:28 UTC · re: Ævar Arnfjörð Bjarmason · lore

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

Show 47 quoted lines
> 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 :-)
Junio C Hamano· Dec 4, 2017, 22:22 UTC · re: Jeff King · lore

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

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.
Junio C Hamano· Dec 4, 2017, 21:35 UTC · re: lars.schneider@autodesk.com · lore

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

lars.schneider@autodesk.com writes:
Show 10 quoted lines
> 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.

← back to recent threads