Re: Patch to show individual statement latencies in pgbench output

Finally got around to taking a longer look at your patch, sorry about
the delay here. Patch itself seems to work on simple tests anyway (more
on the one suspect bit below). You didn't show what the output looks
like, so let's start with that because it is both kind of neat and not
what I expected from your description. Here's the sort of extra stuff
added to the end of the standard output when you toggle this feature on:

$ pgbench -S pgbench -T 10 -c 8 -j 4 -l -r
...
tps = 28824.943954 (excluding connections establishing)
command latencies
0.001487 \set naccounts 100000 * :scale
0.000677 \setrandom aid 1 :naccounts
0.273983 SELECT abalance FROM pgbench_accounts WHERE aid = :aid;

From the way you described the patch, I had thought that you were just
putting this information into the log files or something like that. In
fact, it's not in the log files; it just shows up in this summary at the
end. I'm not sure if that's best or not. Some might want to see how the
per-statement variation varies over time. Sort of torn on whether the
summary alone is enough detail or not. Let me play with this some more
and get back to you on that.

Here's what a standard test looks like:

tps = 292.468349 (excluding connections establishing)
command latencies
0.002120 \set nbranches 1 * :scale
0.000682 \set ntellers 10 * :scale
0.000615 \set naccounts 100000 * :scale
0.000723 \setrandom aid 1 :naccounts
0.000522 \setrandom bid 1 :nbranches
0.000553 \setrandom tid 1 :ntellers
0.000525 \setrandom delta -5000 5000
0.070307 BEGIN;
1.721631 UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE
aid = :aid;
0.147854 SELECT abalance FROM pgbench_accounts WHERE aid = :aid;
11.894366 UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE
tid = :tid;
4.761715 UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE
bid = :bid;
0.643895 INSERT INTO pgbench_history (tid, bid, aid, delta, mtime)
VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);
7.452017 END;

I'm happy to see that the END here has a significant portion of time
assigned to it, which means that it's correctly tracking the commit that
happens there. It's possible to ask the question "why add this feature
when pg_stat_statements will get you the same data?". I think this gives
a different enough view of things that it's worth adding anyway. Getting
the END statements tracked, not having to use prepared statements to
make it work, and now having to worry about overflowing the
pg_stat_statements.max parameter that limits what that module tracks are
all points in favor of this patch being useful even if you know about
pg_stat_statements.

Now onto the nitpicking. With the standard Ubuntu compiler warnings on I
get this:

pgbench.c:1588: warning: ‘i’ may be used uninitialized in this function

If you didn't see that, you may want to double-check how verbose you
have your compiler setup to be; maybe you just missed it (which is of
course what reviewers are here for). Regardless, the troublesome bit is
this:

int i;

commands = process_commands(&buf[i]);

Which is obviously not a good thing. I'm not sure entirely what you're
doing with the changes you made to process_file, but I'd suggest you
double check the logic and coding of that section because there's at
least one funny thing going on here with i being used without
initialization first here. I didn't try yet to figure out how this error
might lead to a bug, but there probably is one.

This looks like a good feature to me, just not sure if it's worth
extending to produce even more output if people want to see it. Can
always layer that on top later. I'll continue testing and try to get a
firmer opinion. Please take a look at the problem I pointed out and
produce a new patch when you get a chance that fixes that part, so at
least we don't get stuck on that detail.

--
Greg Smith 2ndQuadrant US Baltimore, MD
PostgreSQL Training, Services and Support
greg(at)2ndQuadrant(dot)com www.2ndQuadrant.us