Jeff KingTaylor 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
