PATCH: pgbench - aggregation of info written into log
Hi,
this patch adds support for aggregation of info written into the log.
Instead of info about each transaction, a summary for time intervals (with
custom length) is written into the log. All you need to do is add "-A
seconds", e.g.
$ pgbench -T 3600 -A 10 -l db
which will produce log with 10-second summaries, containing interval start
timestamp, number of transactions, sum of latencies, sum of 2nd power of
latencies, min and max latency (it's done this way to allow handling of
multiple logs produced by "-j" option).
This patch is a bit less polished (and more complex) than the other
pgbench patch I've sent a while back, and I'm not sure how to handle the
Windows branch. That needs to be fixed during the commit fest.
kind regards
Tomas
Attachments:
pgbench-aggregated.difftext/plain; name=pgbench-aggregated.diffDownload
diff --git a/contrib/pgbench/pgbench.c b/contrib/pgbench/pgbench.c
index 00cab73..9fede3c 100644
--- a/contrib/pgbench/pgbench.c
+++ b/contrib/pgbench/pgbench.c
@@ -145,6 +145,8 @@ char *index_tablespace = NULL;
#define naccounts 100000
bool use_log; /* log transaction latencies to a file */
+bool use_log_agg; /* log aggregates instead of individual transactions */
+int naggseconds = 1; /* number of seconds for aggregation */
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 */
@@ -240,6 +242,18 @@ typedef struct
char *argv[MAX_ARGS]; /* command word list */
} Command;
+typedef struct
+{
+
+ long start_time; /* when does the interval start */
+ int cnt; /* number of transactions */
+ double min_duration; /* min/max durations */
+ double max_duration;
+ double sum; /* sum(duration), sum(duration^2) - for estimates */
+ double sum2;
+
+} AggVals;
+
static Command **sql_files[MAX_FILES]; /* SQL script files */
static int num_files; /* number of script files */
static int num_commands = 0; /* total number of Command structs */
@@ -364,6 +378,7 @@ usage(void)
" -f FILENAME read transaction script from FILENAME\n"
" -j NUM number of threads (default: 1)\n"
" -l write transaction times to log file\n"
+ " -A NUM write aggregates (over NUM seconds) instead\n"
" -M simple|extended|prepared\n"
" protocol for submitting queries to server (default: simple)\n"
" -n do not run VACUUM before tests\n"
@@ -817,9 +832,22 @@ clientDone(CState *st, bool ok)
return false; /* always false */
}
+static
+void agg_vals_init(AggVals * aggs, instr_time start)
+{
+ aggs->cnt = 0;
+ aggs->sum = 0;
+ aggs->sum2 = 0;
+
+ aggs->min_duration = 3600 * 1000000.0; /* one hour */
+ aggs->max_duration = 0;
+
+ aggs->start_time = INSTR_TIME_GET_DOUBLE(start);
+}
+
/* return false iff client should be disconnected */
static bool
-doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile)
+doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVals * agg)
{
PGresult *res;
Command **commands;
@@ -881,17 +909,65 @@ top:
diff = now;
INSTR_TIME_SUBTRACT(diff, st->txn_begin);
usec = (double) INSTR_TIME_GET_MICROSEC(diff);
-
+
+ /* should we aggregate the results or not? */
+ if (use_log_agg) {
+
+ /* are we still in the same interval? if yes, accumulate the
+ * values (print them otherwise) */
+ if (agg->start_time + naggseconds >= INSTR_TIME_GET_DOUBLE(now)) {
+
+ /* accumulate */
+ agg->cnt += 1;
+
+ agg->min_duration = (usec < agg->min_duration) ? usec : agg->min_duration;
+ agg->max_duration = (usec > agg->max_duration) ? usec : agg->max_duration;
+
+ agg->sum += usec;
+ agg->sum2 += usec * usec;
+
+ } else {
+
+ /* print */
#ifndef WIN32
- /* This is more than we really ought to know about instr_time */
- fprintf(logfile, "%d %d %.0f %d %ld %ld\n",
- st->id, st->cnt, usec, st->use_file,
- (long) now.tv_sec, (long) now.tv_usec);
+ /* This is more than we really ought to know about instr_time */
+ fprintf(logfile, "%ld %d %.0f %.0f %.0f %.0f\n",
+ agg->start_time, agg->cnt, agg->sum, agg->sum2,
+ agg->min_duration, agg->max_duration);
#else
- /* On Windows, instr_time doesn't provide a timestamp anyway */
- fprintf(logfile, "%d %d %.0f %d 0 0\n",
- st->id, st->cnt, usec, st->use_file);
+ /* On Windows, instr_time doesn't provide a timestamp anyway */
+ // FIXME
+// fprintf(logfile, "%d %ld %.0f %d 0 0\n",
+// st->id, aggvals.start_time, aggvals.cnt, usec, st->use_file);
#endif
+ /* and now reset the values (include the current) */
+ agg->cnt = 1;
+ agg->min_duration = usec;
+ agg->max_duration = usec;
+
+ agg->sum = usec;
+ agg->sum2 = usec * usec;
+
+ /* move to the next interval (there may be transactions longer than
+ * the desired interval */
+ while (agg->start_time + naggseconds < INSTR_TIME_GET_DOUBLE(now)) {
+ agg->start_time = agg->start_time + naggseconds;
+ }
+ }
+
+ } else {
+ /* no, print raw transactions */
+#ifndef WIN32
+ /* This is more than we really ought to know about instr_time */
+ fprintf(logfile, "%d %d %.0f %d %ld %ld\n",
+ st->id, st->cnt, usec, st->use_file,
+ (long) now.tv_sec, (long) now.tv_usec);
+#else
+ /* On Windows, instr_time doesn't provide a timestamp anyway */
+ fprintf(logfile, "%d %d %.0f %d 0 0\n",
+ st->id, st->cnt, usec, st->use_file);
+#endif
+ }
}
if (commands[st->state]->type == SQL_COMMAND)
@@ -1962,7 +2038,7 @@ main(int argc, char **argv)
state = (CState *) xmalloc(sizeof(CState));
memset(state, 0, sizeof(CState));
- while ((c = getopt_long(argc, argv, "ih:nvp:dSNc:j:Crs:t:T:U:lf:D:F:M:", long_options, &optindex)) != -1)
+ while ((c = getopt_long(argc, argv, "ih:nvp:dSNc:j:Crs:t:T:U:lf:A:D:F:M:", long_options, &optindex)) != -1)
{
switch (c)
{
@@ -2070,6 +2146,15 @@ main(int argc, char **argv)
case 'l':
use_log = true;
break;
+ case 'A':
+ use_log_agg = true;
+ naggseconds = atoi(optarg);
+ if (naggseconds <= 0)
+ {
+ fprintf(stderr, "invalid number of seconds for aggregation: %d\n", naggseconds);
+ exit(1);
+ }
+ break;
case 'f':
ttype = 3;
filename = optarg;
@@ -2158,6 +2243,11 @@ main(int argc, char **argv)
exit(1);
}
+ if (naggseconds > duration) {
+ fprintf(stderr, "number of seconds for aggregation (%d) must not be higher that test duration (%d)\n", naggseconds, duration);
+ exit(1);
+ }
+
/*
* is_latencies only works with multiple threads in thread-based
* implementations, not fork-based ones, because it supposes that the
@@ -2416,7 +2506,9 @@ threadRun(void *arg)
int nstate = thread->nstate;
int remains = nstate; /* number of remaining clients */
int i;
-
+
+ AggVals aggs;
+
result = xmalloc(sizeof(TResult));
INSTR_TIME_SET_ZERO(result->conn_time);
@@ -2452,6 +2544,8 @@ threadRun(void *arg)
INSTR_TIME_SET_CURRENT(result->conn_time);
INSTR_TIME_SUBTRACT(result->conn_time, thread->start_time);
+ agg_vals_init(&aggs, thread->start_time);
+
/* send start up queries in async manner */
for (i = 0; i < nstate; i++)
{
@@ -2460,7 +2554,7 @@ threadRun(void *arg)
int prev_ecnt = st->ecnt;
st->use_file = getrand(thread, 0, num_files - 1);
- if (!doCustom(thread, st, &result->conn_time, logfile))
+ if (!doCustom(thread, st, &result->conn_time, logfile, &aggs))
remains--; /* I've aborted */
if (st->ecnt > prev_ecnt && commands[st->state]->type == META_COMMAND)
@@ -2562,7 +2656,7 @@ threadRun(void *arg)
if (st->con && (FD_ISSET(PQsocket(st->con), &input_mask)
|| commands[st->state]->type == META_COMMAND))
{
- if (!doCustom(thread, st, &result->conn_time, logfile))
+ if (!doCustom(thread, st, &result->conn_time, logfile, &aggs))
remains--; /* I've aborted */
}
@@ -2589,7 +2683,6 @@ done:
return result;
}
-
/*
* Support for duration option: set timer_exceeded after so many seconds.
*/
@@ -2783,4 +2876,4 @@ pthread_join(pthread_t th, void **thread_return)
return 0;
}
-#endif /* WIN32 */
+#endif /* WIN32 */
\ No newline at end of file
diff --git a/doc/src/sgml/pgbench.sgml b/doc/src/sgml/pgbench.sgml
index 437fcea..8929b96 100644
--- a/doc/src/sgml/pgbench.sgml
+++ b/doc/src/sgml/pgbench.sgml
@@ -317,6 +317,18 @@ pgbench <optional> <replaceable>options</> </optional> <replaceable>dbname</>
</varlistentry>
<varlistentry>
+ <term><option>-A</option> <replaceable>seconds</></term>
+ <listitem>
+ <para>
+ Length of aggregation interval (in seconds). May be used only together
+ with <application>-l</application> - with this option, the log contains
+ per-interval summary (number of transactions, min/max latency and two
+ additional fields useful for variance estimation). Default is 1.
+ </para>
+ </listitem>
+ </varlistentry>
+
+ <varlistentry>
<term><option>-M</option> <replaceable>querymode</></term>
<listitem>
<para>
@@ -712,8 +724,9 @@ END;
<title>Per-Transaction Logging</title>
<para>
- With the <option>-l</> option, <application>pgbench</> writes the time
- taken by each transaction to a log file. The log file will be named
+ With the <option>-l</> option, and without the <option>-A</option>,
+ <application>pgbench</> writes the time taken by each transaction
+ to a log file. The log file will be named
<filename>pgbench_log.<replaceable>nnn</></filename>, where
<replaceable>nnn</> is the PID of the pgbench process.
If the <option>-j</> option is 2 or higher, creating multiple worker
@@ -750,6 +763,37 @@ END;
0 201 2513 0 1175850569 608
0 202 2038 0 1175850569 2663
</screen></para>
+
+ <title>Aggregated Logging</title>
+
+ <para>
+ With the <option>-A</option> option, the logs use a bit different format:
+
+<synopsis>
+<replaceable>interval_start</> <replaceable>num_of_transactions</> <replaceable>latency_sum</> <replaceable>latency_2_sum</> <replaceable>min_latency</> <replaceable>max_latency</>
+</synopsis>
+
+ where <replaceable>interval_start</> is the start of the interval (UNIX epoch
+ format timestamp), <replaceable>num_of_transactions</> is the number of transactions
+ within the interval, <replaceable>latency_sum</replaceable> is a sum of latencies
+ (so you can compute average latency easily). The following two fields are useful
+ for variance estimation - <replaceable>latency_sum</> is a sum of latencies and
+ <replaceable>latency_2_sum</> is a sum of 2nd powers of latencies. The last two
+ fields are <replaceable>min_latency</> - a minimum latency within the interval, and
+ <replaceable>max_latency</> - maximum latency within the interval. A transaction is
+ counted into the interval when it was committed.
+ </para>
+
+ <para>
+ Here is example outputs:
+<screen>
+1345828501 5601 1542744 483552416 61 2573
+1345828503 7884 1979812 565806736 60 1479
+1345828505 7208 1979422 567277552 59 1391
+1345828507 7685 1980268 569784714 60 1398
+1345828509 7073 1979779 573489941 236 1411
+</screen></para>
+
</refsect2>
<refsect2>On 24 Srpen 2012, 23:25, Tomas Vondra wrote:
Hi,
this patch adds support for aggregation of info written into the log.
Instead of info about each transaction, a summary for time intervals (with
custom length) is written into the log. All you need to do is add "-A
seconds", e.g.$ pgbench -T 3600 -A 10 -l db
which will produce log with 10-second summaries, containing interval start
timestamp, number of transactions, sum of latencies, sum of 2nd power of
latencies, min and max latency (it's done this way to allow handling of
multiple logs produced by "-j" option).
I've forgot to mention that just like the other patch, this is meant for
cases when you really don't need the raw per-transaction info, but
per-second summary is just enough. This is helpful especially when the
test produces a lot of transaction, thus huge log files etc.
So you can either log all the transactions and then post-process the huge
files, or completely skip that and just log the summaries.
Tomas
On Fri, Aug 24, 2012 at 5:25 PM, Tomas Vondra <tv@fuzzy.cz> wrote:
This patch is a bit less polished (and more complex) than the other
pgbench patch I've sent a while back, and I'm not sure how to handle the
Windows branch. That needs to be fixed during the commit fest.
What's the problem with the Windows branch?
Could you un-cuddle your brances to follow the PostgreSQL style, omit
braces around single-statement blocks, and remove the spurious
whitespace changes?
Instead of having both use_log_agg and naggseconds, I think you can
get by with just having a single variable that is zero if aggregation
is not in use and is otherwise the aggregation period. On a related
note, you can't specify -A without an associated value, so there is no
point in documenting a "default". As with your other patch, I suggest
using a long option name like --latency-aggregate-interval and then
making the name of the variable in the code match the option name,
with s/-/_/g, for clarity.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
On 30 Srpen 2012, 18:02, Robert Haas wrote:
On Fri, Aug 24, 2012 at 5:25 PM, Tomas Vondra <tv@fuzzy.cz> wrote:
This patch is a bit less polished (and more complex) than the other
pgbench patch I've sent a while back, and I'm not sure how to handle the
Windows branch. That needs to be fixed during the commit fest.What's the problem with the Windows branch?
Well, there are comments about how timestamp does not work on Windows
(filling 0), and I'm not sure how that affects the patch (e.g. determining
the aggregation interval). I have no Windows workstation available so I
can't actually try that.
Could you un-cuddle your brances to follow the PostgreSQL style, omit
braces around single-statement blocks, and remove the spurious
whitespace changes?
OK, will do.
Instead of having both use_log_agg and naggseconds, I think you can
get by with just having a single variable that is zero if aggregation
is not in use and is otherwise the aggregation period. On a related
note, you can't specify -A without an associated value, so there is no
point in documenting a "default". As with your other patch, I suggest
using a long option name like --latency-aggregate-interval and then
making the name of the variable in the code match the option name,
with s/-/_/g, for clarity.
Why --latency-aggregate-interval? It has nothing to do with latencies,
it's merely number of transactions per interval.
Tomas
On Thu, Aug 30, 2012 at 3:25 PM, Tomas Vondra <tv@fuzzy.cz> wrote:
On 30 Srpen 2012, 18:02, Robert Haas wrote:
On Fri, Aug 24, 2012 at 5:25 PM, Tomas Vondra <tv@fuzzy.cz> wrote:
This patch is a bit less polished (and more complex) than the other
pgbench patch I've sent a while back, and I'm not sure how to handle the
Windows branch. That needs to be fixed during the commit fest.What's the problem with the Windows branch?
Well, there are comments about how timestamp does not work on Windows
(filling 0), and I'm not sure how that affects the patch (e.g. determining
the aggregation interval). I have no Windows workstation available so I
can't actually try that.
Hmm. That seems like it might be something we need to fix first...
Could you un-cuddle your brances to follow the PostgreSQL style, omit
braces around single-statement blocks, and remove the spurious
whitespace changes?OK, will do.
Instead of having both use_log_agg and naggseconds, I think you can
get by with just having a single variable that is zero if aggregation
is not in use and is otherwise the aggregation period. On a related
note, you can't specify -A without an associated value, so there is no
point in documenting a "default". As with your other patch, I suggest
using a long option name like --latency-aggregate-interval and then
making the name of the variable in the code match the option name,
with s/-/_/g, for clarity.Why --latency-aggregate-interval? It has nothing to do with latencies,
it's merely number of transactions per interval.
Oh, I thought it was modifying the behavior of -l.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
On 30 Srpen 2012, 23:47, Robert Haas wrote:
On Thu, Aug 30, 2012 at 3:25 PM, Tomas Vondra <tv@fuzzy.cz> wrote:
On 30 Srpen 2012, 18:02, Robert Haas wrote:
On Fri, Aug 24, 2012 at 5:25 PM, Tomas Vondra <tv@fuzzy.cz> wrote:
This patch is a bit less polished (and more complex) than the other
pgbench patch I've sent a while back, and I'm not sure how to handle
the
Windows branch. That needs to be fixed during the commit fest.What's the problem with the Windows branch?
Well, there are comments about how timestamp does not work on Windows
(filling 0), and I'm not sure how that affects the patch (e.g.
determining
the aggregation interval). I have no Windows workstation available so I
can't actually try that.Hmm. That seems like it might be something we need to fix first...
Could you un-cuddle your brances to follow the PostgreSQL style, omit
braces around single-statement blocks, and remove the spurious
whitespace changes?OK, will do.
Instead of having both use_log_agg and naggseconds, I think you can
get by with just having a single variable that is zero if aggregation
is not in use and is otherwise the aggregation period. On a related
note, you can't specify -A without an associated value, so there is no
point in documenting a "default". As with your other patch, I suggest
using a long option name like --latency-aggregate-interval and then
making the name of the variable in the code match the option name,
with s/-/_/g, for clarity.Why --latency-aggregate-interval? It has nothing to do with latencies,
it's merely number of transactions per interval.Oh, I thought it was modifying the behavior of -l.
It does, but AFAIK the "-l" means logging. I suppose
"--aggregate-interval" would be a good option name, I don't see a reason
to put there the additional word when there are other aggregated values
(e.g. num of transactions).
T.
On Thu, Aug 30, 2012 at 5:55 PM, Tomas Vondra <tv@fuzzy.cz> wrote:
It does, but AFAIK the "-l" means logging. I suppose
"--aggregate-interval" would be a good option name, I don't see a reason
to put there the additional word when there are other aggregated values
(e.g. num of transactions).
Oh, I was thinking that the l was for latency, but maybe not.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
Dne 30.08.2012 18:02, Robert Haas napsal:
On Fri, Aug 24, 2012 at 5:25 PM, Tomas Vondra <tv@fuzzy.cz> wrote:
This patch is a bit less polished (and more complex) than the other
pgbench patch I've sent a while back, and I'm not sure how to handle
the
Windows branch. That needs to be fixed during the commit fest.What's the problem with the Windows branch?
Could you un-cuddle your brances to follow the PostgreSQL style, omit
braces around single-statement blocks, and remove the spurious
whitespace changes?
Done, or at least I don't see other formatting issues. Let me know if I
missed something.
Instead of having both use_log_agg and naggseconds, I think you can
get by with just having a single variable that is zero if aggregation
is not in use and is otherwise the aggregation period. On a related
note, you can't specify -A without an associated value, so there is
no
point in documenting a "default". As with your other patch, I
suggest
using a long option name like --latency-aggregate-interval and then
making the name of the variable in the code match the option name,
with s/-/_/g, for clarity.
Fixed. I've kept use_log_agg only and I've removed the default. Also
I've added one more check (that the total duration is a multiple of
the aggregation interval).
And just as with the sampling patch, I believe the "-l" should not be
enabled by default, but required. But if more people ask to enable it
whenever the aggregation or sampling is used, I'm fine with it.
Tomas
Attachments:
pgbench-aggregated-v2.difftext/plain; name=pgbench-aggregated-v2.diffDownload
diff --git a/contrib/pgbench/pgbench.c b/contrib/pgbench/pgbench.c
index 00cab73..e044564 100644
--- a/contrib/pgbench/pgbench.c
+++ b/contrib/pgbench/pgbench.c
@@ -145,6 +145,7 @@ char *index_tablespace = NULL;
#define naccounts 100000
bool use_log; /* log transaction latencies to a file */
+int use_log_agg; /* log aggregates instead of individual transactions */
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 */
@@ -240,6 +241,18 @@ typedef struct
char *argv[MAX_ARGS]; /* command word list */
} Command;
+typedef struct
+{
+
+ long start_time; /* when does the interval start */
+ int cnt; /* number of transactions */
+ double min_duration; /* min/max durations */
+ double max_duration;
+ double sum; /* sum(duration), sum(duration^2) - for estimates */
+ double sum2;
+
+} AggVals;
+
static Command **sql_files[MAX_FILES]; /* SQL script files */
static int num_files; /* number of script files */
static int num_commands = 0; /* total number of Command structs */
@@ -364,6 +377,8 @@ usage(void)
" -f FILENAME read transaction script from FILENAME\n"
" -j NUM number of threads (default: 1)\n"
" -l write transaction times to log file\n"
+ " --aggregate-interval NUM\n"
+ " aggregate data over NUM seconds\n"
" -M simple|extended|prepared\n"
" protocol for submitting queries to server (default: simple)\n"
" -n do not run VACUUM before tests\n"
@@ -817,9 +832,22 @@ clientDone(CState *st, bool ok)
return false; /* always false */
}
+static
+void agg_vals_init(AggVals * aggs, instr_time start)
+{
+ aggs->cnt = 0;
+ aggs->sum = 0;
+ aggs->sum2 = 0;
+
+ aggs->min_duration = 3600 * 1000000.0; /* one hour */
+ aggs->max_duration = 0;
+
+ aggs->start_time = INSTR_TIME_GET_DOUBLE(start);
+}
+
/* return false iff client should be disconnected */
static bool
-doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile)
+doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVals * agg)
{
PGresult *res;
Command **commands;
@@ -881,17 +909,70 @@ top:
diff = now;
INSTR_TIME_SUBTRACT(diff, st->txn_begin);
usec = (double) INSTR_TIME_GET_MICROSEC(diff);
-
+
+ /* should we aggregate the results or not? */
+ if (use_log_agg)
+ {
+
+ /* are we still in the same interval? if yes, accumulate the
+ * values (print them otherwise) */
+ if (agg->start_time + use_log_agg >= INSTR_TIME_GET_DOUBLE(now))
+ {
+
+ /* accumulate */
+ agg->cnt += 1;
+
+ agg->min_duration = (usec < agg->min_duration) ? usec : agg->min_duration;
+ agg->max_duration = (usec > agg->max_duration) ? usec : agg->max_duration;
+
+ agg->sum += usec;
+ agg->sum2 += usec * usec;
+
+ }
+ else
+ {
+
+ /* print */
+#ifndef WIN32
+ /* This is more than we really ought to know about instr_time */
+ fprintf(logfile, "%ld %d %.0f %.0f %.0f %.0f\n",
+ agg->start_time, agg->cnt, agg->sum, agg->sum2,
+ agg->min_duration, agg->max_duration);
+#else
+ /* On Windows, instr_time doesn't provide a timestamp anyway */
+ // FIXME
+// fprintf(logfile, "%d %ld %.0f %d 0 0\n",
+// st->id, aggvals.start_time, aggvals.cnt, usec, st->use_file);
+#endif
+ /* and now reset the values (include the current) */
+ agg->cnt = 1;
+ agg->min_duration = usec;
+ agg->max_duration = usec;
+
+ agg->sum = usec;
+ agg->sum2 = usec * usec;
+
+ /* move to the next interval (there may be transactions longer than
+ * the desired interval */
+ while (agg->start_time + use_log_agg < INSTR_TIME_GET_DOUBLE(now))
+ agg->start_time = agg->start_time + use_log_agg;
+ }
+
+ }
+ else
+ {
+ /* no, print raw transactions */
#ifndef WIN32
- /* This is more than we really ought to know about instr_time */
- fprintf(logfile, "%d %d %.0f %d %ld %ld\n",
- st->id, st->cnt, usec, st->use_file,
- (long) now.tv_sec, (long) now.tv_usec);
+ /* This is more than we really ought to know about instr_time */
+ fprintf(logfile, "%d %d %.0f %d %ld %ld\n",
+ st->id, st->cnt, usec, st->use_file,
+ (long) now.tv_sec, (long) now.tv_usec);
#else
- /* On Windows, instr_time doesn't provide a timestamp anyway */
- fprintf(logfile, "%d %d %.0f %d 0 0\n",
- st->id, st->cnt, usec, st->use_file);
+ /* On Windows, instr_time doesn't provide a timestamp anyway */
+ fprintf(logfile, "%d %d %.0f %d 0 0\n",
+ st->id, st->cnt, usec, st->use_file);
#endif
+ }
}
if (commands[st->state]->type == SQL_COMMAND)
@@ -1918,6 +1999,7 @@ main(int argc, char **argv)
{"index-tablespace", required_argument, NULL, 3},
{"tablespace", required_argument, NULL, 2},
{"unlogged-tables", no_argument, &unlogged_tables, 1},
+ {"aggregate-interval", required_argument, NULL, 5},
{NULL, 0, NULL, 0}
};
@@ -2123,6 +2205,14 @@ main(int argc, char **argv)
case 3: /* index-tablespace */
index_tablespace = optarg;
break;
+ case 5:
+ use_log_agg = atoi(optarg);
+ if (use_log_agg <= 0)
+ {
+ fprintf(stderr, "invalid number of seconds for aggregation: %d\n", use_log_agg);
+ exit(1);
+ }
+ break;
default:
fprintf(stderr, _("Try \"%s --help\" for more information.\n"), progname);
exit(1);
@@ -2158,6 +2248,21 @@ main(int argc, char **argv)
exit(1);
}
+ if (use_log_agg > 0 && (! use_log)) {
+ fprintf(stderr, "log aggregation is allowed only when actually logging transactions\n");
+ exit(1);
+ }
+
+ if ((duration > 0) && (use_log_agg > duration)) {
+ fprintf(stderr, "number of seconds for aggregation (%d) must not be higher that test duration (%d)\n", use_log_agg, duration);
+ exit(1);
+ }
+
+ if ((duration > 0) && (use_log_agg > 0) && (duration % use_log_agg != 0)) {
+ fprintf(stderr, "duration (%d) must be a multiple of aggregation interval (%d)\n", duration, use_log_agg);
+ exit(1);
+ }
+
/*
* is_latencies only works with multiple threads in thread-based
* implementations, not fork-based ones, because it supposes that the
@@ -2416,7 +2521,9 @@ threadRun(void *arg)
int nstate = thread->nstate;
int remains = nstate; /* number of remaining clients */
int i;
-
+
+ AggVals aggs;
+
result = xmalloc(sizeof(TResult));
INSTR_TIME_SET_ZERO(result->conn_time);
@@ -2452,6 +2559,8 @@ threadRun(void *arg)
INSTR_TIME_SET_CURRENT(result->conn_time);
INSTR_TIME_SUBTRACT(result->conn_time, thread->start_time);
+ agg_vals_init(&aggs, thread->start_time);
+
/* send start up queries in async manner */
for (i = 0; i < nstate; i++)
{
@@ -2460,7 +2569,7 @@ threadRun(void *arg)
int prev_ecnt = st->ecnt;
st->use_file = getrand(thread, 0, num_files - 1);
- if (!doCustom(thread, st, &result->conn_time, logfile))
+ if (!doCustom(thread, st, &result->conn_time, logfile, &aggs))
remains--; /* I've aborted */
if (st->ecnt > prev_ecnt && commands[st->state]->type == META_COMMAND)
@@ -2562,7 +2671,7 @@ threadRun(void *arg)
if (st->con && (FD_ISSET(PQsocket(st->con), &input_mask)
|| commands[st->state]->type == META_COMMAND))
{
- if (!doCustom(thread, st, &result->conn_time, logfile))
+ if (!doCustom(thread, st, &result->conn_time, logfile, &aggs))
remains--; /* I've aborted */
}
@@ -2589,7 +2698,6 @@ done:
return result;
}
-
/*
* Support for duration option: set timer_exceeded after so many seconds.
*/
@@ -2783,4 +2891,4 @@ pthread_join(pthread_t th, void **thread_return)
return 0;
}
-#endif /* WIN32 */
+#endif /* WIN32 */
\ No newline at end of file
diff --git a/doc/src/sgml/pgbench.sgml b/doc/src/sgml/pgbench.sgml
index 437fcea..47fa3ec 100644
--- a/doc/src/sgml/pgbench.sgml
+++ b/doc/src/sgml/pgbench.sgml
@@ -317,6 +317,18 @@ pgbench <optional> <replaceable>options</> </optional> <replaceable>dbname</>
</varlistentry>
<varlistentry>
+ <term><option>--aggregate-interval</option> <replaceable>seconds</></term>
+ <listitem>
+ <para>
+ Length of aggregation interval (in seconds). May be used only together
+ with <application>-l</application> - with this option, the log contains
+ per-interval summary (number of transactions, min/max latency and two
+ additional fields useful for variance estimation).
+ </para>
+ </listitem>
+ </varlistentry>
+
+ <varlistentry>
<term><option>-M</option> <replaceable>querymode</></term>
<listitem>
<para>
@@ -712,8 +724,9 @@ END;
<title>Per-Transaction Logging</title>
<para>
- With the <option>-l</> option, <application>pgbench</> writes the time
- taken by each transaction to a log file. The log file will be named
+ With the <option>-l</> option, and without the <option>-A</option>,
+ <application>pgbench</> writes the time taken by each transaction
+ to a log file. The log file will be named
<filename>pgbench_log.<replaceable>nnn</></filename>, where
<replaceable>nnn</> is the PID of the pgbench process.
If the <option>-j</> option is 2 or higher, creating multiple worker
@@ -750,6 +763,37 @@ END;
0 201 2513 0 1175850569 608
0 202 2038 0 1175850569 2663
</screen></para>
+
+ <title>Aggregated Logging</title>
+
+ <para>
+ With the <option>-A</option> option, the logs use a bit different format:
+
+<synopsis>
+<replaceable>interval_start</> <replaceable>num_of_transactions</> <replaceable>latency_sum</> <replaceable>latency_2_sum</> <replaceable>min_latency</> <replaceable>max_latency</>
+</synopsis>
+
+ where <replaceable>interval_start</> is the start of the interval (UNIX epoch
+ format timestamp), <replaceable>num_of_transactions</> is the number of transactions
+ within the interval, <replaceable>latency_sum</replaceable> is a sum of latencies
+ (so you can compute average latency easily). The following two fields are useful
+ for variance estimation - <replaceable>latency_sum</> is a sum of latencies and
+ <replaceable>latency_2_sum</> is a sum of 2nd powers of latencies. The last two
+ fields are <replaceable>min_latency</> - a minimum latency within the interval, and
+ <replaceable>max_latency</> - maximum latency within the interval. A transaction is
+ counted into the interval when it was committed.
+ </para>
+
+ <para>
+ Here is example outputs:
+<screen>
+1345828501 5601 1542744 483552416 61 2573
+1345828503 7884 1979812 565806736 60 1479
+1345828505 7208 1979422 567277552 59 1391
+1345828507 7685 1980268 569784714 60 1398
+1345828509 7073 1979779 573489941 236 1411
+</screen></para>
+
</refsect2>
<refsect2>
On Sun, Sep 2, 2012 at 3:46 PM, Tomas Vondra <tv@fuzzy.cz> wrote:
Fixed. I've kept use_log_agg only and I've removed the default. Also
I've added one more check (that the total duration is a multiple of
the aggregation interval).
Hi Tomas,
In the docs, -l is an option, not an application:
"<application>-l</application>"
Also, the docs still refer to <option>-A</option>, rather than to
<option>--aggregate-interval</option>, in a few places.
I think a section in the docs that points out that transactions run by
specifying mulitple -f will be mingled together into an interval would
be a good idea, as that could easily be overlooked (as I did earlier).
The docs do not mention anywhere what the units for the latencies are.
I think the format of the logfile should somehow make it unmistakably
different from the regular -l logfile, for example by prefixing every
line with "Aggregate: ". Or maybe there is some other solution, but
I think that having two log formats, both of which consist of nothing
but 6 integers, but yet mean very different things, is a recipe for
confusion.
Is it unavoidable that the interval be an integral number of seconds?
I found the units in the original code confusing, so maybe there is
some reason it needs to be like that that I don't understand yet.
I'll look into it some more.
Thanks,
Jeff
On 3.9.2012 01:28, Jeff Janes wrote:
On Sun, Sep 2, 2012 at 3:46 PM, Tomas Vondra <tv@fuzzy.cz> wrote:
Fixed. I've kept use_log_agg only and I've removed the default. Also
I've added one more check (that the total duration is a multiple of
the aggregation interval).Hi Tomas,
In the docs, -l is an option, not an application:
"<application>-l</application>"Also, the docs still refer to <option>-A</option>, rather than to
<option>--aggregate-interval</option>, in a few places.
Fixed.
I think a section in the docs that points out that transactions run by
specifying mulitple -f will be mingled together into an interval would
be a good idea, as that could easily be overlooked (as I did earlier).
Fixed, added a paragraph mentioning this.
The docs do not mention anywhere what the units for the latencies are.
I think the format of the logfile should somehow make it unmistakably
different from the regular -l logfile, for example by prefixing every
line with "Aggregate: ". Or maybe there is some other solution, but
I think that having two log formats, both of which consist of nothing
but 6 integers, but yet mean very different things, is a recipe for
confusion.
Not sure how to do that, I'd say it's a responsibility of the user.
Is it unavoidable that the interval be an integral number of seconds?
I found the units in the original code confusing, so maybe there is
some reason it needs to be like that that I don't understand yet.
I'll look into it some more.
Not really, but I don't see a real use case for such intervals, so I'm
keeping the integers for now.
Also, I've realized the last interval may not be logged at all - I'll
take a look into this in the next version of the patch.
Tomas
Attachments:
pgbench-aggregated-v3.difftext/plain; charset=UTF-8; name=pgbench-aggregated-v3.diffDownload
diff --git a/contrib/pgbench/pgbench.c b/contrib/pgbench/pgbench.c
index f5ac3b1..19c3b18 100644
--- a/contrib/pgbench/pgbench.c
+++ b/contrib/pgbench/pgbench.c
@@ -145,6 +145,7 @@ char *index_tablespace = NULL;
#define naccounts 100000
bool use_log; /* log transaction latencies to a file */
+int use_log_agg; /* log aggregates instead of individual transactions */
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 */
@@ -240,6 +241,18 @@ typedef struct
char *argv[MAX_ARGS]; /* command word list */
} Command;
+typedef struct
+{
+
+ long start_time; /* when does the interval start */
+ int cnt; /* number of transactions */
+ double min_duration; /* min/max durations */
+ double max_duration;
+ double sum; /* sum(duration), sum(duration^2) - for estimates */
+ double sum2;
+
+} AggVals;
+
static Command **sql_files[MAX_FILES]; /* SQL script files */
static int num_files; /* number of script files */
static int num_commands = 0; /* total number of Command structs */
@@ -364,6 +377,8 @@ usage(void)
" -f FILENAME read transaction script from FILENAME\n"
" -j NUM number of threads (default: 1)\n"
" -l write transaction times to log file\n"
+ " --aggregate-interval NUM\n"
+ " aggregate data over NUM seconds\n"
" -M simple|extended|prepared\n"
" protocol for submitting queries to server (default: simple)\n"
" -n do not run VACUUM before tests\n"
@@ -817,9 +832,22 @@ clientDone(CState *st, bool ok)
return false; /* always false */
}
+static
+void agg_vals_init(AggVals * aggs, instr_time start)
+{
+ aggs->cnt = 0;
+ aggs->sum = 0;
+ aggs->sum2 = 0;
+
+ aggs->min_duration = 3600 * 1000000.0; /* one hour */
+ aggs->max_duration = 0;
+
+ aggs->start_time = INSTR_TIME_GET_DOUBLE(start);
+}
+
/* return false iff client should be disconnected */
static bool
-doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile)
+doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVals * agg)
{
PGresult *res;
Command **commands;
@@ -881,17 +909,70 @@ top:
diff = now;
INSTR_TIME_SUBTRACT(diff, st->txn_begin);
usec = (double) INSTR_TIME_GET_MICROSEC(diff);
-
+
+ /* should we aggregate the results or not? */
+ if (use_log_agg)
+ {
+
+ /* are we still in the same interval? if yes, accumulate the
+ * values (print them otherwise) */
+ if (agg->start_time + use_log_agg >= INSTR_TIME_GET_DOUBLE(now))
+ {
+
+ /* accumulate */
+ agg->cnt += 1;
+
+ agg->min_duration = (usec < agg->min_duration) ? usec : agg->min_duration;
+ agg->max_duration = (usec > agg->max_duration) ? usec : agg->max_duration;
+
+ agg->sum += usec;
+ agg->sum2 += usec * usec;
+
+ }
+ else
+ {
+
+ /* print */
+#ifndef WIN32
+ /* This is more than we really ought to know about instr_time */
+ fprintf(logfile, "%ld %d %.0f %.0f %.0f %.0f\n",
+ agg->start_time, agg->cnt, agg->sum, agg->sum2,
+ agg->min_duration, agg->max_duration);
+#else
+ /* On Windows, instr_time doesn't provide a timestamp anyway */
+ // FIXME
+// fprintf(logfile, "%d %ld %.0f %d 0 0\n",
+// st->id, aggvals.start_time, aggvals.cnt, usec, st->use_file);
+#endif
+ /* and now reset the values (include the current) */
+ agg->cnt = 1;
+ agg->min_duration = usec;
+ agg->max_duration = usec;
+
+ agg->sum = usec;
+ agg->sum2 = usec * usec;
+
+ /* move to the next interval (there may be transactions longer than
+ * the desired interval */
+ while (agg->start_time + use_log_agg < INSTR_TIME_GET_DOUBLE(now))
+ agg->start_time = agg->start_time + use_log_agg;
+ }
+
+ }
+ else
+ {
+ /* no, print raw transactions */
#ifndef WIN32
- /* This is more than we really ought to know about instr_time */
- fprintf(logfile, "%d %d %.0f %d %ld %ld\n",
- st->id, st->cnt, usec, st->use_file,
- (long) now.tv_sec, (long) now.tv_usec);
+ /* This is more than we really ought to know about instr_time */
+ fprintf(logfile, "%d %d %.0f %d %ld %ld\n",
+ st->id, st->cnt, usec, st->use_file,
+ (long) now.tv_sec, (long) now.tv_usec);
#else
- /* On Windows, instr_time doesn't provide a timestamp anyway */
- fprintf(logfile, "%d %d %.0f %d 0 0\n",
- st->id, st->cnt, usec, st->use_file);
+ /* On Windows, instr_time doesn't provide a timestamp anyway */
+ fprintf(logfile, "%d %d %.0f %d 0 0\n",
+ st->id, st->cnt, usec, st->use_file);
#endif
+ }
}
if (commands[st->state]->type == SQL_COMMAND)
@@ -1920,6 +2001,7 @@ main(int argc, char **argv)
{"index-tablespace", required_argument, NULL, 3},
{"tablespace", required_argument, NULL, 2},
{"unlogged-tables", no_argument, &unlogged_tables, 1},
+ {"aggregate-interval", required_argument, NULL, 5},
{NULL, 0, NULL, 0}
};
@@ -2125,6 +2207,14 @@ main(int argc, char **argv)
case 3: /* index-tablespace */
index_tablespace = optarg;
break;
+ case 5:
+ use_log_agg = atoi(optarg);
+ if (use_log_agg <= 0)
+ {
+ fprintf(stderr, "invalid number of seconds for aggregation: %d\n", use_log_agg);
+ exit(1);
+ }
+ break;
default:
fprintf(stderr, _("Try \"%s --help\" for more information.\n"), progname);
exit(1);
@@ -2160,6 +2250,21 @@ main(int argc, char **argv)
exit(1);
}
+ if (use_log_agg > 0 && (! use_log)) {
+ fprintf(stderr, "log aggregation is allowed only when actually logging transactions\n");
+ exit(1);
+ }
+
+ if ((duration > 0) && (use_log_agg > duration)) {
+ fprintf(stderr, "number of seconds for aggregation (%d) must not be higher that test duration (%d)\n", use_log_agg, duration);
+ exit(1);
+ }
+
+ if ((duration > 0) && (use_log_agg > 0) && (duration % use_log_agg != 0)) {
+ fprintf(stderr, "duration (%d) must be a multiple of aggregation interval (%d)\n", duration, use_log_agg);
+ exit(1);
+ }
+
/*
* is_latencies only works with multiple threads in thread-based
* implementations, not fork-based ones, because it supposes that the
@@ -2418,7 +2523,9 @@ threadRun(void *arg)
int nstate = thread->nstate;
int remains = nstate; /* number of remaining clients */
int i;
-
+
+ AggVals aggs;
+
result = xmalloc(sizeof(TResult));
INSTR_TIME_SET_ZERO(result->conn_time);
@@ -2454,6 +2561,8 @@ threadRun(void *arg)
INSTR_TIME_SET_CURRENT(result->conn_time);
INSTR_TIME_SUBTRACT(result->conn_time, thread->start_time);
+ agg_vals_init(&aggs, thread->start_time);
+
/* send start up queries in async manner */
for (i = 0; i < nstate; i++)
{
@@ -2462,7 +2571,7 @@ threadRun(void *arg)
int prev_ecnt = st->ecnt;
st->use_file = getrand(thread, 0, num_files - 1);
- if (!doCustom(thread, st, &result->conn_time, logfile))
+ if (!doCustom(thread, st, &result->conn_time, logfile, &aggs))
remains--; /* I've aborted */
if (st->ecnt > prev_ecnt && commands[st->state]->type == META_COMMAND)
@@ -2564,7 +2673,7 @@ threadRun(void *arg)
if (st->con && (FD_ISSET(PQsocket(st->con), &input_mask)
|| commands[st->state]->type == META_COMMAND))
{
- if (!doCustom(thread, st, &result->conn_time, logfile))
+ if (!doCustom(thread, st, &result->conn_time, logfile, &aggs))
remains--; /* I've aborted */
}
@@ -2591,7 +2700,6 @@ done:
return result;
}
-
/*
* Support for duration option: set timer_exceeded after so many seconds.
*/
@@ -2785,4 +2893,4 @@ pthread_join(pthread_t th, void **thread_return)
return 0;
}
-#endif /* WIN32 */
+#endif /* WIN32 */
\ No newline at end of file
diff --git a/doc/src/sgml/pgbench.sgml b/doc/src/sgml/pgbench.sgml
index 437fcea..014810b 100644
--- a/doc/src/sgml/pgbench.sgml
+++ b/doc/src/sgml/pgbench.sgml
@@ -317,6 +317,18 @@ pgbench <optional> <replaceable>options</> </optional> <replaceable>dbname</>
</varlistentry>
<varlistentry>
+ <term><option>--aggregate-interval</option> <replaceable>seconds</></term>
+ <listitem>
+ <para>
+ Length of aggregation interval (in seconds). May be used only together
+ with <application>-l</application> - with this option, the log contains
+ per-interval summary (number of transactions, min/max latency and two
+ additional fields useful for variance estimation).
+ </para>
+ </listitem>
+ </varlistentry>
+
+ <varlistentry>
<term><option>-M</option> <replaceable>querymode</></term>
<listitem>
<para>
@@ -712,8 +724,9 @@ END;
<title>Per-Transaction Logging</title>
<para>
- With the <option>-l</> option, <application>pgbench</> writes the time
- taken by each transaction to a log file. The log file will be named
+ With the <option>-l</> option but without the <option>--aggregate-interval</option>,
+ <application>pgbench</> writes the time taken by each transaction
+ to a log file. The log file will be named
<filename>pgbench_log.<replaceable>nnn</></filename>, where
<replaceable>nnn</> is the PID of the pgbench process.
If the <option>-j</> option is 2 or higher, creating multiple worker
@@ -750,6 +763,43 @@ END;
0 201 2513 0 1175850569 608
0 202 2038 0 1175850569 2663
</screen></para>
+
+ <title>Aggregated Logging</title>
+
+ <para>
+ With the <option>--aggregate-interval</option> option, the logs use a bit different format:
+
+<synopsis>
+<replaceable>interval_start</> <replaceable>num_of_transactions</> <replaceable>latency_sum</> <replaceable>latency_2_sum</> <replaceable>min_latency</> <replaceable>max_latency</>
+</synopsis>
+
+ where <replaceable>interval_start</> is the start of the interval (UNIX epoch
+ format timestamp), <replaceable>num_of_transactions</> is the number of transactions
+ within the interval, <replaceable>latency_sum</replaceable> is a sum of latencies
+ (so you can compute average latency easily). The following two fields are useful
+ for variance estimation - <replaceable>latency_sum</> is a sum of latencies and
+ <replaceable>latency_2_sum</> is a sum of 2nd powers of latencies. The last two
+ fields are <replaceable>min_latency</> - a minimum latency within the interval, and
+ <replaceable>max_latency</> - maximum latency within the interval. A transaction is
+ counted into the interval when it was committed.
+ </para>
+
+ <para>
+ Here is example outputs:
+<screen>
+1345828501 5601 1542744 483552416 61 2573
+1345828503 7884 1979812 565806736 60 1479
+1345828505 7208 1979422 567277552 59 1391
+1345828507 7685 1980268 569784714 60 1398
+1345828509 7073 1979779 573489941 236 1411
+</screen></para>
+
+ <para>
+ Notice that while the plain (unaggregated) log file contains index
+ of the custom script files, the aggregated log does not. Therefore if
+ you need per script data, you need to aggregate the data on your own.
+ </para>
+
</refsect2>
<refsect2>
Tomas Vondra wrote:
Also, I've realized the last interval may not be logged at all - I'll
take a look into this in the next version of the patch.
I didn't see any later version of this patch posted anywhere. I guess
it'll have to wait until the next commitfest. Please fix the remaining
issues and resubmit.
Thanks to Robert Haas, Jeff Janes and Pavel Stehule for the reviews.
--
Álvaro Herrera http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services