Re: [HACKERS] pgbench progress report improvements - split 3 v2 - A
On Sat, Oct 5, 2013 at 6:10 PM, Noah Misch n...@leadboat.com wrote: The sum of the squares of the latencies wraps after 2^63/(10^12 * avg_latency * nclients) seconds. That's unlikely to come up with the ordinary pgbench script, but one can reach it in a few hours when benchmarking a command that runs for many seconds. If we care, we can track the figure as a double. I merely added a comment about it. Using a double seems wise to me. I think that both int64 double are fine. The likelyhood of having underflows (double) or overflows/wraparounds (int64) seems pretty low for any practical run. I took the former because it is exact... up to when it is totally wrong. The later one may provide underestimated results silently: it would fail more continuously. So I'm okay if it is changed to double consistently. -- Fabien. -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] pgbench progress report improvements - split 3 v2 - A
pgbench already offers two schedules of pgbench --initialize messaging, message-per-100k-rows and message-per-5s. A user too picky to find satisfaction in either option can filter the messages through grep, sed et al. We patched pgbench on two occasions during the 9.3 cycle to arrive at that status quo. Had I participated, I may well have voted for something like your proposal over pgbench --quiet. Now that we've released --quiet, a proposal for an additional message schedule option needs to depict a clear and convincing step forward. This proposal does not rise to that level. The step forward is to have the same options apply to *both* modes, instead of options for one mode (default 100k or --quiet 5s), and a convenient --progress (adjustable seconds) for the other. It is convincing to me because I hate commands with non orthogonal options, as I'm sure not to notice that one option is for one mode and the other for another, and to get caught by it. But this is clearly a matter of design taste. -- Fabien. -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] pgbench progress report improvements - split 3 v2 - A
On Sat, Oct 5, 2013 at 6:10 PM, Noah Misch n...@leadboat.com wrote: The sum of the squares of the latencies wraps after 2^63/(10^12 * avg_latency * nclients) seconds. That's unlikely to come up with the ordinary pgbench script, but one can reach it in a few hours when benchmarking a command that runs for many seconds. If we care, we can track the figure as a double. I merely added a comment about it. Using a double seems wise to me. -- Robert Haas EnterpriseDB: http://www.enterprisedb.com The Enterprise PostgreSQL Company -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] pgbench progress report improvements - split 3 v2 - A
Hello Noah, Patch (4): Redefine latency as reported by pgbench and report lag more. Here is a first partial patch, which focusses on measuring latency and reporting the measure under --progress. This patch contains the features pertaining to both hypothetical patches (3) and (4), not just (4) like I requested. Sorry, I misunderstood the expected scope of your request. The sum of the squares of the latencies wraps after 2^63/(10^12 * avg_latency * nclients) seconds. That's unlikely to come up with the ordinary pgbench script, but one can reach it in a few hours when benchmarking a command that runs for many seconds. If we care, we can track the figure as a double. I merely added a comment about it. Indeed I thought about that. I choose int64 because the overflow seemed very unlikely: it would required about 1 billion pretty large 100 ms latency (2^16.6 µs) transactions to wrap around, which is a multi-year one thread run. So I stayed homogeneous to the other accumulator and the surveyed data type. Also, the measure is exact with int64, but rounding or undeflows could happen with double. Adding a comment about it is a good idea. I restored applicable parts of your update to the --progress documentation from pgbench-measurements-v5.patch. The patch made output like this: progress: 7.2 s, 1.7 tps, 205.225 stddev 3.484 ms lat, 45.472 ms lag [...] Indeed, the postfix English-like version is not very clear. progress: 36.0 s, 115.2 tps, lat avg 9.678 ms stddev 1.792, lag 0.143 ms I switched to that, except that I removed the word avg to save horizontal space and since lag is also an average though not labelled as such. Yep, space is a concern. That was one of the reason why I used +-. + printf(latency average: %.3f ms\n, + 1000.0 * duration / normal_xacts); I incorporated the nclients factor needed here. Oops!? Thanks a log for the fixes and the improvements. Which part do you want as a next step? -- Fabien. -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] pgbench progress report improvements - split 3 v2 - A
On Sun, Oct 06, 2013 at 09:40:40AM +0200, Fabien COELHO wrote: Which part do you want as a next step? I think we're done; here are the distinct changes in your original patch, along with their dispositions: Patch (1): Change the default from --progress=0 to --progress=5 Rejected Patch (2): Make --initialize mode respect --progress. Rejected Patch (3): Report the standard deviation of latency. Committed Patch (4): Redefine latency as reported by pgbench and report lag more. Committed Patch (5): Take thread start time at the beginning of the thread. Returned with Feedback Patch (6): Reduce and compensate throttling underestimation bias. Committed Patch (7): Documentation and --help corrections Committed Patch (8): Remove stray use of float. Committed -- Noah Misch EnterpriseDB http://www.enterprisedb.com -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] pgbench progress report improvements - split 3 v2 - A
Hello Noah, Patch (1): Change the default from --progress=0 to --progress=5 Rejected Yep. Too bad, esp as the default is meaningless and does not scale. Patch (2): Make --initialize mode respect --progress. Rejected I missed this one... This is just about having the same option (--progress) to set the progress report delay both under benchmarking and initialization. I do not understand where and why it would be rejected, especially as it does not imply to change the current default behavior. Patch (5): Take thread start time at the beginning of the thread. Returned with Feedback Hmmm. I fought back on the feedback:-) I thought my arguments where good enough to consider an accept. -- Fabien. -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] pgbench progress report improvements - split 3 v2 - A
On Sun, Oct 06, 2013 at 05:04:56PM +0200, Fabien COELHO wrote: Patch (2): Make --initialize mode respect --progress. Rejected I missed this one... See the second half of this message, including quoted material: http://www.postgresql.org/message-id/CA+TgmoZNXkm-EtszHX=kwq34h5ni4cs8dg31no86cmdryaq...@mail.gmail.com Patch (5): Take thread start time at the beginning of the thread. Returned with Feedback Hmmm. I fought back on the feedback:-) I thought my arguments where good enough to consider an accept. Here is the feedback in question: http://www.postgresql.org/message-id/20130930223621.ga125...@tornado.leadboat.com With or without the patch, reported performance figures are uninformative when thread start time is substantial relative to benchmark duration. A mere time accounting change will not help much; improving this requires tighter synchronization around the start of actual query activity across threads. I didn't read anything in your response as disagreement with that conclusion. nm -- Noah Misch EnterpriseDB http://www.enterprisedb.com -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] pgbench progress report improvements - split 3 v2 - A
Patch (2): Make --initialize mode respect --progress. Rejected I missed this one... See the second half of this message, including quoted material: http://www.postgresql.org/message-id/CA+TgmoZNXkm-EtszHX=kwq34h5ni4cs8dg31no86cmdryaq...@mail.gmail.com I did not read Peter Haas comments as whether --progress should be used for both modes, although it is in the section about it. All his argumentation is about *not changing any defaults*. I understood that his -1 applied about the dropping the row-counting based reporting: Robert complains about any break[ing] backward compatibility again one release later in the paragraph, not really about --progress becoming significant under -i, so this would be a veto agains what you called Patch (1). So what I've done in version 5 of the patch on this subject is that --progress specifies the interval of the progress report in any mode, and quiet just set it to five seconds for initialization as is the current behavior. Version 5 does not change any current default behavior, as I understood that this was the requirement expressed by Robert Haas. Patch (5): Take thread start time at the beginning of the thread. Returned with Feedback Hmmm. I fought back on the feedback:-) I thought my arguments where good enough to consider an accept. Here is the feedback in question: http://www.postgresql.org/message-id/20130930223621.ga125...@tornado.leadboat.com With or without the patch, reported performance figures are uninformative when thread start time is substantial relative to benchmark duration. A mere time accounting change will not help much; improving this requires tighter synchronization around the start of actual query activity across threads. I didn't read anything in your response as disagreement with that conclusion. In my answer to the message you mention. http://www.postgresql.org/message-id/alpine.DEB.2.02.1310011422130.324@sto I explained why I had to re-take gettimeofday under --rate because the start_time value cannot be relied on. The code I suggested simplifies the logic by taking the time only once, instead of ignoring the first one because it does not make sense. It seems to me that the logical answer to this argument could have been ok. But it seems that you do not percieve my logic. -- Fabien. -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] pgbench progress report improvements - split 3 v2 - A
On Sun, Oct 06, 2013 at 06:44:11PM +0200, Fabien COELHO wrote: Patch (2): Make --initialize mode respect --progress. Rejected I missed this one... See the second half of this message, including quoted material: http://www.postgresql.org/message-id/CA+TgmoZNXkm-EtszHX=kwq34h5ni4cs8dg31no86cmdryaq...@mail.gmail.com I did not read Peter Haas comments as whether --progress should be used for both modes, although it is in the section about it. All his argumentation is about *not changing any defaults*. I understood that his -1 applied about the dropping the row-counting based reporting: Robert complains about any break[ing] backward compatibility again one release later in the paragraph, not really about --progress becoming significant under -i, so this would be a veto agains what you called Patch (1). So what I've done in version 5 of the patch on this subject is that --progress specifies the interval of the progress report in any mode, and quiet just set it to five seconds for initialization as is the current behavior. Version 5 does not change any current default behavior, as I understood that this was the requirement expressed by Robert Haas. I don't know whether that accurately describes Robert's position, but I will elaborate on my own position: pgbench already offers two schedules of pgbench --initialize messaging, message-per-100k-rows and message-per-5s. A user too picky to find satisfaction in either option can filter the messages through grep, sed et al. We patched pgbench on two occasions during the 9.3 cycle to arrive at that status quo. Had I participated, I may well have voted for something like your proposal over pgbench --quiet. Now that we've released --quiet, a proposal for an additional message schedule option needs to depict a clear and convincing step forward. This proposal does not rise to that level. Patch (5): Take thread start time at the beginning of the thread. Returned with Feedback Hmmm. I fought back on the feedback:-) I thought my arguments where good enough to consider an accept. Here is the feedback in question: http://www.postgresql.org/message-id/20130930223621.ga125...@tornado.leadboat.com With or without the patch, reported performance figures are uninformative when thread start time is substantial relative to benchmark duration. A mere time accounting change will not help much; improving this requires tighter synchronization around the start of actual query activity across threads. I didn't read anything in your response as disagreement with that conclusion. In my answer to the message you mention. http://www.postgresql.org/message-id/alpine.DEB.2.02.1310011422130.324@sto I explained why I had to re-take gettimeofday under --rate because the start_time value cannot be relied on. The code I suggested simplifies the logic by taking the time only once, instead of ignoring the first one because it does not make sense. It seems to me that the logical answer to this argument could have been ok. But it seems that you do not percieve my logic. Yeah, perhaps I don't understand. Throttling behaves fine, because pgbench already does take a fresh timestamp in threadRun(). Your patch makes thread-start_time adequate in place of that fresh timestamp. If that were the patch's only effect, it would be okay as a minor code cleanup. That is not the patch's only effect. Its other effect, explored thoroughly in my post referenced above, changes one bad user-visible behavior to a different bad user-visible behavior. When a code cleanup has such a side effect, we don't commit it. -- Noah Misch EnterpriseDB http://www.enterprisedb.com -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] pgbench progress report improvements - split 3 v2 - A
On Thu, Sep 26, 2013 at 08:50:15PM +0200, Fabien COELHO wrote: Patch (4): Redefine latency as reported by pgbench and report lag more. Here is a first partial patch, which focusses on measuring latency and reporting the measure under --progress. This patch contains the features pertaining to both hypothetical patches (3) and (4), not just (4) like I requested. The sum of the squares of the latencies wraps after 2^63/(10^12 * avg_latency * nclients) seconds. That's unlikely to come up with the ordinary pgbench script, but one can reach it in a few hours when benchmarking a command that runs for many seconds. If we care, we can track the figure as a double. I merely added a comment about it. I restored applicable parts of your update to the --progress documentation from pgbench-measurements-v5.patch. The patch made output like this: progress: 7.2 s, 1.7 tps, 205.225 stddev 3.484 ms lat, 45.472 ms lag I read that as five facts: 7.2 s 1.7 tps 205.225 stddev 3.484 ms lat 45.472 ms lag That was a wrong reading; 205.225 is the latency average and 3.484 is the latency standard deviation. Let's be consistent about the placement of labels relative to their figures. Upthread, had you proposed this format: progress: 36.0 s, 115.2 tps, lat avg 9.678 ms stddev 1.792, lag 0.143 ms I switched to that, except that I removed the word avg to save horizontal space and since lag is also an average though not labelled as such. + printf(latency average: %.3f ms\n, +1000.0 * duration / normal_xacts); I incorporated the nclients factor needed here. Committed with those changes. -- Noah Misch EnterpriseDB http://www.enterprisedb.com -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] pgbench progress report improvements - split 3 v2
My feelings on the patch split haven't changed; your three bullet points call for four separate patches. Conflicting patches are bad, but dependent patches are okay; Indeed, this is the only solution if you do not want one patch. Note that it will not possible to backtrack one of the patch but the last one without conflicts. just disclose the dependency order. How about this: as a next step, please extract just this feature that I listed last Saturday: Patch (4): Redefine latency as reported by pgbench and report lag more. Once that's committed, we can move on to others. Ok, I'll submit a first part, hopefully today, possibly the one you suggest, about fixing and extending latency measure under --rate and reporting it under progress. -- Fabien. -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] pgbench progress report improvements - split 3 v2 - A
Patch (4): Redefine latency as reported by pgbench and report lag more.
Here is a first partial patch, which focusses on measuring latency and
reporting the measure under --progress.
**
Improve pgbench measurements progress report
Measure transaction latency instead under --rate and --progress.
The previous computed figure does not make sense under throttling:
as sleep throttling time was included in the figures, the displayed
results were plain false.
The latency and its standard deviation are printed out under progress and
in the final report when available.
It could be made always available, but that would require to accept
additional gettimeofday calls. I do not think that there is a performance
issue here, but there is significant opposition to the idea.
Sample output under benchmarking with --progress=1
progress: 1.0 s, 2626.1 tps, 0.374 stddev 0.597 ms lat
progress: 2.0 s, 2766.6 tps, 0.358 stddev 0.588 ms lat
progress: 3.0 s, 2567.4 tps, 0.385 stddev 0.665 ms lat
progress: 4.0 s, 3014.2 tps, 0.328 stddev 0.593 ms lat
progress: 5.0 s, 2959.3 tps, 0.334 stddev 0.553 ms lat
...
progress: 16.0 s, 5009.2 tps, 0.197 stddev 0.381 ms lat
...
progress: 24.0 s, 7051.2 tps, 0.139 stddev 0.284 ms lat
...
progress: 50.0 s, 6860.5 tps, 0.143 stddev 0.052 ms lat
...
The warmup is quite fast because the DB is on a SSD. In the beginning
the standard deviation is well over the average transaction time, but
when the steady state is reached (later) it is much below.
--
Fabien.diff --git a/contrib/pgbench/pgbench.c b/contrib/pgbench/pgbench.c
index 06dd709..a48498a 100644
--- a/contrib/pgbench/pgbench.c
+++ b/contrib/pgbench/pgbench.c
@@ -172,6 +172,7 @@ int agg_interval; /* log aggregates instead of individual
* transactions */
int progress = 0; /* thread progress report every this seconds */
int progress_nclients = 0; /* number of clients for progress report */
+int progress_nthreads = 0; /* number of threads for progress report */
bool is_connect; /* establish connection for each transaction */
bool is_latencies; /* report per-command latencies */
int main_pid; /* main process id used in log filename */
@@ -214,6 +215,8 @@ typedef struct
int nvariables;
instr_time txn_begin; /* used for measuring transaction latencies */
instr_time stmt_begin; /* used for measuring statement latencies */
+ int64 txn_latencies; /* cumulated latencies */
+ int64 txn_sqlats; /* cumulated square latencies */
bool is_throttled; /* whether transaction throttling is done */
int use_file; /* index in sql_files for this client */
bool prepared[MAX_FILES];
@@ -243,6 +246,8 @@ typedef struct
{
instr_time conn_time;
int xacts;
+ int64 latencies;
+ int64 sqlats;
int64 throttle_lag;
int64 throttle_lag_max;
} TResult;
@@ -1003,6 +1008,21 @@ top:
}
/*
+ * always record latency under progress or throttling
+ */
+ if ((progress || throttle_delay) commands[st-state + 1] == NULL)
+ {
+ instr_time now, diff;
+ int64 latency;
+ INSTR_TIME_SET_CURRENT(now);
+ diff = now;
+ INSTR_TIME_SUBTRACT(diff, st-txn_begin);
+ latency = INSTR_TIME_GET_MICROSEC(diff);
+ st-txn_latencies += latency;
+ st-txn_sqlats += latency*latency;
+ }
+
+ /*
* if transaction finished, record the time it took in the log
*/
if (logfile commands[st-state + 1] == NULL)
@@ -1191,8 +1211,8 @@ top:
goto top;
}
- /* Record transaction start time if logging is enabled */
- if (logfile st-state == 0)
+ /* Record transaction start time under logging, progress or throttling */
+ if ((logfile || progress || throttle_delay) st-state == 0)
INSTR_TIME_SET_CURRENT(st-txn_begin);
/* Record statement start time if per-command latencies are requested */
@@ -2096,6 +2116,7 @@ static void
printResults(int ttype, int normal_xacts, int nclients,
TState *threads, int nthreads,
instr_time total_time, instr_time conn_total_time,
+ int64 total_latencies, int64 total_sqlats,
int64 throttle_lag, int64 throttle_lag_max)
{
double time_include,
@@ -2135,6 +2156,22 @@ printResults(int ttype, int normal_xacts, int nclients,
normal_xacts);
}
+ if (throttle_delay || progress)
+ {
+ /* compute and show latency average and standard deviation */
+ double latency = 0.001 * total_latencies / normal_xacts;
+ double sqlat = (double) total_sqlats / normal_xacts;
+ printf(latency average: %.3f ms\n
+ latency stddev: %.3f ms\n,
+ latency, 0.001 * sqrt(sqlat - 100*latency*latency));
+ }
+ else
+ {
+ /* only an average latency computed from the duration is available */
+ printf(latency average: %.3f ms\n,
+ 1000.0 * duration / normal_xacts);
+ }
+
if (throttle_delay)
{
/*
@@ -2143,7 +2180,7 @@ printResults(int ttype, int normal_xacts, int nclients,
* transaction. The measured lag may be caused by thread/client load,
* the database load, or the Poisson
Re: [HACKERS] pgbench progress report improvements - split 3 v2
On Tue, Sep 24, 2013 at 10:41:17PM +0200, Fabien COELHO wrote: These changes are coupled because measures are changed, and their reporting as well. Submitting separate patches for these different features would result in conflicting or dependent patches, so I wish to avoid that if possible. My feelings on the patch split haven't changed; your three bullet points call for four separate patches. Conflicting patches are bad, but dependent patches are okay; just disclose the dependency order. How about this: as a next step, please extract just this feature that I listed last Saturday: Patch (4): Redefine latency as reported by pgbench and report lag more. Once that's committed, we can move on to others. nm -- Noah Misch EnterpriseDB http://www.enterprisedb.com -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] pgbench progress report improvements - split 3
On 09/22/2013 10:44 PM, Fabien COELHO wrote: Due to the possibly repetitive table structure of the data, maybe CSV would make sense as well. It is less extensible, but it is directly usable by sqlite or pg. I'd be OK with CSV. At least I wouldn't be regexing the output. -- Josh Berkus PostgreSQL Experts Inc. http://pgexperts.com -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] pgbench progress report improvements - split 3 v2
Split 3 of the initial submission, which actually deal with data measured and reported on stderr under various options. This version currently takes into account many comments by Noah Mish. In particular, the default no report behavior under benchmarking is not changed, although I really think that it should. Also, the standard deviation is only shown when available, which is not in under all settings, because of concerns expressed about the cost of additional calls to gettimeofday. ISTM that these concerned are misplaced in this particular case. Yet another version to fulfill requirements by Robert Haas not to change current default behaviors. The initialization progress is reported every 100-k rows, and there is no progress report for benchmarking. Improve pgbench measurements progress report These changes are coupled because measures are changed, and their reporting as well. Submitting separate patches for these different features would result in conflicting or dependent patches, so I wish to avoid that if possible. - Use same progress and quiet options both under init bench. However, the default reporting is NOT changed, as required by Robert Haas. It is currently every 100k rows when initializing, and nothing when benchmarking. I would suggest to change this default to a few seconds for both. The 100-k row report is very verbose an unreadable on good hardware. For benchmarking, the rational is that it is error prone as it must run a long time to be significant because of warmup effects (esp on HDD, less true on SSD). Seeing how the current performance evolve would help pgbench users realise that. See down below a sample output. - Measure transaction latency instead of computing it, for --rate and --progress. The previous computed figure does not make sense under throttling: as sleep throttling time was included in the figures, the displayed results were plain false. The latency and its standard deviation are printed out under progress and in the final report when available. It could be made always available, but that would require to accept additional gettimeofday calls. I do not think that there is a performance issue here, but there is significant opposition to the idea. - Take thread start time at the beginning of the thread (!) Otherwise it includes pretty slow thread/fork system start times in the measurements. May help with bug #8326. This also helps with throttling, as the start time is used to adjust the rate: if it is not the actual start time, there is a bit of a rush at the beginning in order to catch up. Taking the start time when the thread actually starts is the sane thing to do to avoid surprises at possibly strange measures on short runs. Sample output under initialization with --progress=1 creating tables... 1126000 of 300 tuples (37%) done (elapsed 1.00 s, remaining 1.67 s). 2106000 of 300 tuples (70%) done (elapsed 2.00 s, remaining 0.85 s). 2824000 of 300 tuples (94%) done (elapsed 3.00 s, remaining 0.19 s). 300 of 300 tuples (100%) done (elapsed 3.19 s, remaining 0.00 s). vacuum... set primary keys... done. Sample output under benchmarking with --progress=1 progress: 1.0 s, 2626.1 tps, 0.374 stddev 0.597 ms lat progress: 2.0 s, 2766.6 tps, 0.358 stddev 0.588 ms lat progress: 3.0 s, 2567.4 tps, 0.385 stddev 0.665 ms lat progress: 4.0 s, 3014.2 tps, 0.328 stddev 0.593 ms lat progress: 5.0 s, 2959.3 tps, 0.334 stddev 0.553 ms lat ... progress: 16.0 s, 5009.2 tps, 0.197 stddev 0.381 ms lat ... progress: 24.0 s, 7051.2 tps, 0.139 stddev 0.284 ms lat ... progress: 50.0 s, 6860.5 tps, 0.143 stddev 0.052 ms lat ... The warmup is quite fast because the DB is on a SSD. In the beginning the standard deviation is well over the average transaction time, but when the steady state is reached (later) it is much below. -- Fabien.diff --git a/contrib/pgbench/pgbench.c b/contrib/pgbench/pgbench.c index ad8e272..934244b 100644 --- a/contrib/pgbench/pgbench.c +++ b/contrib/pgbench/pgbench.c @@ -167,11 +167,13 @@ char *index_tablespace = NULL; #define SCALE_32BIT_THRESHOLD 2 bool use_log; /* log transaction latencies to a file */ -bool use_quiet; /* quiet logging onto stderr */ int agg_interval; /* log aggregates instead of individual * transactions */ -int progress = 0; /* thread progress report every this seconds */ +bool use_quiet = false; /* more or less quiet logging onto stderr */ +int progress = -1; /* report every this seconds. + 0 is no report, -1 is not set yet */ int progress_nclients = 0; /* number of clients for progress report */ +int progress_nthreads = 0; /* number of threads for progress report */ bool is_connect; /* establish connection for each transaction */ bool is_latencies; /* report per-command latencies */ int main_pid;
Re: [HACKERS] pgbench progress report improvements - split 3
On 9/22/13 2:58 PM, Fabien wrote: Split 3 of the initial submission, which actually deal with data measured and reported on stderr under various options. It seems this patch doesn't apply. Does it need the first two applied first? -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] pgbench progress report improvements - split 3
Dear Peter,
Split 3 of the initial submission, which actually deal with data
measured and reported on stderr under various options.
It seems this patch doesn't apply. Does it need the first two applied
first?
Oops. Indeed. The patch is fully independent of the two others. It was
generated with git diff -b master, because I was told not to change
spacing, but then it must be applied with patch -l -p1.
Please find attached a new version without this requirement.
postgresql git branch test
postgresql git checkout test
Switched to branch 'test'
postgresql patch -p1 ../pgbench-measurements-v4.patch
patching file contrib/pgbench/pgbench.c
patching file doc/src/sgml/pgbench.sgml
--
Fabien.diff --git a/contrib/pgbench/pgbench.c b/contrib/pgbench/pgbench.c
index ad8e272..2590b12 100644
--- a/contrib/pgbench/pgbench.c
+++ b/contrib/pgbench/pgbench.c
@@ -167,11 +167,12 @@ char *index_tablespace = NULL;
#define SCALE_32BIT_THRESHOLD 2
bool use_log; /* log transaction latencies to a file */
-bool use_quiet; /* quiet logging onto stderr */
int agg_interval; /* log aggregates instead of individual
* transactions */
-int progress = 0; /* thread progress report every this seconds */
+int progress = -1; /* report every this seconds.
+ 0 is quiet, -1 is not set yet */
int progress_nclients = 0; /* number of clients for progress report */
+int progress_nthreads = 0; /* number of threads for progress report */
bool is_connect; /* establish connection for each transaction */
bool is_latencies; /* report per-command latencies */
int main_pid; /* main process id used in log filename */
@@ -214,6 +215,8 @@ typedef struct
int nvariables;
instr_time txn_begin; /* used for measuring transaction latencies */
instr_time stmt_begin; /* used for measuring statement latencies */
+ int64 txn_latencies; /* cumulated latencies */
+ int64 txn_sqlats; /* cumulated square latencies */
bool is_throttled; /* whether transaction throttling is done */
int use_file; /* index in sql_files for this client */
bool prepared[MAX_FILES];
@@ -243,6 +246,8 @@ typedef struct
{
instr_time conn_time;
int xacts;
+ int64 latencies;
+ int64 sqlats;
int64 throttle_lag;
int64 throttle_lag_max;
} TResult;
@@ -347,7 +352,6 @@ usage(void)
-i, --initialize invokes initialization mode\n
-F, --fillfactor=NUM set fill factor\n
-n, --no-vacuum do not run VACUUM after initialization\n
- -q, --quiet quiet logging (one message each 5 seconds)\n
-s, --scale=NUM scaling factor\n
--foreign-keys create foreign key constraints between tables\n
--index-tablespace=TABLESPACE\n
@@ -367,7 +371,6 @@ usage(void)
(default: simple)\n
-n, --no-vacuum do not run VACUUM before tests\n
-N, --skip-some-updates skip updates of pgbench_tellers and pgbench_branches\n
- -P, --progress=NUM show thread progress report every NUM seconds\n
-r, --report-latencies report average latency per command\n
-R, --rate=SPEC target rate in transactions per second\n
-s, --scale=NUM report this scale factor in output\n
@@ -382,6 +385,8 @@ usage(void)
-d, --debug print debugging output\n
-h, --host=HOSTNAME database server host or socket directory\n
-p, --port=PORT database server port number\n
+ -P, --progress=NUM show progress report every NUM seconds\n
+ -q, --quiet no progress report\n
-U, --username=USERNAME connect as specified database user\n
-V, --versionoutput version information, then exit\n
-?, --help show this help, then exit\n
@@ -1003,6 +1008,21 @@ top:
}
/*
+ * always record latency under progress or throttling
+ */
+ if ((progress || throttle_delay) commands[st-state + 1] == NULL)
+ {
+ instr_time now, diff;
+ int64 latency;
+ INSTR_TIME_SET_CURRENT(now);
+ diff = now;
+ INSTR_TIME_SUBTRACT(diff, st-txn_begin);
+ latency = INSTR_TIME_GET_MICROSEC(diff);
+ st-txn_latencies += latency;
+ st-txn_sqlats += latency*latency;
+ }
+
+ /*
* if transaction finished, record the time it took in the log
*/
if (logfile commands[st-state + 1] == NULL)
@@ -1191,8 +1211,11 @@ top:
goto top;
}
- /* Record transaction start time if logging is enabled */
- if (logfile st-state == 0)
+ /*
+ * Record transaction start time
+ * if logging, progress or throttling is enabled
+ */
+ if ((logfile || progress || throttle_delay) st-state == 0)
INSTR_TIME_SET_CURRENT(st-txn_begin);
/* Record statement start time if per-command latencies are requested */
@@ -1678,25 +1701,8 @@ init(bool is_no_vacuum)
exit(1);
}
- /*
- * If we want to
Re: [HACKERS] pgbench progress report improvements - split 3
Split 3 of the initial submission, which actually deal with data measured and reported on stderr under various options. This version currently takes into account many comments by Noah Mish. In particular, the default no report behavior under benchmarking is not changed, although I really think that it should. Also, the standard deviation is only shown when available, which is not in under all settings, because of concerns expressed about the cost of additional calls to gettimeofday. ISTM that these concerned are misplaced in this particular case. Improve pgbench measurements progress report These changes are coupled because measures are changed, and their reporting as well. Submitting separate patches for these interlinked features would result in conflicting or dependent patches, so I wish to avoid that. Also it would require more reviewer time. - Use same progress and quiet options both under init bench. The reporting is every 5 seconds for initialization, and currently no report for benchmarking. I strongly suggest to change this default to 5 seconds for both, if people do not veto any change of the default behavior... The rational is that benchmarking is error prone as it must run a long time to be significant because of warmup effects (esp on HDD, less true on SSD). Seeing how the current performance evolve would help pgbench users realise that. See down below a sample output. The previous progress report under initialization, which printed a line every 100,000 rows, is removed, as it is much to verbose for most hardware, and pretty long for any significant scale. - Measure transaction latency instead of computing it, for --rate and --progress. The previous computed figure does not make sense under throttling: as sleep throttling time was included in the figures, the displayed results were plain false. The latency and its standard deviation are printed out under progress and in the final report when available. It could be made always available, but that would require to accept additional gettimeofday calls. I do not think that there is a performance issue here, but there is no concensus yet. - Take thread start time at the beginning of the thread (!) Otherwise it includes pretty slow thread/fork system start times in the measurements. May help with bug #8326. This also helps with throttling, as the start time is used to adjust the rate: if it is not the actual start time, there is a bit of a rush at the beginning in order to catch up. Taking the start time when the thread actually starts is the sane thing to do to avoid surprises at possibly strange measures on short runs. Sample output under initialization with --progress=1 creating tables... 1126000 of 300 tuples (37%) done (elapsed 1.00 s, remaining 1.67 s). 2106000 of 300 tuples (70%) done (elapsed 2.00 s, remaining 0.85 s). 2824000 of 300 tuples (94%) done (elapsed 3.00 s, remaining 0.19 s). 300 of 300 tuples (100%) done (elapsed 3.19 s, remaining 0.00 s). vacuum... set primary keys... done. Sample output under benchmarking with --progress=1 progress: 1.0 s, 2626.1 tps, 0.374 stddev 0.597 ms lat progress: 2.0 s, 2766.6 tps, 0.358 stddev 0.588 ms lat progress: 3.0 s, 2567.4 tps, 0.385 stddev 0.665 ms lat progress: 4.0 s, 3014.2 tps, 0.328 stddev 0.593 ms lat progress: 5.0 s, 2959.3 tps, 0.334 stddev 0.553 ms lat ... progress: 16.0 s, 5009.2 tps, 0.197 stddev 0.381 ms lat ... progress: 24.0 s, 7051.2 tps, 0.139 stddev 0.284 ms lat ... progress: 50.0 s, 6860.5 tps, 0.143 stddev 0.052 ms lat ... The warmup is quite fast because the DB is on a SSD. In the beginning the standard deviation is well over the average transaction time, but when the steady state is reached (later) it is much below. -- Fabien.diff --git a/contrib/pgbench/pgbench.c b/contrib/pgbench/pgbench.c index ad8e272..0bdf8dd 100644 --- a/contrib/pgbench/pgbench.c +++ b/contrib/pgbench/pgbench.c @@ -167,11 +167,12 @@ char *index_tablespace = NULL; #define SCALE_32BIT_THRESHOLD 2 bool use_log; /* log transaction latencies to a file */ -bool use_quiet; /* quiet logging onto stderr */ int agg_interval; /* log aggregates instead of individual * transactions */ -int progress = 0; /* thread progress report every this seconds */ +int progress = -1; /* report every this seconds. + 0 is quiet, -1 is not set yet */ int progress_nclients = 0; /* number of clients for progress report */ +int progress_nthreads = 0; /* number of threads for progress report */ bool is_connect; /* establish connection for each transaction */ bool is_latencies; /* report per-command latencies */ int main_pid; /* main process id used in log filename */ @@ -214,6 +215,8 @@ typedef struct int nvariables; instr_time txn_begin; /* used for measuring
Re: [HACKERS] pgbench progress report improvements - split 3
Fabien, As long as you're hacking pgbench output, what about offering a JSON option instead of the text output? I'm working on automating pgbench performance testing, and having the output in a proper delimited format would be really helpful. -- Josh Berkus PostgreSQL Experts Inc. http://pgexperts.com -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] pgbench progress report improvements - split 3
Hello Josh, As long as you're hacking pgbench output, what about offering a JSON option instead of the text output? I'm working on automating pgbench performance testing, and having the output in a proper delimited format would be really helpful. I'm more a grep | cut | ... person, but I do understand your point about automation. My favorite hack is to load benchmark data into sqlite and perform query to build data extract for gnuplot figures. So I can put that in the stack of things to do when I have some time. Due to the possibly repetitive table structure of the data, maybe CSV would make sense as well. It is less extensible, but it is directly usable by sqlite or pg. -- Fabien. -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
