Date: Thu, 17 Jun 2021 09:15:37 +0200 (CEST)
From: Fabien COELHO <coelho@cri.ensmp.fr>
To: Kyotaro Horiguchi <horikyota.ntt@gmail.com>
cc: nagata@sraoss.co.jp, gregsmithpgsql@gmail.com,
    pgsql-hackers@postgresql.org, david.christensen@crunchydata.com
Subject: Re: pgbench logging broken by time logic changes
In-Reply-To: <20210617.141756.654908256727895408.horikyota.ntt@gmail.com>
Message-ID: <alpine.DEB.2.22.394.2106170901100.2693553@pseudo>
References: <20210617025138.04a35c3ae9a6cd40c077cea0@sraoss.co.jp>
 <alpine.DEB.2.22.394.2106162102030.2407635@pseudo>
 <20210617122342.74aa8e65b186a7f2e0034533@sraoss.co.jp>
 <20210617.141756.654908256727895408.horikyota.ntt@gmail.com>
User-Agent: Alpine 2.22 (DEB 394 2020-01-19)
MIME-Version: 1.0
Content-Type: multipart/mixed;
 boundary="2056645051-1824793688-1623914137=:2693553"
Archived-At: 
 <https://www.postgresql.org/message-id/alpine.DEB.2.22.394.2106170901100.2693553%40pseudo>
Precedence: bulk

  This message is in MIME format.  The first part should be readable text,
  while the remaining parts are likely unreadable without MIME-aware tools.

--2056645051-1824793688-1623914137=:2693553
Content-Type: text/plain; format=flowed; charset=US-ASCII


Hello,

>>> I cannot say that I'm thrilled by having multiple tv stuff back in several
>>> place. I can be okay with one, though. What about the attached? Does it
>>> make sense?
>
> +1 The patch rounds down sd->start_time from ms to s but it seems to
> me a degradation.

Yes, please we should not use time.

>> At first, I also thought of fixing pg_time_now() to use gettimeofday() instead
>> of INSTR_TIME_SET_CURRENT, but I noticed that using INSTR_TIME_SET_CURRENT is
>> proper to measure time interval.  I mean, this macro uses
>> lock_gettime(CLOCK_MONOTONIC, ) if avilable, which give reliable interval
>> timing even in the face of changes to the system clock due to NTP.
>
> If I understand the op correctly, the problem here is the time values
> in pgbench log file are based on a bogus epoch.

It is not "bogus", but is not necessary epoch depending on the underlying 
function called behind by INSTR_TIME macros, and people are entitled to 
expect epoch for log correlations.

