fprintf_ln() is slow

fprintf_ln() is slow

[Jeff King]

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:

diff --git a/builtin/fsck.c b/builtin/fsck.c
index d26fb0a044..234b766843 100644
--- a/builtin/fsck.c
+++ b/builtin/fsck.c
@@ -128,12 +128,12 @@ static int fsck_error_func(struct fsck_options *o,
 	switch (type) {
 	case FSCK_WARN:
 		/* TRANSLATORS: e.g. warning in tree 01bfda: <more explanation> */
-		fprintf_ln(stderr, _("warning in %s %s: %s"),
+		fprintf(stderr, _("warning in %s %s: %s\n"),
 			   printable_type(obj), describe_object(obj), message);
 		return 0;
 	case FSCK_ERROR:
 		/* TRANSLATORS: e.g. error in tree 01bfda: <more explanation> */
-		fprintf_ln(stderr, _("error in %s %s: %s"),
+		fprintf(stderr, _("error in %s %s: %s\n"),
 			   printable_type(obj), describe_object(obj), message);
 		return 1;
 	default:

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% 

That test makes a repo with a million bad commits. Most of those (except
the last one, which doesn't see a huge change!) tests are outputting
900k+ error messages. So small changes in the speed of printing are
amplified.

This is a totally synthetic repo. So as a real-world case, these numbers
are probably not all that interesting. If you have a million-line fsck
output, the extra 1s of output time is probably not biggest thing on
your mind. But we do use fprintf_ln() elsewhere, and I wonder if there
are cases where it could add up.

I thought it might be due to stdio's locking overhead (we ran into that
with single-character getc's in other code). But there's no unlocked
variant of the formatting functions, so the best we can do is this:

diff --git a/strbuf.c b/strbuf.c
index 0e18b259ce..fac3b33f68 100644
--- a/strbuf.c
+++ b/strbuf.c
@@ -882,12 +882,18 @@ int fprintf_ln(FILE *fp, const char *fmt, ...)
 {
 	int ret;
 	va_list ap;
+
+	flockfile(fp);
+
 	va_start(ap, fmt);
 	ret = vfprintf(fp, fmt, ap);
 	va_end(ap);
-	if (ret < 0 || putc('\n', fp) == EOF)
-		return -1;
-	return ret + 1;
+
+	if (ret >= 0 && putc_unlocked('\n', fp) != EOF)
+		ret++;
+
+	funlockfile(fp);
+	return ret;
 }
 
 char *xstrdup_tolower(const char *string)

which doesn't seem to help. I don't know if this is even worth digging
into, or if we should declare that "yeah, fprintf_ln is not the fastest
way to print something; don't use it in a tight loop".

But maybe somebody else has a brilliant idea.

-Peff

Re: fprintf_ln() is slow

[Jeff King]

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. 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. We'd need that to be able
to switch back correctly (and to avoid switching for things that are
already buffered).

I suppose it would be enough to check for "fp == stderr", since that is
the only unbuffered thing we'd generally see.

And it may be that the code above is really not much different anyway.
For an unbuffered stream, I'd guess it dumps an fwrite() directly to
write() anyway (since by definition it does not need to hold onto it,
and nor is there anything in the buffer ahead of it).

Something like:

  char buf[1024];
  if (fp == stderr)
	setvbuf(stream, buf, _IOLBF, sizeof(buf));

  ... do fprintf and putc ...

  if (fp == stderr)
	setvbuf(stream, NULL, _IONBF, 0);

feels less horrible, but it's making the assumption that we were
unbuffered coming into the function. I dunno.

-Peff

Re: fprintf_ln() is slow

[Duy Nguyen]

On Thu, Jun 27, 2019 at 1:00 PM Jeff King <peff@peff.net> 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. 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. We'd need that to be able
> to switch back correctly (and to avoid switching for things that are
> already buffered).
>
> I suppose it would be enough to check for "fp == stderr", since that is
> the only unbuffered thing we'd generally see.
>
> And it may be that the code above is really not much different anyway.
> For an unbuffered stream, I'd guess it dumps an fwrite() directly to
> write() anyway (since by definition it does not need to hold onto it,
> and nor is there anything in the buffer ahead of it).
>
> Something like:
>
>   char buf[1024];
>   if (fp == stderr)
>         setvbuf(stream, buf, _IOLBF, sizeof(buf));
>
>   ... do fprintf and putc ...
>
>   if (fp == stderr)
>         setvbuf(stream, NULL, _IONBF, 0);
>
> feels less horrible, but it's making the assumption that we were
> unbuffered coming into the function. I dunno.

How about do all the formatting in strbuf and only fwrite last minute?
A bit more overhead with malloc(), so I don't know if it's an
improvement or not.
-- 
Duy

Re: fprintf_ln() is slow

[Ævar Arnfjörð Bjarmason]

On Thu, Jun 27 2019, Duy Nguyen wrote:

> On Thu, Jun 27, 2019 at 1:00 PM Jeff King <peff@peff.net> 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. 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. We'd need that to be able
>> to switch back correctly (and to avoid switching for things that are
>> already buffered).
>>
>> I suppose it would be enough to check for "fp == stderr", since that is
>> the only unbuffered thing we'd generally see.
>>
>> And it may be that the code above is really not much different anyway.
>> For an unbuffered stream, I'd guess it dumps an fwrite() directly to
>> write() anyway (since by definition it does not need to hold onto it,
>> and nor is there anything in the buffer ahead of it).
>>
>> Something like:
>>
>>   char buf[1024];
>>   if (fp == stderr)
>>         setvbuf(stream, buf, _IOLBF, sizeof(buf));
>>
>>   ... do fprintf and putc ...
>>
>>   if (fp == stderr)
>>         setvbuf(stream, NULL, _IONBF, 0);
>>
>> feels less horrible, but it's making the assumption that we were
>> unbuffered coming into the function. I dunno.
>
> How about do all the formatting in strbuf and only fwrite last minute?
> A bit more overhead with malloc(), so I don't know if it's an
> improvement or not.

Why shouldn't we just move back to plain fprintf() with "\n"? Your
9a0a30aa4b ("strbuf: convenience format functions with \n automatically
appended", 2012-04-23) doesn't explain why this is a convenience for
translators.

When I'm translating things tend to like knowing that something ends in
a newline explicitly, why do we need to hide that from translators? They
also need to deal with trailing \n in other messages, so these *_ln()
functions make things inconsistent.

It's also not possible for translators to do this by mistake without
being caught, because msgfmt will catch this (and other common issues):

    po/de.po:23: 'msgid' and 'msgstr' entries do not both end with '\n'

Re: fprintf_ln() is slow

[Duy Nguyen]

On Thu, Jun 27, 2019 at 7:18 PM Ævar Arnfjörð Bjarmason
<avarab@gmail.com> wrote:
> Why shouldn't we just move back to plain fprintf() with "\n"? Your
> 9a0a30aa4b ("strbuf: convenience format functions with \n automatically
> appended", 2012-04-23) doesn't explain why this is a convenience for
> translators.
>
> When I'm translating things tend to like knowing that something ends in
> a newline explicitly, why do we need to hide that from translators? They
> also need to deal with trailing \n in other messages, so these *_ln()
> functions make things inconsistent.
>
> It's also not possible for translators to do this by mistake

This (accidentally dropping \n which sometimes is significant) is the
part that I made me prefer *printf_ln(). I had been translating for
years, as far back as 2003-ish, but I've stopped since the last few
years so I'm no longer uptodate with gettext development. And my very
old/outdated experience with gettext might make me think it's still
the problem.

> without
> being caught, because msgfmt will catch this (and other common issues):
>
>     po/de.po:23: 'msgid' and 'msgstr' entries do not both end with '\n'

Ok good. And with the downside of degraded performance, sure remove
all the *printf_ln()
-- 
Duy

Re: fprintf_ln() is slow

[Junio C Hamano]

Duy Nguyen <pclouds@gmail.com> writes:

>> without
>> being caught, because msgfmt will catch this (and other common issues):
>>
>>     po/de.po:23: 'msgid' and 'msgstr' entries do not both end with '\n'
>
> Ok good. And with the downside of degraded performance, sure remove
> all the *printf_ln()

Sounds good.  Thanks.

Re: fprintf_ln() is slow

[Jeff King]

On Thu, Jun 27, 2019 at 07:32:53PM +0700, Duy Nguyen wrote:

> > It's also not possible for translators to do this by mistake
> 
> This (accidentally dropping \n which sometimes is significant) is the
> part that I made me prefer *printf_ln(). I had been translating for
> years, as far back as 2003-ish, but I've stopped since the last few
> years so I'm no longer uptodate with gettext development. And my very
> old/outdated experience with gettext might make me think it's still
> the problem.
> 
> > without
> > being caught, because msgfmt will catch this (and other common issues):
> >
> >     po/de.po:23: 'msgid' and 'msgstr' entries do not both end with '\n'
> 
> Ok good. And with the downside of degraded performance, sure remove
> all the *printf_ln()

I don't have a strong opinion here. If you want to convert them all back
to embedded "\n", that's fine with me.

But I do suspect this same issue will come up in other places, too. For
instance, we already format into a buffer for error(), etc. Mostly for
atomic output as opposed to efficiency. And it's not just "\n", but
adding prefixes, etc.

It might be nice to have some generalized solution for writing to
stderr. And maybe it's even just using vreportf more widely. That also
caps the output length and munges unprintable characters, but that's
probably a good thing when we're going to stderr.

-Peff

Re: fprintf_ln() is slow

[Jeff King]

On Thu, Jun 27, 2019 at 04:27:07PM +0700, Duy Nguyen wrote:

> >  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);
> [...]
> 
> How about do all the formatting in strbuf and only fwrite last minute?
> A bit more overhead with malloc(), so I don't know if it's an
> improvement or not.

We could easily do that by replacing the vfprintf() slow path there with
a strbuf, and it would be faster in the normal case for small outputs.
The question is whether a malloc() or two write()s is worse.

Probably the malloc() costs less for sane-sized inputs, but would blow
up in pathological cases as we ask for a lot of RAM.

I'm not sure it's worth caring that much about such a case. This is,
after all, designed to print a single line. I suspect we could put
BUG("woah, your line is really big") in the slow-path here and nobody
would ever notice. ;)

I'm also not entirely convinced it's worth caring about this problem at
all (whether the solution is buffering here, or just adding the "\n"
back to the original strings). It's true that p1451 shows off a
measurable improvement, but I think it's a silly, pathological case. I'd
be surprised if anybody ever noticed the difference in the real world.

The biggest benefit I see to dealing with it is not performance, but
that it makes our messages more likely to appear atomically in the
output (if multiple entities are writing to stderr).

-Peff

Re: fprintf_ln() is slow

[Junio C Hamano]

Jeff King <peff@peff.net> writes:

> I'm also not entirely convinced it's worth caring about this problem at
> all (whether the solution is buffering here, or just adding the "\n"
> back to the original strings). It's true that p1451 shows off a
> measurable improvement, but I think it's a silly, pathological case. I'd
> be surprised if anybody ever noticed the difference in the real world.

Yup, exactly my thought.

> The biggest benefit I see to dealing with it is not performance, but
> that it makes our messages more likely to appear atomically in the
> output (if multiple entities are writing to stderr).

I was primarily in favor of getting rid of *printf_ln() functions
(there are some 200+ callsites if I counted correctly) as I found it
a bit distracting.

Re: fprintf_ln() is slow

[Johannes Schindelin]

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

Re: fprintf_ln() is slow

[Jeff King]

On Thu, Jun 27, 2019 at 02:00:54PM +0200, Johannes Schindelin wrote:

> > I can get similar speedups by formatting into a buffer:
> [..]
> > But we shouldn't have to resort to that.
> 
> Why not?

My thinking was that it was introducing an extra copy of the data. But
on further reflection, it probably doesn't, at least for the case of an
unbuffered stream (we might want to predicate it on "fp == stderr",
though).

> 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.

I assume you initially stack-backed strbuf?

Perhaps. I'm not sure that it's better for the fallback when we need
more than the stack buffer to be allocating more memory as opposed to
just calling fprintf() and sending it out in multiple writes.

> > 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 considered that, too, but I think it is safe. stdio has its own
locking, so every individual call is atomic. The potentially problematic
case would be where we switch back from line buffering to no-buffering,
and somebody else has written some content into our stack-based buffer
(that is about to go out of scope!). But I'd assume that as part of the
switch to no-buffering that any stdio implementation would flush out the
buffer that it's detaching from (while under lock). Nothing else makes
sense.

That said...

> I'd be much more comfortable with rendering the string into a buffer and
> then sending that buffer wholesale to stderr.

It's sufficiently complex that I think I prefer to just use our own
buffer, too.

It also makes it more likely for the newline and the message to end up
in an atomic write(), so if multiple threads _are_ writing to stderr
they'd be more likely to stay together.

It does sound like people in the other part of the thread are OK with
just getting rid of the "_ln" functions altogether.

-Peff

Re: fprintf_ln() is slow

[Phillip Wood]

Dear Peff and Dscho

On 27/06/2019 22:10, Jeff King wrote:
> On Thu, Jun 27, 2019 at 02:00:54PM +0200, Johannes Schindelin wrote:
> 
>>> 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 considered that, too, but I think it is safe. stdio has its own
> locking, so every individual call is atomic. The potentially problematic
> case would be where we switch back from line buffering to no-buffering,
> and somebody else has written some content into our stack-based buffer
> (that is about to go out of scope!). But I'd assume that as part of the
> switch to no-buffering that any stdio implementation would flush out the
> buffer that it's detaching from (while under lock). Nothing else makes
> sense.

The C standard section 7.19.5.6 says that
  The setvbuf function may be used only after the stream pointed to by
  a stream has been associated with an open file and before any other
  operation (other than an unsuccessful call to setvbuf) is performed
  on the stream.

The is a note about the buffer that says
  The buffer has to have a lifetime at least as great as the open
  stream, so the stream should be closed before a buffer that has
  automatic storage duration is deallocated upon block exit.

So changing the buffer in the way that has been proposed is undefined
behavior on two counts I think.

Best Wishes

Phillip


> That said...
> 
>> I'd be much more comfortable with rendering the string into a buffer and
>> then sending that buffer wholesale to stderr.
> 
> It's sufficiently complex that I think I prefer to just use our own
> buffer, too.
> 
> It also makes it more likely for the newline and the message to end up
> in an atomic write(), so if multiple threads _are_ writing to stderr
> they'd be more likely to stay together.
> 
> It does sound like people in the other part of the thread are OK with
> just getting rid of the "_ln" functions altogether.
> 
> -Peff
> 

Re: fprintf_ln() is slow

[Jeff King]

On Fri, Jun 28, 2019 at 11:03:27AM +0100, Phillip Wood wrote:

> > I considered that, too, but I think it is safe. stdio has its own
> > locking, so every individual call is atomic. The potentially problematic
> > case would be where we switch back from line buffering to no-buffering,
> > and somebody else has written some content into our stack-based buffer
> > (that is about to go out of scope!). But I'd assume that as part of the
> > switch to no-buffering that any stdio implementation would flush out the
> > buffer that it's detaching from (while under lock). Nothing else makes
> > sense.
> 
> The C standard section 7.19.5.6 says that
>   The setvbuf function may be used only after the stream pointed to by
>   a stream has been associated with an open file and before any other
>   operation (other than an unsuccessful call to setvbuf) is performed
>   on the stream.
> 
> The is a note about the buffer that says
>   The buffer has to have a lifetime at least as great as the open
>   stream, so the stream should be closed before a buffer that has
>   automatic storage duration is deallocated upon block exit.
> 
> So changing the buffer in the way that has been proposed is undefined
> behavior on two counts I think.

Oof, thanks for the reference. That is much less safe than I had
imagined. We used to do this kind of setvbuf() munging in vreportf.
Interestingly, it was in released versions for about 2 years, but I
don't recall anybody complaining (we eventually reverted it to have more
flexibility in sanitizing the results before writing them out).

Anyway, I think we're all agreed that's the wrong approach here.

-Peff