Re: Allowing printf("%m") only where it actually works

[Tom Lane]

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


#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;
	double elapsed2;
	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 %lld %s",
				 42, (long long) 42,
				 "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 %lld %s",
				 42, (long long) 42,
				 "01234567890012345678900123456789001234567890012345678900123456789001234567890012345678900123456789001234567890");
	}

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

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

	return 0;
}