> If it's the only issue
> here and and if we just want to show the time based on the unix epoch
> time, just recording the difference would work as I scketched in the
> attached.  (Precisely theepoch would move if we set the system clock
> but I don't think that matters:p)

I do like the approach.

I'm hesitant to promote it for fixing the beta, but the code impact is 
small enough, so I'd say yes. Maybe there is a similar issue with progress 
which should probably use the same approach. I think that aligning the 
implementations can wait for pg15.

The patch as white space issues. Attached an updated version which fixes 
that, adds comments and simplify the code a little bit.

> I'm not sure we have transaction lasts for very short time that 
> nanoseconds matters.

Indeed.

-- 
Fabien.
--2056645051-1824793688-1623914137=:2693553
Content-Type: text/x-diff; name=pgbench-epoch-4.patch
Content-Transfer-Encoding: BASE64
Content-ID: <alpine.DEB.2.22.394.2106170915370.2693553@pseudo>
Content-Description: 
Content-Disposition: attachment; filename=pgbench-epoch-4.patch

ZGlmZiAtLWdpdCBhL3NyYy9iaW4vcGdiZW5jaC9wZ2JlbmNoLmMgYi9zcmMv
YmluL3BnYmVuY2gvcGdiZW5jaC5jDQppbmRleCBkNzQ3OTkyNWNiLi44NzZj
NWE0NTQ3IDEwMDY0NA0KLS0tIGEvc3JjL2Jpbi9wZ2JlbmNoL3BnYmVuY2gu
Yw0KKysrIGIvc3JjL2Jpbi9wZ2JlbmNoL3BnYmVuY2guYw0KQEAgLTM0Miw2
ICszNDIsMTIgQEAgdHlwZWRlZiBzdHJ1Y3QgU3RhdHNEYXRhDQogCVNpbXBs
ZVN0YXRzIGxhZzsNCiB9IFN0YXRzRGF0YTsNCiANCisvKg0KKyAqIEZvciBk
aXNwbGF5aW5nIGVwb2NoIHRpbWVzdGFtcCwgYXMgc29tZSB0aW1lIGZ1bmN0
aW9ucyBtYXkgaGF2ZQ0KKyAqIGFub3RoZXIgcmVmZXJlbmNlLg0KKyAqLw0K
K3BnX3RpbWVfdXNlY190IGVwb2NoX3NoaWZ0Ow0KKw0KIC8qDQogICogU3Ry
dWN0IHRvIGtlZXAgcmFuZG9tIHN0YXRlLg0KICAqLw0KQEAgLTM4MDMsNyAr
MzgwOSw3IEBAIGRvTG9nKFRTdGF0ZSAqdGhyZWFkLCBDU3RhdGUgKnN0LA0K
IAkJew0KIAkJCS8qIHByaW50IGFnZ3JlZ2F0ZWQgcmVwb3J0IHRvIGxvZ2Zp
bGUgKi8NCiAJCQlmcHJpbnRmKGxvZ2ZpbGUsIElOVDY0X0ZPUk1BVCAiICIg
SU5UNjRfRk9STUFUICIgJS4wZiAlLjBmICUuMGYgJS4wZiIsDQotCQkJCQlh
Z2ctPnN0YXJ0X3RpbWUsDQorCQkJCQlhZ2ctPnN0YXJ0X3RpbWUgKyBlcG9j
aF9zaGlmdCwNCiAJCQkJCWFnZy0+Y250LA0KIAkJCQkJYWdnLT5sYXRlbmN5
LnN1bSwNCiAJCQkJCWFnZy0+bGF0ZW5jeS5zdW0yLA0KQEAgLTM4MzAsNiAr
MzgzNiw5IEBAIGRvTG9nKFRTdGF0ZSAqdGhyZWFkLCBDU3RhdGUgKnN0LA0K
IAl9DQogCWVsc2UNCiAJew0KKwkJLyogc3dpdGNoIHRvIGVwb2NoIGZvciBk
aXNwbGF5aW5nIHRoZSB0aW1lc3RhbXAgKi8NCisJCW5vdyArPSBlcG9jaF9z
aGlmdDsNCisNCiAJCS8qIG5vLCBwcmludCByYXcgdHJhbnNhY3Rpb25zICov
DQogCQlpZiAoc2tpcHBlZCkNCiAJCQlmcHJpbnRmKGxvZ2ZpbGUsICIlZCAi
IElOVDY0X0ZPUk1BVCAiIHNraXBwZWQgJWQgIiBJTlQ2NF9GT1JNQVQgIiAi
DQpAQCAtNTc3NSw2ICs1Nzg0LDExIEBAIG1haW4oaW50IGFyZ2MsIGNoYXIg
Kiphcmd2KQ0KIAljaGFyCSAgICplbnY7DQogDQogCWludAkJCWV4aXRfY29k
ZSA9IDA7DQorCXN0cnVjdCB0aW1ldmFsIHR2Ow0KKw0KKwkvKiByZWNvcmQg
c2hpZnQgYmV0d2VlbiBlcG9jaCBhbmQgbm93KCkgKi8NCisJZ2V0dGltZW9m
ZGF5KCZ0diwgTlVMTCk7DQorCWVwb2NoX3NoaWZ0ID0gdHYudHZfc2VjICog
MTAwMDAwMCArIHR2LnR2X3VzZWMgLSBwZ190aW1lX25vdygpOw0KIA0KIAlw
Z19sb2dnaW5nX2luaXQoYXJndlswXSk7DQogCXByb2duYW1lID0gZ2V0X3By
b2duYW1lKGFyZ3ZbMF0pOw0K

--2056645051-1824793688-1623914137=:2693553--