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: <1437.1534100930@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>
 <1437.1534100930@sss.pgh.pa.us>
Comments: In-reply-to Tom Lane <tgl@sss.pgh.pa.us>
	message dated "Sun, 12 Aug 2018 15:08:50 -0400"
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="----- =_aaaaaaaaaa0"
Content-ID: <3009.1534102449.0@sss.pgh.pa.us>
Date: Sun, 12 Aug 2018 15:35:09 -0400
Message-ID: <3067.1534102509@sss.pgh.pa.us>
Precedence: bulk

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

I wrote:
> ... 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.

Oh, the plot thickens: apparently, a very large chunk of the time
in that test scenario went into the %g format item, which I think
we can all agree isn't performance-critical for Postgres.  Changing
the test case to test %lld in place of %g, I get (on the same
five platforms as before)

RHEL6:

snprintf time = 357.634 ms total, 0.000357634 ms per iteration
pg_snprintf time = 281.708 ms total, 0.000281708 ms per iteration
ratio = 0.788

macOS:

snprintf time = 155.86 ms total, 0.00015586 ms per iteration
pg_snprintf time = 104.074 ms total, 0.000104074 ms per iteration
ratio = 0.668

FreeBSD:

snprintf time = 268.883 ms total, 0.000268883 ms per iteration
pg_snprintf time = 185.294 ms total, 0.000185294 ms per iteration
ratio = 0.689

OpenBSD:

snprintf time = 276.418 ms total, 0.000276418 ms per iteration
pg_snprintf time = 153.334 ms total, 0.000153334 ms per iteration
ratio = 0.555

NetBSD:

snprintf time = 1174.13 ms total, 0.00117413 ms per iteration
pg_snprintf time = 1508.82 ms total, 0.00150882 ms per iteration
ratio = 1.285

So there's actually a plausible argument to be made that we'd
get a net speed win on most platforms and test cases.

			regards, tom lane


------- =_aaaaaaaaaa0
Content-Type: text/x-c; name="timeprintf-2.c"; charset="us-ascii"
Content-ID: <3009.1534102449.2@sss.pgh.pa.us>
Content-Description: timeprintf-2.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;
	double elapsed2;
	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 %lld %s",
				 42, (long long) 42,
				 "01234567890012345678900123456789001234567890012345678900123456789001=
234567890012345678900123456789001234567890");
	}

	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 %lld %s",
				 42, (long long) 42,
				 "01234567890012345678900123456789001234567890012345678900123456789001=
234567890012345678900123456789001234567890");
	}

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

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

	return 0;
}

------- =_aaaaaaaaaa0--