Re: [HACKERS] pgbench progress with timestamp

[Teodor Sigaev]

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

[Fabien COELHO]

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

[Jeff Janes]

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

[Fabien COELHO]

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

[Fabien COELHO]

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

[Jeff Janes]

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

[Jeff Janes]

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

[HACKERS] pgbench progress with timestamp

[Fabien COELHO]

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.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 replaceableoptions/ /optional replaceabledbname/
  /varlistentry
 
  varlistentry
+  termoption--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
   termoption-r/option/term
   termoption--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 - 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