Re: Patch to show individual statement latencies in pgbench output

Hi

To be able to asses the performance characteristics of the different wal-related options, I patched pgbench to show the average latency of each individual statement. The idea is to be able to compare the latency of the COMMIT with the ones of the other statements.

This patch adds two new finds to the Command struct, elapsed and cnt, which accumulate the total time spent on each statement and the number of times it was executed. printResults essentially prings elapsed/cnt for each statement, followed by the statement itself.

Patch is attached.

best regards,
Florian Pflug

Florian Pflug wrote:
> To be able to asses the performance characteristics of the different wal-related options, I patched pgbench to show the average latency of each individual statement. The idea is to be able to compare the latency of the COMMIT with the ones of the other statements.
>

That's an interesting idea, particularly given that people don't really
understand where the time is going in the standard pgbench test. Your
first bit of review feedback is that this would have to be something you
could toggle on and off, there's no way most people want to pay this
penalty. If you submit a new patch with a command line option to enable
this alternate logging format and add the result to
https://commitfest.postgresql.org/action/commitfest_view?id=6 , you can
put my name down as a reviewer and I'll take a deeper look at it as part
of that.

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

On Jun 14, 2010, at 2:22 , Greg Smith wrote:
> Florian Pflug wrote:
>> To be able to asses the performance characteristics of the different wal-related options, I patched pgbench to show the average latency of each individual statement. The idea is to be able to compare the latency of the COMMIT with the ones of the other statements.
>
> That's an interesting idea, particularly given that people don't really understand where the time is going in the standard pgbench test. Your first bit of review feedback is that this would have to be something you could toggle on and off, there's no way most people want to pay this penalty. If you submit a new patch with a command line option to enable this alternate logging format and add the result to https://commitfest.postgresql.org/action/commitfest_view?id=6 , you can put my name down as a reviewer and I'll take a deeper look at it as part of that.

Thank for offering to review this!

Here is an updated patch that adds a command-line option (-r) to enable/disable per-command latency reporting. It also uses the INSTR_TIME infrastructure that 9.0 provides, and should work correctly in multi-threaded mode. Data is collected per-thread and summarized only for reporting to avoid locking overhead. It now shows all lines for the SQL scripts together with their latencies (zero for comments), not only those containing SQL commands.

I'll add this patch to the next commitfest, and put you down as a reviewer, as you suggested.

best regards,
Florian Pflug

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

On Jul29, 2010, at 00:48 , Greg Smith wrote:
> 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:
>
> <snipped output>
>
> 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.

I think the two features are pretty much orthogonal, even though they'd make use of the same per-statement instrumentation machinery.

I created the patch to tune the wal_writer for the synchronous_commit=off case - the idea being that the COMMIT should be virtually instantaneous if the wal_writer writes old wal buffers out fast enough.

I haven't yet used pgbench's log output feature, so I can't judge how useful the additional of per-statement data to that log is, and what the format should be. However, if you think it's useful and can come up with a sensible format, I'd be happy to add that feature to the patch.

> 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]);

Fixed. That was a leftover of the trimming and comment skipping logic, which my patch moves to process_command.

Updated patch is attached.

Thanks for your extensive review &
best regards,
Florian Pflug

Florian Pflug wrote:
> I created the patch to tune the wal_writer for the synchronous_commit=off case - the idea being that the COMMIT should be virtually instantaneous if the wal_writer writes old wal buffers out fast enough.
>

As I was saying, being able to see the COMMIT times for purposes such as
that is something I consider valuable about using this instrumentation
that's not really targeted by pg_stat_statements, the other way built-in
way people might try to get it.

> I haven't yet used pgbench's log output feature, so I can't judge how useful the additional of per-statement data to that log is, and what the format should be. However, if you think it's useful and can come up with a sensible format, I'd be happy to add that feature to the patch.
>

Let's worry about that in the future. Maybe it's a good add-on, but
it's more than I have time to get into during this CF personally.

> That was a leftover of the trimming and comment skipping logic, which my patch moves to process_command.
>

I think there's still a trimming error here--line 195 of the new patch
is now removing the declaration of "i" just before it sets it to zero?

