Overhead for stats_command_string et al, take 2 - Mailing list pgsql-hackers

I redid my previous measurements after finishing up the weekend's
hacking.  The numbers shown below are elapsed time in seconds for
time psql -f testfile.sql postgres >/dev/null

using CVS HEAD and REL8_1_STABLE branch tip, compiled --enable-debug
--disable-cassert, no nondefault options except for turning fsync off
(which doesn't particularly affect read-only tests like these anyway).
The machines are both running current Fedora Core 5.  The older x86
machine is known to have the slow-gettimeofday problem from previous
experimentation with EXPLAIN ANALYZE.  Each number is the median of 3
or more tests, rounded off to 0.1 second (I wouldn't put a lot of faith
in differences of 0.1 sec or so, because of the variance I saw in the
tests).
                    x86            x86_64
                8.1    HEAD    8.1    HEAD

100000 "SELECT 1;"            25.9    27.0     9.2    9.1
with stats_command_string=1        63.5    27.6    18.7    9.2
with log_min_duration_statement=100    26.9    27.8     9.6    9.2
with statement_timeout=100        27.5    28.6     9.6    9.8
with all 3 features            66.1    29.3    19.5    9.7

BEGIN, 100000 "SELECT 1;", COMMIT    21.2    23.1     8.3    8.4
with stats_command_string=1        52.3    23.5    15.4    8.5
with log_min_duration_statement=100    22.1    23.4     8.4    8.4
with statement_timeout=100        23.7    24.3     8.6    8.8
with all 3 features            55.2    25.5    16.0    8.8

I chose the log_min_duration_statement and statement_timeout settings
high enough so that no actual logging or timeout would happen --- the
point is to measure the measurement overhead.

The good news is that we've pretty much licked the problem of
stats_command_string costing an unreasonable amount.

The bad news is that except in the stats_command_string cases, HEAD
is noticeably slower than 8.1 on the machine with slow gettimeofday.
In the single-transaction test this might be blamed on the addition
of statement_timestamp support (which requires a gettimeofday per
statement that wasn't there in 8.1) ... but in the one-transaction-
per-statement tests that doesn't hold water, because each branch is
doing a gettimeofday per statement, just in different places.

Can anyone else reproduce this slowdown?  It might be only an artifact
of these particular builds, but it's a bit too consistent in my x86 data
to just ignore.

BTW, according to "top" the CPU usage percentages in these tests are
on the order of 55% backend, 45% psql.  Methinks psql needs a round
of performance tuning ...
        regards, tom lane