Horton
Menu

Thread

  1. Patch to show individual statement latencies in pgbench output

    Florian G. Pflug <fgp@phlo.org> — 2010-06-12T15:07:05Z

    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

  2. Re: Patch to show individual statement latencies in pgbench output

    Greg Smith <greg@2ndquadrant.com> — 2010-06-14T00:22:36Z

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

  3. Re: Patch to show individual statement latencies in pgbench output

    Florian G. Pflug <fgp@phlo.org> — 2010-06-16T18:58:55Z

    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

  4. Re: Patch to show individual statement latencies in pgbench output

    Greg Smith <greg@2ndquadrant.com> — 2010-07-28T22:48:58Z

    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

  5. Re: Patch to show individual statement latencies in pgbench output

    Florian G. Pflug <fgp@phlo.org> — 2010-07-29T01:23:51Z

    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

  6. Re: Patch to show individual statement latencies in pgbench output

    Greg Smith <greg@2ndquadrant.com> — 2010-08-03T19:16:25Z

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

  7. Re: Patch to show individual statement latencies in pgbench output

    Florian G. Pflug <fgp@phlo.org> — 2010-08-04T11:58:32Z

    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

  8. Re: Patch to show individual statement latencies in pgbench output

    Florian G. Pflug <fgp@phlo.org> — 2010-08-05T22:05:24Z

    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

  9. Re: Patch to show individual statement latencies in pgbench output

    Greg Smith <greg@2ndquadrant.com> — 2010-08-11T04:34:05Z

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

  10. Re: Patch to show individual statement latencies in pgbench output

    Tom Lane <tgl@sss.pgh.pa.us> — 2010-08-12T17:48:53Z

    Greg Smith <greg@2ndquadrant.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

  11. Re: Patch to show individual statement latencies in pgbench output

    Tom Lane <tgl@sss.pgh.pa.us> — 2010-08-12T19:20:03Z

    Greg Smith <greg@2ndquadrant.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

  12. Re: Patch to show individual statement latencies in pgbench output

    Tom Lane <tgl@sss.pgh.pa.us> — 2010-08-12T21:19:00Z

    Greg Smith <greg@2ndquadrant.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

  13. Re: Patch to show individual statement latencies in pgbench output

    Florian G. Pflug <fgp@phlo.org> — 2010-08-12T23:13:50Z

    On Aug12, 2010, at 19:48 , Tom Lane wrote:
> Greg Smith <greg@2ndquadrant.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

  14. Re: Patch to show individual statement latencies in pgbench output

    Greg Smith <greg@2ndquadrant.com> — 2010-08-13T00:22:18Z

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

  15. Re: Patch to show individual statement latencies in pgbench output

    Tom Lane <tgl@sss.pgh.pa.us> — 2010-08-13T01:51:13Z

    Florian Pflug <fgp@phlo.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