From: Tom Lane Date: Mon, 2 Jan 2017 17:26:03 +0000 (-0500) Subject: In pgbench logging, avoid assuming that instr_times match Unix timestamps. X-Git-Tag: REL_10_BETA1~1176 X-Git-Url: https://granicus.if.org/sourcecode?a=commitdiff_plain;h=67a875355e4a6db294e9652af5a883876ddeb4a5;p=postgresql In pgbench logging, avoid assuming that instr_times match Unix timestamps. For aggregated logging, pg_bench supposed that printing the integer part of INSTR_TIME_GET_DOUBLE() would produce a Unix timestamp. That was already broken on Windows, and it's about to get broken on most other platforms as well. As in commit 74baa1e3b, we can remove the entanglement at the price of one extra syscall per transaction; though here it seems more convenient to use time(NULL) instead of gettimeofday(), since we only need integral-second precision. I took the time to do some wordsmithing on the documentation about pgbench's logging features, too. Discussion: https://postgr.es/m/8837.1483216839@sss.pgh.pa.us --- diff --git a/doc/src/sgml/ref/pgbench.sgml b/doc/src/sgml/ref/pgbench.sgml index 3a65729bf3..3fb29f8c1d 100644 --- a/doc/src/sgml/ref/pgbench.sgml +++ b/doc/src/sgml/ref/pgbench.sgml @@ -355,7 +355,7 @@ pgbench options dbname - Write the time taken by each transaction to a log file. + Write information about each transaction to a log file. See below for details. @@ -572,13 +572,9 @@ pgbench options dbname - Length of aggregation interval (in seconds). May be used only together - with -l - with this option, the log contains - per-interval summary (number of transactions, min/max latency and two - additional fields useful for variance estimation). - - - This option is not currently supported on Windows. + Length of aggregation interval (in seconds). May be used only + with option. With this option, the log contains + per-interval summary data, as described below. @@ -618,8 +614,8 @@ pgbench options dbname - Set the filename prefix for the transaction log file created by - @@ -1128,38 +1124,44 @@ END; Per-Transaction Logging - With the , - pgbench writes the time taken by each transaction + With the option), + pgbench writes information about each transaction to a log file. The log file will be named prefix.nnn, where prefix defaults to pgbench_log, and nnn is the PID of the - pgbench process. If the The format of the log is: -client_id transaction_no time script_no time_epoch time_us schedule_lag +client_id transaction_no time script_no time_epoch time_us schedule_lag - where time is the total elapsed transaction time in microseconds, + where + client_id indicates which client session ran the transaction, + transaction_no counts how many transactions have been + run by that session, + time is the total elapsed transaction time in microseconds, script_no identifies which script file was used (useful when multiple scripts were specified with - Here is a snippet of the log file generated: + Here is a snippet of a log file generated in a single-client run: 0 199 2241 0 1175850568 995598 0 200 2465 0 1175850568 998079 @@ -1176,7 +1178,8 @@ END; 0 202 2038 0 1175850569 2663 - Another example with --rate=100 and --latency-limit=5 (note the additional + Another example with --rate=100 + and --latency-limit=5 (note the additional schedule_lag column): 0 81 4621 0 1412881037 912698 3005 @@ -1203,32 +1206,41 @@ END; Aggregated Logging - With the option, the logs use a bit different format: + With the option, a different + format is used for the log files: -interval_start num_of_transactions latency_sum latency_2_sum min_latency max_latency lag_sum lag_2_sum min_lag max_lag skipped_transactions +interval_start num_transactions sum_latency sum_latency_2 min_latency max_latency sum_lag sum_lag_2 min_lag max_lag skipped - where interval_start is the start of the interval (Unix epoch - format time stamp), num_of_transactions is the number of transactions - within the interval, latency_sum is a sum of latencies - (so you can compute average latency easily). The following two fields are useful - for variance estimation - latency_sum is a sum of latencies and - latency_2_sum is a sum of 2nd powers of latencies. The next two - fields are min_latency - a minimum latency within the interval, and - max_latency - maximum latency within the interval. A transaction is - counted into the interval when it was committed. The fields in the end, - lag_sum, lag_2_sum, min_lag, + where + interval_start is the start of the interval (as a Unix + epoch time stamp), + num_transactions is the number of transactions + within the interval, + sum_latency is the sum of the transaction + latencies within the interval, + sum_latency_2 is the sum of squares of the + transaction latencies within the interval, + min_latency is the minimum latency within the interval, + and + max_latency is the maximum latency within the interval. + The next fields, + sum_lag, sum_lag_2, min_lag, and max_lag, are only present if the - Here is example output: + Here is some example output: 1345828501 5601 1542744 483552416 61 2573 1345828503 7884 1979812 565806736 60 1479 @@ -1238,9 +1250,9 @@ END; - Notice that while the plain (unaggregated) log file contains a reference - to 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. + Notice that while the plain (unaggregated) log file shows which script + was used for each transaction, the aggregated log does not. Therefore if + you need per-script data, you need to aggregate the data on your own. diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c index 1f05650c66..16a32e21f5 100644 --- a/src/bin/pgbench/pgbench.c +++ b/src/bin/pgbench/pgbench.c @@ -42,6 +42,7 @@ #include #include #include +#include #include #ifdef HAVE_SYS_SELECT_H #include @@ -227,7 +228,7 @@ typedef struct SimpleStats */ typedef struct StatsData { - long start_time; /* interval start time, for aggregates */ + time_t start_time; /* interval start time, for aggregates */ int64 cnt; /* number of transactions */ int64 skipped; /* number of transactions skipped under --rate * and --latency-limit */ @@ -449,7 +450,7 @@ static const BuiltinScript builtin_script[] = static void setIntValue(PgBenchValue *pv, int64 ival); static void setDoubleValue(PgBenchValue *pv, double dval); static bool evaluateExpr(TState *, CState *, PgBenchExpr *, PgBenchValue *); -static void doLog(TState *thread, CState *st, instr_time *now, +static void doLog(TState *thread, CState *st, StatsData *agg, bool skipped, double latency, double lag); static void processXactStats(TState *thread, CState *st, instr_time *now, bool skipped, StatsData *agg); @@ -780,7 +781,7 @@ mergeSimpleStats(SimpleStats *acc, SimpleStats *ss) * the given value. */ static void -initStats(StatsData *sd, double start_time) +initStats(StatsData *sd, time_t start_time) { sd->start_time = start_time; sd->cnt = 0; @@ -2425,10 +2426,15 @@ doCustom(TState *thread, CState *st, StatsData *agg) } /* - * print log entry after completing one transaction. + * Print log entry after completing one transaction. + * + * We print Unix-epoch timestamps in the log, so that entries can be + * correlated against other logs. On some platforms this could be obtained + * from the instr_time reading the caller has, but rather than get entangled + * with that, we just eat the cost of an extra syscall in all cases. */ static void -doLog(TState *thread, CState *st, instr_time *now, +doLog(TState *thread, CState *st, StatsData *agg, bool skipped, double latency, double lag) { FILE *logfile = thread->logfile; @@ -2447,15 +2453,17 @@ doLog(TState *thread, CState *st, instr_time *now, if (agg_interval > 0) { /* - * Loop until we reach the interval of the current transaction, and - * print all the empty intervals in between (this may happen with very - * low tps, e.g. --rate=0.1). + * Loop until we reach the interval of the current moment, and print + * any empty intervals in between (this may happen with very low tps, + * e.g. --rate=0.1). */ - while (agg->start_time + agg_interval < INSTR_TIME_GET_DOUBLE(*now)) + time_t now = time(NULL); + + while (agg->start_time + agg_interval <= now) { /* print aggregated report to logfile */ fprintf(logfile, "%ld " INT64_FORMAT " %.0f %.0f %.0f %.0f", - agg->start_time, + (long) agg->start_time, agg->cnt, agg->latency.sum, agg->latency.sum2, @@ -2485,12 +2493,6 @@ doLog(TState *thread, CState *st, instr_time *now, /* no, print raw transactions */ struct timeval tv; - /* - * We print the current system timestamp in the log, so that entries - * can be correlated against other logs. On some platforms this is - * available in *now, but rather than get entangled with that, we just - * eat the cost of an extra syscall in all cases. - */ gettimeofday(&tv, NULL); if (skipped) fprintf(logfile, "%d " INT64_FORMAT " skipped %d %ld %ld", @@ -2518,7 +2520,7 @@ processXactStats(TState *thread, CState *st, instr_time *now, double latency = 0.0, lag = 0.0; - if ((!skipped || agg_interval) && INSTR_TIME_IS_ZERO(*now)) + if ((!skipped) && INSTR_TIME_IS_ZERO(*now)) INSTR_TIME_SET_CURRENT(*now); if (!skipped) @@ -2540,7 +2542,7 @@ processXactStats(TState *thread, CState *st, instr_time *now, thread->stats.cnt++; if (use_log) - doLog(thread, st, now, agg, skipped, latency, lag); + doLog(thread, st, agg, skipped, latency, lag); /* XXX could use a mutex here, but we choose not to */ if (per_script_stats) @@ -3202,7 +3204,7 @@ ParseScript(const char *script, const char *desc, int weight) ps.desc = desc; ps.weight = weight; ps.commands = (Command **) pg_malloc(sizeof(Command *) * alloc_num); - initStats(&ps.stats, 0.0); + initStats(&ps.stats, 0); /* Prepare to parse script */ sstate = psql_scan_create(&pgbench_callbacks); @@ -3972,10 +3974,6 @@ main(int argc, char **argv) } break; case 5: -#ifdef WIN32 - fprintf(stderr, "--aggregate-interval is not currently supported on Windows\n"); - exit(1); -#else benchmarking_option_set = true; agg_interval = atoi(optarg); if (agg_interval <= 0) @@ -3984,7 +3982,6 @@ main(int argc, char **argv) optarg); exit(1); } -#endif break; case 6: progress_timestamp = true; @@ -4267,7 +4264,7 @@ main(int argc, char **argv) thread->random_state[2] = random(); thread->logfile = NULL; /* filled in later */ thread->latency_late = 0; - initStats(&thread->stats, 0.0); + initStats(&thread->stats, 0); nclients_dealt += thread->nstate; } @@ -4321,7 +4318,7 @@ main(int argc, char **argv) #endif /* ENABLE_THREAD_SAFETY */ /* wait for threads and accumulate results */ - initStats(&stats, 0.0); + initStats(&stats, 0); INSTR_TIME_SET_ZERO(conn_total_time); for (i = 0; i < nthreads; i++) { @@ -4394,6 +4391,9 @@ threadRun(void *arg) INSTR_TIME_SET_ZERO(thread->conn_time); + initStats(&aggs, time(NULL)); + last = aggs; + /* open log file if requested */ if (use_log) { @@ -4429,9 +4429,6 @@ threadRun(void *arg) INSTR_TIME_SET_CURRENT(thread->conn_time); INSTR_TIME_SUBTRACT(thread->conn_time, thread->start_time); - initStats(&aggs, INSTR_TIME_GET_DOUBLE(thread->start_time)); - last = aggs; - /* explicitly initialize the state machines */ for (i = 0; i < nstate; i++) { @@ -4635,7 +4632,7 @@ threadRun(void *arg) * (If a read from a 64-bit integer is not atomic, you might * get a "torn" read and completely bogus latencies though!) */ - initStats(&cur, 0.0); + initStats(&cur, 0); for (i = 0; i < nthreads; i++) { mergeSimpleStats(&cur.latency, &thread[i].stats.latency); @@ -4695,12 +4692,13 @@ done: INSTR_TIME_ACCUM_DIFF(thread->conn_time, end, start); if (thread->logfile) { - if (agg_interval) + if (agg_interval > 0) { /* log aggregated but not yet reported transactions */ - doLog(thread, state, &end, &aggs, false, 0, 0); + doLog(thread, state, &aggs, false, 0, 0); } fclose(thread->logfile); + thread->logfile = NULL; } return NULL; }