Hi, attached is a v5 of this patch. Details below:
On 8.12.2012 16:33, Andres Freund wrote: > Hi Tomas, > > On 2012-11-27 14:55:59 +0100, Pavel Stehule wrote: >>> attached is a v4 of the patch. There are not many changes, mostly some >>> simple tidying up, except for handling the Windows. > > After a quick look I am not sure what all the talk about windows is > about? instr_time.h seems to provide all you need, even for windows? The > only issue of gettimeofday() for windows seems to be that it is that its > not all that fast an not too high precision, but that shouldn't be a > problem in this case? > > Could you expand a bit on the problems? As explained in the previous message, this is an existing problem with unavailable timestamp. I'm not very fond of adding Linux-only features, but fixing that was not the goal of this patch. >>>> * I had a problem with doc > > The current patch has conflict markers in the sgml source, there seems > to have been some unresolved merge. Maybe that's all that causes the > errors? > > Whats your problem with setting up the doc toolchain? Yeah, my fault because of incomplete merge. But the real culprit was a missing refsect2. Fixed. > >> issues: >> >> * empty lines with invisible chars (tabs) + and sometimes empty lines >> after and before {} Fixed (I've removed the lines etc.) >> >> * adjustment of start_time >> >> + * the desired interval */ >> + while (agg->start_time >> + agg_interval < INSTR_TIME_GET_DOUBLE(now)) >> + >> agg->start_time = agg->start_time + agg_interval; >> >> can "skip" one interval - so when transaction time will be larger or >> similar to agg_interval - then results can be strange. We have to know >> real length of interval > > Could you post a patch that adresses these issues? So, in the end I've rewritten the section advancing the start_time. Now it works so that when skipping an interval (because of a very long transaction), it will print lines even for those "empty" intervals. So for example with a transaction file containing a single query SELECT pg_sleep(1.5); and an interval length of 1 second, you'll get something like this: 1355009677 0 0 0 0 0 1355009678 1 1501028 2253085056784 1501028 1501028 1355009679 0 0 0 0 0 1355009680 1 1500790 2252370624100 1500790 1500790 1355009681 1 1500723 2252169522729 1500723 1500723 1355009682 0 0 0 0 0 1355009683 1 1500719 2252157516961 1500719 1500719 1355009684 1 1500703 2252109494209 1500703 1500703 1355009685 0 0 0 0 0 which is IMHO the best way to deal with this. I've fixed several minor issues, added a few comments. regards Tomas
diff --git a/contrib/pgbench/pgbench.c b/contrib/pgbench/pgbench.c index e376452..5a03796 100644 --- a/contrib/pgbench/pgbench.c +++ b/contrib/pgbench/pgbench.c @@ -150,6 +150,7 @@ char *index_tablespace = NULL; #define naccounts 100000 bool use_log; /* log transaction latencies to a file */ +int agg_interval; /* 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 */ @@ -245,6 +246,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 */ @@ -377,6 +390,10 @@ usage(void) " -l write transaction times to log file\n" " --sampling-rate NUM\n" " fraction of transactions to log (e.g. 0.01 for 1%% sample)\n" +#ifndef WIN32 + " --aggregate-interval NUM\n" + " aggregate data over NUM seconds\n" +#endif " -M simple|extended|prepared\n" " protocol for submitting queries to server (default: simple)\n" " -n do not run VACUUM before tests\n" @@ -830,9 +847,25 @@ clientDone(CState *st, bool ok) return false; /* always false */ } +static +void agg_vals_init(AggVals * aggs, instr_time start) +{ + /* basic counters */ + aggs->cnt = 0; /* number of transactions */ + aggs->sum = 0; /* SUM(duration) */ + aggs->sum2 = 0; /* SUM(duration*duration) */ + + /* min and max transaction duration */ + aggs->min_duration = 0; + aggs->max_duration = 0; + + /* start of the current interval */ + 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; @@ -897,22 +930,74 @@ top: if (sample_rate == 0.0 || pg_erand48(thread->random_state) <= sample_rate) { - INSTR_TIME_SET_CURRENT(now); diff = now; INSTR_TIME_SUBTRACT(diff, st->txn_begin); usec = (double) INSTR_TIME_GET_MICROSEC(diff); + /* should we aggregate the results or not? */ + if (agg_interval > 0) + { + /* are we still in the same interval? if yes, accumulate the + * values (print them otherwise) */ + if (agg->start_time + agg_interval >= INSTR_TIME_GET_DOUBLE(now)) + { + agg->cnt += 1; + agg->sum += usec; + agg->sum2 += usec * usec; + + /* first in this aggregation interval */ + if ((agg->cnt == 1) || (usec < agg->min_duration)) + agg->min_duration = usec; + + if ((agg->cnt == 1) || (usec > agg->max_duration)) + agg->max_duration = usec; + } + else + { + /* Loop until we reach the interval of the current transaction (and + * print all the empty intervals in between). */ + while (agg->start_time + agg_interval < INSTR_TIME_GET_DOUBLE(now)) + { + /* This is a non-Windows branch (thanks to the ifdef in usage), so + * we don't need to handle this in a special way (see below). */ + fprintf(logfile, "%ld %d %.0f %.0f %.0f %.0f\n", + agg->start_time, agg->cnt, agg->sum, agg->sum2, + agg->min_duration, agg->max_duration); + + /* move to the next inteval */ + agg->start_time = agg->start_time + agg_interval; + + /* reset for "no transaction" intervals */ + agg->cnt = 0; + agg->min_duration = 0; + agg->max_duration = 0; + agg->sum = 0; + agg->sum2 = 0; + } + + /* and now update the reset values (include the current) */ + agg->cnt = 1; + agg->min_duration = usec; + agg->max_duration = usec; + agg->sum = usec; + agg->sum2 = usec * usec; + } + } + 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 + } } } @@ -1921,6 +2006,9 @@ main(int argc, char **argv) {"tablespace", required_argument, NULL, 2}, {"unlogged-tables", no_argument, &unlogged_tables, 1}, {"sampling-rate", required_argument, NULL, 4}, +#ifndef WIN32 + {"aggregate-interval", required_argument, NULL, 5}, +#endif {NULL, 0, NULL, 0} }; @@ -2156,6 +2244,16 @@ main(int argc, char **argv) exit(1); } break; +#ifndef WIN32 + case 5: + agg_interval = atoi(optarg); + if (agg_interval <= 0) + { + fprintf(stderr, "invalid number of seconds for aggregation: %d\n", agg_interval); + exit(1); + } + break; +#endif default: fprintf(stderr, _("Try \"%s --help\" for more information.\n"), progname); exit(1); @@ -2198,6 +2296,28 @@ main(int argc, char **argv) exit(1); } + /* --sampling-rate may must not be used with --aggregate-interval */ + if (sample_rate > 0.0 && agg_interval > 0) + { + fprintf(stderr, "log sampling (--sampling-rate) and aggregation (--aggregate-interval) can't be used at the same time\n"); + exit(1); + } + + if (agg_interval > 0 && (! use_log)) { + fprintf(stderr, "log aggregation is allowed only when actually logging transactions\n"); + exit(1); + } + + if ((duration > 0) && (agg_interval > duration)) { + fprintf(stderr, "number of seconds for aggregation (%d) must not be higher that test duration (%d)\n", agg_interval, duration); + exit(1); + } + + if ((duration > 0) && (agg_interval > 0) && (duration % agg_interval != 0)) { + fprintf(stderr, "duration (%d) must be a multiple of aggregation interval (%d)\n", duration, agg_interval); + exit(1); + } + /* * is_latencies only works with multiple threads in thread-based * implementations, not fork-based ones, because it supposes that the @@ -2457,7 +2577,10 @@ threadRun(void *arg) int remains = nstate; /* number of remaining clients */ int i; + AggVals aggs; + result = pg_malloc(sizeof(TResult)); + INSTR_TIME_SET_ZERO(result->conn_time); /* open log file if requested */ @@ -2492,6 +2615,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++) { @@ -2500,7 +2625,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) @@ -2602,7 +2727,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 */ } @@ -2629,7 +2754,6 @@ done: return result; } - /* * Support for duration option: set timer_exceeded after so many seconds. */ diff --git a/doc/src/sgml/pgbench.sgml b/doc/src/sgml/pgbench.sgml index 91530ab..f109bbd 100644 --- a/doc/src/sgml/pgbench.sgml +++ b/doc/src/sgml/pgbench.sgml @@ -335,6 +335,21 @@ 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> + <para> + This option is not available on Windows. + </para> + </listitem> + </varlistentry> + + <varlistentry> <term><option>-M</option> <replaceable>querymode</></term> <listitem> <para> @@ -730,8 +745,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 @@ -777,6 +793,45 @@ END; </refsect2> <refsect2> + <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> <title>Per-Statement Latencies</title> <para>
-- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers