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@2ndQuadrant.com   www.2ndQuadrant.us