Re: Error on pgbench logs

At Tue, 8 Jun 2021 12:09:47 +0900, YoungHwan Joo <rulyox@gmail.com> wrote in 
> Hello!
> 
> While I was using pgbench from the master branch, I discovered an error on
> pgbench logs.
> When I run pgbench, the log file contains a lot of redundant 0s.
> 
> I ran git bisect and found out that this error occured since the commit
> 547f04e7348b6ed992bd4a197d39661fe7c25097 (Mar 10, 2021).

Ugh!  Thanks for the hunting!

The cause is that the time unit is changed to usec but the patch
forgot to convert agg_interval into the same unit in doLog. I tempted
to change it into pg_time_usec_t but it seems that it is better that
the unit is same with other similar variables like duration.

So I think that the attached fix works for you. (However, I'm not sure
the emitted log is correct or not, though..)

I didn't check for the similar bugs for other variables yet.

> I ran the tests below on the problematic commit and the commit before it.
> (I used Debian 10.9 and Ubuntu 20.04)
> 
> =====
> ./pg_ctl -D /tmp/data init
> ./pg_ctl -D /tmp/data start
> 
> ./pgbench -i -s 1 postgres
> 
> ./pgbench -r -c 1 -j 1 -T 1 --aggregate-interval 1 -l --log-prefix
> pgbench-log postgres
> ./pgbench -r -c 2 -j 4 -T 60 --aggregate-interval 1 -l --log-prefix
> pgbench-log postgres
> ./pgbench -r -c 2 -j 4 -T 60 --aggregate-interval 10 -l --log-prefix
> pgbench-log postgres
> =====
> 
> The result screenshots are in the attachments.
> (I didn't attach the problematic 60 second log file which was bigger than
> 1GB.)
> 
> Please take a look at this issue.
> 
> Thank you!
> 
> Regards,
> YoungHwan

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index dc84b7b9b7..c68dfa1806 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -3799,7 +3799,7 @@ doLog(TState *thread, CState *st,
          * e.g. --rate=0.1).
          */
 
-        while (agg->start_time + agg_interval <= now)
+        while (agg->start_time + agg_interval * 1000000 <= now)
         {
             /* print aggregated report to logfile */
             fprintf(logfile, INT64_FORMAT " " INT64_FORMAT " %.0f %.0f %.0f %.0f",
@@ -3822,7 +3822,7 @@ doLog(TState *thread, CState *st,
             fputc('\n', logfile);
 
             /* reset data and move to next interval */
-            initStats(agg, agg->start_time + agg_interval);
+            initStats(agg, agg->start_time + agg_interval * 1000000);
         }
 
         /* accumulate the current transaction */