pgbench progress with timestamp

Started by Fabien COELHOover 10 years ago8 messages

coelho@cri.ensmp.fr

over 10 years ago

1 attachment(s)

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
...

--
Fabien.

Attachments:

pgbench-progress-timestamp-1.patchtext/x-diff; name=pgbench-progress-timestamp-1.patchDownload

diff --git a/doc/src/sgml/ref/pgbench.sgml b/doc/src/sgml/ref/pgbench.sgml
index 2517a3a..dc7e55f 100644
--- a/doc/src/sgml/ref/pgbench.sgml
+++ b/doc/src/sgml/ref/pgbench.sgml
@@ -429,6 +429,18 @@ pgbench <optional> <replaceable>options</> </optional> <replaceable>dbname</>
      </varlistentry>
 
      <varlistentry>
+      <term><option>--progress-timestamp</option></term>
+      <listitem>
+       <para>
+        When showing progress (option <option>-P</>), use a millisecond
+        timestamp (Unix epoch) intead of the number of second since the
+        beginning of the run.
+        This helps compare logs generated by various tools.
+       </para>
+      </listitem>
+     </varlistentry>
+
+     <varlistentry>
       <term><option>-r</option></term>
       <term><option>--report-latencies</option></term>
       <listitem>
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index 30e8d2a..6cab4a3 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 a ms timestamp 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 - 1000000.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);

Jeff Janes

jeff.janes@gmail.com

over 10 years ago

In reply to: Fabien COELHO (#1)

Re: pgbench progress with timestamp

On Sun, Aug 23, 2015 at 4:25 AM, Fabien COELHO <coelho@cri.ensmp.fr> 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

Fabien COELHO

coelho@cri.ensmp.fr

over 10 years ago

In reply to: Jeff Janes (#2)

Re: 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

Jeff Janes

jeff.janes@gmail.com

over 10 years ago

In reply to: Fabien COELHO (#3)

Re: pgbench progress with timestamp

On Mon, Sep 7, 2015 at 11:25 PM, Fabien COELHO <coelho@cri.ensmp.fr> 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

Fabien COELHO

coelho@cri.ensmp.fr

over 10 years ago

In reply to: Jeff Janes (#4)

1 attachment(s)

Re: 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.

Attachments:

pgbench-progress-timestamp-2.patchtext/x-diff; name=pgbench-progress-timestamp-2.patchDownload

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 <optional> <replaceable>options</> </optional> <replaceable>dbname</>
      </varlistentry>
 
      <varlistentry>
+      <term><option>--progress-timestamp</option></term>
+      <listitem>
+       <para>
+        When showing progress (option <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.
+       </para>
+      </listitem>
+     </varlistentry>
+
+     <varlistentry>
       <term><option>-r</option></term>
       <term><option>--report-latencies</option></term>
       <listitem>
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 - 1000000.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);

Jeff Janes

jeff.janes@gmail.com

over 10 years ago

In reply to: Fabien COELHO (#5)

Re: pgbench progress with timestamp

On Wed, Sep 9, 2015 at 1:35 AM, Fabien COELHO <coelho@cri.ensmp.fr> 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

Fabien COELHO

coelho@cri.ensmp.fr

over 10 years ago

In reply to: Jeff Janes (#6)

1 attachment(s)

Re: 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.

Attachments:

pgbench-progress-timestamp-3.patchtext/x-diff; name=pgbench-progress-timestamp-3.patchDownload

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 <optional> <replaceable>options</> </optional> <replaceable>dbname</>
      </varlistentry>
 
      <varlistentry>
+      <term><option>--progress-timestamp</option></term>
+      <listitem>
+       <para>
+        When showing progress (option <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.
+       </para>
+      </listitem>
+     </varlistentry>
+
+     <varlistentry>
       <term><option>-r</option></term>
       <term><option>--report-latencies</option></term>
       <listitem>
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 - 1000000.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);

Teodor Sigaev

teodor@sigaev.ru

over 10 years ago

In reply to: Fabien COELHO (#7)

Re: 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: teodor@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