On the coding standard side, I noticed all your for loops are missing a
space between the for and the (; that should get fixed.

Finally, now that the rest of the patch is looking in good shape and is
something I think is worth considering to commit, it's time to work on
the documentation SGML.

Also: when generating multiple versions of a patch like this, standard
practice is to add something like "-vX" to the naming, so those of us
trying to review can keep them straight. So next one would be
"pgbench_statementlatency_v3.patch" or something like that. It's a good
habit to get into from first version of a patch you submit. Presuming
that's going to be the only version is optimistic for all but the
smallest of patches, and sometimes not even them...

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

On Aug3, 2010, at 21:16 , Greg Smith wrote:
>> That was a leftover of the trimming and comment skipping logic, which my patch moves to process_command.
>
> I think there's still a trimming error here--line 195 of the new patch is now removing the declaration of "i" just before it sets it to zero?
Hm, I think it's just the diff thats miss-leading there. It correctly marks the "int i" line as "removed" with a "-", but for some reason marks the "i = 0" line (and its successors) with a "!", although they're removed too, and not modified.

> On the coding standard side, I noticed all your for loops are missing a space between the for and the (; that should get fixed.
Fixed

>
> Finally, now that the rest of the patch is looking in good shape and is something I think is worth considering to commit, it's time to work on the documentation SGML.
I've added the "-r" option to the list of pgbench options in pgbench.sgml and also added a short section that shows how the output looks like, similar to how things are done for the "-l" option.

> Also: when generating multiple versions of a patch like this, standard practice is to add something like "-vX" to the naming, so those of us trying to review can keep them straight.
Will do from now on.

Updated patch is attached. I've also pushed this as branch "pgbench_statementlatency" to git://github.com/fgp/postgres.git

best regards,
Florian Pflug

On Aug4, 2010, at 13:58 , Florian Pflug wrote:
> On Aug3, 2010, at 21:16 , Greg Smith wrote:
>>> That was a leftover of the trimming and comment skipping logic, which my patch moves to process_command.
>>
>> I think there's still a trimming error here--line 195 of the new patch is now removing the declaration of "i" just before it sets it to zero?
> Hm, I think it's just the diff thats miss-leading there. It correctly marks the "int i" line as "removed" with a "-", but for some reason marks the "i = 0" line (and its successors) with a "!", although they're removed too, and not modified.
>
>> On the coding standard side, I noticed all your for loops are missing a space between the for and the (; that should get fixed.
> Fixed

Crap. I've messed up to the effect that the for-loop formatting fix wasn't actually in the patch.

Attached is an updated version (v4).

Sorry for the noise.

best regards,
Florian Pflug

Florian Pflug wrote:
> Attached is an updated version (v4).
>

I've attached a v5. No real code changes from Florian's version, just
some wording/style fixes and rework on the documentation. The user side
is now consistent about calling these statement latencies for example,
even though the internals still call them command latencies most places.

Since using this new feature will introduce a whole stack of new calls
to get the system time, I also added a warning about that impacting results:

Note that collecting the additional timing information needed for
detailed latency computation does add some overhead. This will slow
average execution speed and lower the computed TPS. The exact amount
of slowdown varies significantly based on platform and hardware.
Comparing average TPS values with and without latency reporting enabled
is a good way to measure if the timing overhead is significant.

I wasn't able to see any significant slowdown on my modern Linux systems
doing such a test:

$ ./pgbench -T 10 -S -c 8 -j 4 pgbench
tps = 6716.039813 (including connections establishing)
tps = 6720.238878 (excluding connections establishing)
$ ./pgbench -T 10 -S -c 8 -j 4 -r pgbench
tps = 6708.544618 (including connections establishing)
tps = 6712.728526 (excluding connections establishing)

But I know gettimeofday is fast here. Worth including a warning for
though I think.

I'm out of things to check here, marking this one ready for a committer
review. The patch hasn't had a committer assigned yet, so whoever wants
to claim it should mark the CF app.

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

Greg Smith <greg(at)2ndquadrant(dot)com> writes:
> Florian Pflug wrote:
>> Attached is an updated version (v4).

> I've attached a v5. No real code changes from Florian's version, just
> some wording/style fixes and rework on the documentation.

I'm looking through this patch now. It looks mostly good, but I am
wondering just exactly what is the rationale for adding comment
statements to the data structures, rather than ignoring them as before.
It seems like a complete waste of logic, memory space, and cycles;
moreover it renders the documentation's statement that comments
"are ignored" incorrect. I did not find anything in the patch history
explaining the point of that change.

regards, tom lane

Greg Smith <greg(at)2ndquadrant(dot)com> writes:
> Florian Pflug wrote:
>> Attached is an updated version (v4).

> I've attached a v5.

BTW, I discovered a rather nasty shortcoming of this patch on platforms
without ENABLE_THREAD_SAFETY. It doesn't work, and what's worse, it
*looks* like it's working, because it gives you plausible-looking
numbers. But actually the numbers are only averages across the first
worker thread. The other threads are in sub-processes where they can't
affect the contents of the parent's arrays.

Since platforms without ENABLE_THREAD_SAFETY are only a small minority
these days, this is probably not sufficient reason to reject the patch.
What I plan to do instead is reject the combination of -r with -j larger
than 1 on such platforms:

if (is_latencies)
{
/*
* is_latencies only works with multiple threads in thread-based
* implementations, not fork-based ones, because it supposes that the
* parent can see changes made to the command data structures by child
* threads. It seems useful enough to accept despite this limitation,
* but perhaps we should FIXME someday.
*/
#ifndef ENABLE_THREAD_SAFETY
if (nthreads > 1)
{
fprintf(stderr, "-r does not work with -j larger than 1 on this platform.\n");
exit(1);
}
#endif

It could be fixed with enough effort, by having the child threads pass
back their numbers through the child-to-parent pipes. I'm not
interested in doing that myself though.

If anyone thinks this problem makes it uncommittable, speak up now.

regards, tom lane

Greg Smith <greg(at)2ndquadrant(dot)com> writes:
> I've attached a v5. No real code changes from Florian's version, just
> some wording/style fixes and rework on the documentation.

I've committed this with some editorialization. The main non-cosmetic
change was that I pulled the latency statistics counters out of the
per-Command data structures and put them into per-thread arrays instead.
I did this for two reasons:

1. Having different threads munging adjacent array entries without any
locking makes me itch. On some platforms that could possibly fail
entirely, and in any case it's likely to be a performance hit on
machines where processors lock whole cache lines (which is most of them
these days, I think).

2. It should make it a lot easier to pass the per-thread results back up
to the parent in a fork-based implementation, should anyone desire to
fix the limitation I mentioned before.

regards, tom lane

On Aug12, 2010, at 19:48 , Tom Lane wrote:
> Greg Smith <greg(at)2ndquadrant(dot)com> writes:
>> Florian Pflug wrote:
>>> Attached is an updated version (v4).
>
>> I've attached a v5. No real code changes from Florian's version, just
>> some wording/style fixes and rework on the documentation.
>
> I'm looking through this patch now. It looks mostly good, but I am
> wondering just exactly what is the rationale for adding comment
> statements to the data structures, rather than ignoring them as before.
> It seems like a complete waste of logic, memory space, and cycles;
> moreover it renders the documentation's statement that comments
> "are ignored" incorrect. I did not find anything in the patch history
> explaining the point of that change.

To be able to include the comments (with an average latency of zero) in the latency report. This makes the latency report as self-explanatory as the original script was (Think latency report copy-and-pasted into an e-mail or wiki). It also has the benefit of making the line numbers of the latency report agree to those of the original script, which seemed like a natural thing to do, and might make some sorts of post-processing easier. It does make doCustom() a bit more complex, though.

Anyway, I guess the chance of adding this back is slim now that the patch is committed. Oh well.

Thanks for committing this, and
best regards,
Florian Pflug

Tom Lane wrote:
> It could be fixed with enough effort, by having the child threads pass
> back their numbers through the child-to-parent pipes. I'm not
> interested in doing that myself though.
>

That does seem an improvement with a very limited user base it's
applicable to. Probably the next useful improvement to this feature is
to get per-statement data into the latency log files if requested. If
this issue gets in the way there somehow, maybe it's worth squashing
then. I don't think it will though.

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

Florian Pflug <fgp(at)phlo(dot)org> writes:
> On Aug12, 2010, at 19:48 , Tom Lane wrote:
>> I'm looking through this patch now. It looks mostly good, but I am
>> wondering just exactly what is the rationale for adding comment
>> statements to the data structures, rather than ignoring them as before.

> To be able to include the comments (with an average latency of zero)
> in the latency report. This makes the latency report as
> self-explanatory as the original script was (Think latency report
> copy-and-pasted into an e-mail or wiki). It also has the benefit of
> making the line numbers of the latency report agree to those of the
> original script, which seemed like a natural thing to do, and might
> make some sorts of post-processing easier. It does make doCustom() a
> bit more complex, though.

I had wondered if the original form of the patch printed line numbers
rather than the actual line contents. If that were true then it'd make
sense to include comment lines. In the current form of the patch,
though, I think the output is just as readable without comment lines ---
and I'm not thrilled with having this patch materially affect the
behavior for cases where -r wasn't even specified.

regards, tom lane