Hi Peff,
On Thu, 27 Jun 2019, Jeff King wrote:
> On Thu, Jun 27, 2019 at 01:25:15AM -0400, Jeff King wrote:
>
> > Taylor and I noticed a slowdown in p1451 between v2.20.1 and v2.21.0. I
> > was surprised to find that it bisects to bbb15c5193 (fsck: reduce word
> > legos to help i18n, 2018-11-10).
> >
> > The important part, as it turns out, is the switch to using fprintf_ln()
> > instead of a regular fprintf() with a "\n" in it. Doing this:
> > [...]
> > on top of the current tip of master yields this result:
> >
> > Test HEAD^ HEAD
> >
> > -----------------------------------------------------------------------------------------
> > 1451.3: fsck with 0 skipped bad commits 9.78(7.46+2.32)
> > 8.74(7.38+1.36) -10.6%
> > 1451.5: fsck with 1 skipped bad commits 9.78(7.66+2.11)
> > 8.49(7.04+1.44) -13.2%
> > 1451.7: fsck with 10 skipped bad commits 9.83(7.45+2.37)
> > 8.53(7.26+1.24) -13.2%
> > 1451.9: fsck with 100 skipped bad commits 9.87(7.47+2.40)
> > 8.54(7.24+1.30) -13.5%
> > 1451.11: fsck with 1000 skipped bad commits 9.79(7.67+2.12)
> > 8.48(7.25+1.23) -13.4%
> > 1451.13: fsck with 10000 skipped bad commits 9.86(7.58+2.26)
> > 8.38(7.09+1.28) -15.0%
> > 1451.15: fsck with 100000 skipped bad commits 9.58(7.39+2.19)
> > 8.41(7.21+1.19) -12.2%
> > 1451.17: fsck with 1000000 skipped bad commits 6.38(6.31+0.07)
> > 6.35(6.26+0.07) -0.5%
>
> Ah, I think I see it.
>
> See how the system times for HEAD^ (with fprintf_ln) are higher? We're
> flushing stderr more frequently (twice as much, since it's unbuffered,
> and we now have an fprintf followed by a putc).
>
> I can get similar speedups by formatting into a buffer:
>
> diff --git a/strbuf.c b/strbuf.c
> index 0e18b259ce..07ce9b9178 100644
> --- a/strbuf.c
> +++ b/strbuf.c
> @@ -880,8 +880,22 @@ int printf_ln(const char *fmt, ...)
>
> int fprintf_ln(FILE *fp, const char *fmt, ...)
> {
> + char buf[1024];
> int ret;
> va_list ap;
> +
> + /* Fast path: format it ourselves and dump it via fwrite. */
> + va_start(ap, fmt);
> + ret = vsnprintf(buf, sizeof(buf), fmt, ap);
> + va_end(ap);
> + if (ret < sizeof(buf)) {
> + buf[ret++] = '\n';
> + if (fwrite(buf, 1, ret, fp) != ret)
> + return -1;
> + return ret;
> + }
> +
> + /* Slow path: a normal fprintf/putc combo */
> va_start(ap, fmt);
> ret = vfprintf(fp, fmt, ap);
> va_end(ap);
>
> But we shouldn't have to resort to that.
Why not?
It would make for a perfectly fine excuse to finally get work going in
direction of a initially heap-backed strbuf. Which we have wanted for ages
now.
> We can use setvbuf() to toggle buffering back and forth, but I'm not
> sure if there's a way to query the current buffering scheme for a stdio
> stream.
It also is not very safe, especially when we want to have this work in a
multi-threaded fashion.
I'd be much more comfortable with rendering the string into a buffer and
then sending that buffer wholesale to stderr.
Ciao,
Dscho
