From: Tom Lane <tgl@sss.pgh.pa.us>
To: Thomas Munro <thomas.munro@enterprisedb.com>
cc: Alvaro Herrera <alvherre@2ndquadrant.com>,
        PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>
Subject: Re: Allowing printf("%m") only where it actually works
In-reply-to: <14925.1534040609@sss.pgh.pa.us>
References: <20180528150125.j2x3mp62ssbeg3h5@alvherre.pgsql>
 <2685.1527520461@sss.pgh.pa.us> <8770.1533931511@sss.pgh.pa.us>
 <16896.1533935042@sss.pgh.pa.us> <14925.1534040609@sss.pgh.pa.us>
Comments: In-reply-to Tom Lane <tgl@sss.pgh.pa.us>
	message dated "Sat, 11 Aug 2018 22:23:29 -0400"
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="----- =_aaaaaaaaaa0"
Content-ID: <1215.1534100619.0@sss.pgh.pa.us>
Date: Sun, 12 Aug 2018 15:08:50 -0400
Message-ID: <1437.1534100930@sss.pgh.pa.us>
Precedence: bulk

------- =_aaaaaaaaaa0
Content-Type: text/plain; charset="us-ascii"
Content-ID: <1215.1534100619.1@sss.pgh.pa.us>

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.


------- =_aaaaaaaaaa0
Content-Type: text/x-c; name="timeprintf.c"; charset="us-ascii"
Content-ID: <1215.1534100619.2@sss.pgh.pa.us>
Content-Description: timeprintf.c
Content-Transfer-Encoding: quoted-printable

#include "postgres_fe.h"

#include "portability/instr_time.h"

#include "snprintf.c"

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

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

	INSTR_TIME_SET_CURRENT(start);

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

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

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

	INSTR_TIME_SET_CURRENT(start);

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

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

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

	return 0;
}

------- =_aaaaaaaaaa0--