Re: Allowing printf("%m") only where it actually works - Mailing list pgsql-hackers

I wrote:
> So this is all pretty much of a mess.  If we annotate the elog functions
> differently from printf's annotation then we risk getting these complaints
> in elog.c, but if we don't do that then we can't really describe their
> semantics correctly.  We could possibly mark the replacement snprintf
> functions with gnu_printf, but that's a lie with respect to the very
> point at issue about %m.  Unless we were to teach snprintf.c about %m
> ... which probably wouldn't be hard, but I'm not sure I want to go there.

Actually ... the more I think about this, the less insane that idea seems.
Consider the following approach:

1. Teach src/port/snprintf.c about %m.  While I've not written a patch
for this, it looks pretty trivial.

2. Teach configure to test for %m and if it's not there, use the
replacement snprintf.  (Note: we're already forcing snprintf replacement
in cross-compiles, so the added run-time test isn't losing anything.)

3. Get rid of elog.c's hand-made substitution of %m strings, and instead
just let it pass the correct errno value down.  (We'd likely need to do
some fooling in appendStringInfoVA and related functions to preserve
call-time errno, but that's not complicated, nor expensive.)

4. (Optional) Get rid of strerror(errno) calls in favor of %m, even in
frontend code.

Once we've done this, we have uniform printf semantics across all
platforms, which is kind of nice from a testing standpoint, as well as
being less of a cognitive load for developers.  And we can stick with
the existing approach of using the gnu_printf archetype across the board;
that's no longer a lie for the snprintf.c code.

One objection to this is the possible performance advantage of the native
printf functions over snprintf.c.  I did a bit of investigation of that
using the attached testbed, and found that the quality of implementation
of the native functions seems pretty variable:

RHEL6's glibc on x86_64 (this is just a comparison point, since we'd not
be replacing glibc's printf anyway):

snprintf time = 756.795 ms total, 0.000756795 ms per iteration
pg_snprintf time = 824.643 ms total, 0.000824643 ms per iteration

macOS High Sierra on x86_64:

snprintf time = 264.071 ms total, 0.000264071 ms per iteration
pg_snprintf time = 348.41 ms total, 0.00034841 ms per iteration

FreeBSD 11.0 on x86_64:

snprintf time = 628.873 ms total, 0.000628873 ms per iteration
pg_snprintf time = 606.684 ms total, 0.000606684 ms per iteration

OpenBSD 6.0 on x86_64 (same hardware as FreeBSD test):

snprintf time = 331.245 ms total, 0.000331245 ms per iteration
pg_snprintf time = 539.849 ms total, 0.000539849 ms per iteration

NetBSD 8.99 on armv6:

snprintf time = 2423.39 ms total, 0.00242339 ms per iteration
pg_snprintf time = 3769.16 ms total, 0.00376916 ms per iteration

So we would be taking a hit on most platforms, but I've not really
seen sprintf as a major component of very many profiles.  Moreover,
at least for the elog/ereport use-case, we'd be buying back some
nontrivial part of that hit by getting rid of expand_fmt_string().
Also worth noting is that we've never made any effort at all to
micro-optimize snprintf.c, so maybe there's some gold to be mined
there to reduce the penalty.

A different objection, possibly more serious than the performance
one, is that if we get in the habit of using %m in frontend code
then at some point we'd inevitably back-patch such a usage.  (Worse,
it'd pass testing on glibc platforms, only to fail elsewhere.)
I don't see a bulletproof answer to that except to back-patch this
set of changes, which might be a bridge too far.

Aside from the back-patching angle, though, this seems pretty
promising.  Thoughts?

            regards, tom lane

PS: here's the testbed I used for the above numbers.  Feel free to
try other platforms or other test-case formats.  Compile this with
something like

gcc -Wall -O2 -I pgsql/src/include -I pgsql/src/port timeprintf.c

(point the -I switches into a configured PG source tree); you might
need to add "-lrt" or some such to get clock_gettime().  Then run
with "./a.out 1000000" or so.

#include "postgres_fe.h"

#include "portability/instr_time.h"

#include "snprintf.c"

int
main(int argc, char **argv)
{
    int count = 0;
    char buffer[1000];
    instr_time    start;
    instr_time    stop;
    double elapsed;
    int i;

    if (argc > 1)
        count = atoi(argv[1]);
    if (count <= 0)
        count = 1000000;

    INSTR_TIME_SET_CURRENT(start);

    for (i = 0; i < count; i++)
    {
        snprintf(buffer, sizeof(buffer),
                 "%d %g %s",
                 42, 42.2,
"01234567890012345678900123456789001234567890012345678900123456789001234567890012345678900123456789001234567890");
    }

    INSTR_TIME_SET_CURRENT(stop);
    INSTR_TIME_SUBTRACT(stop, start);
    elapsed = INSTR_TIME_GET_MILLISEC(stop);

    printf("snprintf time = %g ms total, %g ms per iteration\n",
           elapsed, elapsed / count);

    INSTR_TIME_SET_CURRENT(start);

    for (i = 0; i < count; i++)
    {
        pg_snprintf(buffer, sizeof(buffer),
                 "%d %g %s",
                 42, 42.2,
"01234567890012345678900123456789001234567890012345678900123456789001234567890012345678900123456789001234567890");
    }

    INSTR_TIME_SET_CURRENT(stop);
    INSTR_TIME_SUBTRACT(stop, start);
    elapsed = INSTR_TIME_GET_MILLISEC(stop);

    printf("pg_snprintf time = %g ms total, %g ms per iteration\n",
           elapsed, elapsed / count);

    return 0;
}