Обсуждение: pgbench progress with timestamp
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.
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
>> 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.
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
> 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.
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
>> --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.
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/