Re: [HACKERS] pgbench progress with timestamp
Thank you, committed Fabien COELHO wrote: --progress-timestamp use Unix epoch timestamps in ms for progress A quibble, but it isn't in ms, it is in seconds. The digits after the decimal point give a precision to the ms level, but they don't change the base unit. Yes. The issue is mostly to keep the description under 80 columns. I would just leave the units out of the help description, as the progress message itself includes the units. Here is a v3 with a shorten description and a better documentation. -- Teodor Sigaev E-mail: teo...@sigaev.ru WWW: http://www.sigaev.ru/ -- 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 with timestamp
--progress-timestamp use Unix epoch timestamps in ms for progress A quibble, but it isn't in ms, it is in seconds. The digits after the decimal point give a precision to the ms level, but they don't change the base unit. Yes. The issue is mostly to keep the description under 80 columns. I would just leave the units out of the help description, as the progress message itself includes the units. Here is a v3 with a shorten description and a better documentation. -- Fabien.diff --git a/doc/src/sgml/ref/pgbench.sgml b/doc/src/sgml/ref/pgbench.sgml index ba3edc4..0ac40f1 100644 --- a/doc/src/sgml/ref/pgbench.sgml +++ b/doc/src/sgml/ref/pgbench.sgml @@ -429,6 +429,19 @@ pgbench options dbname + --progress-timestamp + + +When showing progress (option -P), use a timestamp +(Unix epoch) instead of the number of seconds since the +beginning of the run. The unit is in seconds, with millisecond +precision after the dot. +This helps compare logs generated by various tools. + + + + + -r --report-latencies diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c index 6894345..024d4c5 100644 --- a/src/bin/pgbench/pgbench.c +++ b/src/bin/pgbench/pgbench.c @@ -165,6 +165,7 @@ 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 progress_timestamp = false; int progress_nclients = 0; /* number of clients for progress * report */ int progress_nthreads = 0; /* number of threads for progress @@ -389,6 +390,7 @@ usage(void) " -v, --vacuum-all vacuum all four standard tables before tests\n" " --aggregate-interval=NUM aggregate data over NUM seconds\n" " --sampling-rate=NUM fraction of transactions to log (e.g. 0.01 for 1%%)\n" + " --progress-timestamp use Unix epoch timestamps for progress\n" "\nCommon options:\n" " -d, --debug print debugging output\n" " -h, --host=HOSTNAME database server host or socket directory\n" @@ -2774,6 +2776,7 @@ main(int argc, char **argv) {"aggregate-interval", required_argument, NULL, 5}, {"rate", required_argument, NULL, 'R'}, {"latency-limit", required_argument, NULL, 'L'}, + {"progress-timestamp", no_argument, NULL, 6}, {NULL, 0, NULL, 0} }; @@ -3110,6 +3113,10 @@ main(int argc, char **argv) } #endif break; + case 6: +progress_timestamp = true; +benchmarking_option_set = true; +break; default: fprintf(stderr, _("Try \"%s --help\" for more information.\n"), progname); exit(1); @@ -3748,6 +3755,7 @@ threadRun(void *arg) sqlat, lag, stdev; +char tbuf[64]; /* * Add up the statistics of all threads. @@ -3780,10 +3788,16 @@ threadRun(void *arg) stdev = 0.001 * sqrt(sqlat - 100.0 * latency * latency); lag = 0.001 * (lags - last_lags) / (count - last_count); +if (progress_timestamp) + sprintf(tbuf, "%.03f s", + INSTR_TIME_GET_MILLISEC(now_time) / 1000.0); +else + sprintf(tbuf, "%.1f s", total_run); + fprintf(stderr, - "progress: %.1f s, %.1f tps, " - "lat %.3f ms stddev %.3f", - total_run, tps, latency, stdev); + "progress: %s, %.1f tps, lat %.3f ms stddev %.3f", + tbuf, tps, latency, stdev); + if (throttle_delay) { fprintf(stderr, ", lag %.3f ms", lag); -- 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 with timestamp
On Wed, Sep 9, 2015 at 1:35 AM, Fabien COELHO wrote: > > In the sgml, second should be plural in 'intead of the number of second >> since the'. And 'intead' should be 'instead'. >> > > Ok. > > --progress-timestamp use a Unix-like epoch timestamp for progress >> reporting >> >> but that is getting pretty long. >> > > Indeed. I've done: > > --progress-timestamp use Unix epoch timestamps in ms for progress > A quibble, but it isn't in ms, it is in seconds. The digits after the decimal point give a precision to the ms level, but they don't change the base unit. I would just leave the units out of the help description, as the progress message itself includes the units. Since this is mostly bikeshedding, I've marked it ready for committer. Let's see what color they like the shed. Cheers, Jeff
Re: [HACKERS] pgbench progress with timestamp
In the sgml, second should be plural in 'intead of the number of second since the'. And 'intead' should be 'instead'. Ok. --progress-timestamp use a Unix-like epoch timestamp for progress reporting but that is getting pretty long. Indeed. I've done: --progress-timestamp use Unix epoch timestamps in ms for progress Here is a v2. -- Fabien.diff --git a/doc/src/sgml/ref/pgbench.sgml b/doc/src/sgml/ref/pgbench.sgml index 2517a3a..dabb1ae 100644 --- a/doc/src/sgml/ref/pgbench.sgml +++ b/doc/src/sgml/ref/pgbench.sgml @@ -429,6 +429,18 @@ pgbench options dbname + --progress-timestamp + + +When showing progress (option -P), use a millisecond +timestamp (Unix epoch) instead of the number of seconds since the +beginning of the run. +This helps compare logs generated by various tools. + + + + + -r --report-latencies diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c index 30e8d2a..f750f62 100644 --- a/src/bin/pgbench/pgbench.c +++ b/src/bin/pgbench/pgbench.c @@ -165,6 +165,7 @@ 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 progress_timestamp = false; int progress_nclients = 0; /* number of clients for progress * report */ int progress_nthreads = 0; /* number of threads for progress @@ -389,6 +390,7 @@ usage(void) " -v, --vacuum-all vacuum all four standard tables before tests\n" " --aggregate-interval=NUM aggregate data over NUM seconds\n" " --sampling-rate=NUM fraction of transactions to log (e.g. 0.01 for 1%%)\n" + " --progress-timestamp use Unix epoch timestamps in ms for progress\n" "\nCommon options:\n" " -d, --debug print debugging output\n" " -h, --host=HOSTNAME database server host or socket directory\n" @@ -2774,6 +2776,7 @@ main(int argc, char **argv) {"aggregate-interval", required_argument, NULL, 5}, {"rate", required_argument, NULL, 'R'}, {"latency-limit", required_argument, NULL, 'L'}, + {"progress-timestamp", no_argument, NULL, 6}, {NULL, 0, NULL, 0} }; @@ -3110,6 +3113,10 @@ main(int argc, char **argv) } #endif break; + case 6: +progress_timestamp = true; +benchmarking_option_set = true; +break; default: fprintf(stderr, _("Try \"%s --help\" for more information.\n"), progname); exit(1); @@ -3748,6 +3755,7 @@ threadRun(void *arg) sqlat, lag, stdev; +char tbuf[64]; /* * Add up the statistics of all threads. @@ -3780,10 +3788,16 @@ threadRun(void *arg) stdev = 0.001 * sqrt(sqlat - 100.0 * latency * latency); lag = 0.001 * (lags - last_lags) / (count - last_count); +if (progress_timestamp) + sprintf(tbuf, "%.03f s", + INSTR_TIME_GET_MILLISEC(now_time) / 1000.0); +else + sprintf(tbuf, "%.1f s", total_run); + fprintf(stderr, - "progress: %.1f s, %.1f tps, " - "lat %.3f ms stddev %.3f", - total_run, tps, latency, stdev); + "progress: %s, %.1f tps, lat %.3f ms stddev %.3f", + tbuf, tps, latency, stdev); + if (throttle_delay) { fprintf(stderr, ", lag %.3f ms", lag); -- 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 with timestamp
On Mon, Sep 7, 2015 at 11:25 PM, Fabien COELHO wrote: > > Use milliseconds for consistency with the '%n' log_prefix patch currently >>> submitted by Tomas Vondra in the CF. >>> >>> sh> ./pgbench -P 1 -N -T 100 -c 2 >>> starting vacuum...end. >>> progress: 1.0 s, 546.0 tps, lat 3.619 ms stddev 4.426 >>> progress: 2.0 s, 575.0 tps, lat 3.480 ms stddev 1.705 >>> >>> sh> ./pgbench -P 1 --progress-timestamp -N -T 100 -c 2 >>> starting vacuum...end. >>> progress: 1440328800.064 s, 549.0 tps, lat 3.602 ms stddev 1.698 >>> progress: 1440328801.064 s, 570.0 tps, lat 3.501 ms stddev 1.704 >>> >> >> I like the idea of the timestamp. But could just always print both the >> timestamp and the elapsed time, rather than adding another switch to >> decide >> between them? >> > > I agree that an option for this purpose is on the heavy side. > > I'm not sure how fine it would be, though: progress lines can already be a > little bit long (under -R & -L) and I do not like wide terminal. Also, I > see --progress as a "user friendly" easy to read feature to know how things > are going during a run. A timestamp does not fall into this category: it is > pretty ugly and unreadable, so it is really out of necessity that I'm > resorting to that. > > So I would rather keep the option because of the inelegance of having > timestamps printed. OK. In the sgml, second should be plural in 'intead of the number of second since the'. And 'intead' should be 'instead'. Also, in the usage message, I think the key piece of this is that it is Unix-epoch, not that it is ms resolution: --progress-timestamp use a ms timestamp for progress Maybe --progress-timestamp use a Unix-like epoch timestamp for progress reporting but that is getting pretty long. Other than that, I think it looks good. Cheers, Jeff
Re: [HACKERS] pgbench progress with timestamp
Use milliseconds for consistency with the '%n' log_prefix patch currently submitted by Tomas Vondra in the CF. sh> ./pgbench -P 1 -N -T 100 -c 2 starting vacuum...end. progress: 1.0 s, 546.0 tps, lat 3.619 ms stddev 4.426 progress: 2.0 s, 575.0 tps, lat 3.480 ms stddev 1.705 sh> ./pgbench -P 1 --progress-timestamp -N -T 100 -c 2 starting vacuum...end. progress: 1440328800.064 s, 549.0 tps, lat 3.602 ms stddev 1.698 progress: 1440328801.064 s, 570.0 tps, lat 3.501 ms stddev 1.704 I like the idea of the timestamp. But could just always print both the timestamp and the elapsed time, rather than adding another switch to decide between them? I agree that an option for this purpose is on the heavy side. I'm not sure how fine it would be, though: progress lines can already be a little bit long (under -R & -L) and I do not like wide terminal. Also, I see --progress as a "user friendly" easy to read feature to know how things are going during a run. A timestamp does not fall into this category: it is pretty ugly and unreadable, so it is really out of necessity that I'm resorting to that. So I would rather keep the option because of the inelegance of having timestamps printed. -- 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 with timestamp
On Sun, Aug 23, 2015 at 4:25 AM, Fabien COELHO wrote: > > It is not easy to compare events on a pgbench runs (oops, the tps is down) > with for instance events in postgres log, so as to figure out what may have > cause a given glitch. > > This patches adds an option to replace the "time since pgbench run > started" with a timestamp in the progress report so that it is easier to > compare timelines. > > Use milliseconds for consistency with the '%n' log_prefix patch currently > submitted by Tomas Vondra in the CF. > > sh> ./pgbench -P 1 -N -T 100 -c 2 > starting vacuum...end. > progress: 1.0 s, 546.0 tps, lat 3.619 ms stddev 4.426 > progress: 2.0 s, 575.0 tps, lat 3.480 ms stddev 1.705 > > sh> ./pgbench -P 1 --progress-timestamp -N -T 100 -c 2 > starting vacuum...end. > progress: 1440328800.064 s, 549.0 tps, lat 3.602 ms stddev 1.698 > progress: 1440328801.064 s, 570.0 tps, lat 3.501 ms stddev 1.704 > I like the idea of the timestamp. But could just always print both the timestamp and the elapsed time, rather than adding another switch to decide between them? Cheers, Jeff