Thread

Commits

Same data as JSON: GET /api/v1/messages/:b64id/commits the thread's linked commits as JSON, with link sources. API reference →

Force LC_NUMERIC to C while running TAP tests.
- f25792c541e5 19 (unreleased) landed
Minor tweaks for pg_test_timing.
- 9dcc7641444f 19 (unreleased) landed
Change pg_test_timing to measure in nanoseconds not microseconds.
- 0b096e379e6f 19 (unreleased) landed

What is a typical precision of gettimeofday()?

Peter Eisentraut <peter@eisentraut.org> — 2024-03-19T08:28:37Z

Over in the thread discussing the addition of UUIDv7 support [0], there 
is some uncertainty about what timestamp precision one can expect from 
gettimeofday().

UUIDv7 uses milliseconds since Unix epoch, but can optionally use up to 
12 additional bits of timestamp precision (see [1]), but it can also 
just use a counter instead of the extra precision.  The current patch 
uses the counter method "because of portability concerns" (source code 
comment).

I feel that we don't actually have any information about this 
portability concern.  Does anyone know what precision we can expect from 
gettimeofday()?  Can we expect the full microsecond precision usually?


[0]: 
https://www.postgresql.org/message-id/flat/CAAhFRxitJv=yoGnXUgeLB_O+M7J2BJAmb5jqAT9gZ3bij3uLDA@mail.gmail.com
[1]: 
https://datatracker.ietf.org/doc/html/draft-ietf-uuidrev-rfc4122bis#section-6.2-5.6.1

Re: What is a typical precision of gettimeofday()?

Aleksander Alekseev <aleksander@timescale.com> — 2024-03-19T09:38:44Z

Hi,

cc: Andrey

> Over in the thread discussing the addition of UUIDv7 support [0], there
> is some uncertainty about what timestamp precision one can expect from
> gettimeofday().
>
> UUIDv7 uses milliseconds since Unix epoch, but can optionally use up to
> 12 additional bits of timestamp precision (see [1]), but it can also
> just use a counter instead of the extra precision.  The current patch
> uses the counter method "because of portability concerns" (source code
> comment).
>
> I feel that we don't actually have any information about this
> portability concern.  Does anyone know what precision we can expect from
> gettimeofday()?  Can we expect the full microsecond precision usually?

Specifically in the UUIDv7 application the goal is to generate not
necessarily time-precise UUIDs but rather do our best to get *unique*
UUIDs. As I understand, this is the actual reason why the patch needs
counters.

As Linux man page puts it:

"""
The time returned by gettimeofday() is affected by discontinuous jumps
in the system  time  (e.g.,  if  the  system  administrator  manually
changes the system time).
"""

On top of that MacOS man page says:

"""
The resolution of the system clock is hardware dependent, and the time
may be updated continuously or in ``ticks.''
"""

On Windows our gettimeofday() implementation is a wrapper for
GetSystemTimePreciseAsFileTime(). The corresponding MSDN page [1] is
somewhat laconic.

Considering the number of environments PostgreSQL can run in (OS +
hardware + virtualization technologies) and the fact that
hardware/software changes I doubt that it's realistic to expect any
particular guarantees from gettimeofday() in the general case.

[1]: https://learn.microsoft.com/en-us/windows/win32/api/sysinfoapi/nf-sysinfoapi-getsystemtimepreciseasfiletime


--
Best regards,
Aleksander Alekseev

Re: What is a typical precision of gettimeofday()?

Peter Eisentraut <peter@eisentraut.org> — 2024-03-20T06:35:22Z

On 19.03.24 10:38, Aleksander Alekseev wrote:
> Considering the number of environments PostgreSQL can run in (OS +
> hardware + virtualization technologies) and the fact that
> hardware/software changes I doubt that it's realistic to expect any
> particular guarantees from gettimeofday() in the general case.

If we want to be robust without any guarantees from gettimeofday(), then 
arguably gettimeofday() is not the right underlying function to use for 
UUIDv7.  I'm not arguing that, I think we can assume some reasonable 
baseline for what gettimeofday() produces.  But it would be good to get 
some information about what that might be.

Btw., here is util-linux saying

     /* Assume that the gettimeofday() has microsecond granularity */

https://github.com/util-linux/util-linux/blob/master/libuuid/src/gen_uuid.c#L232

Re: What is a typical precision of gettimeofday()?

Jelte Fennema-Nio <postgres@jeltef.nl> — 2024-03-20T18:35:20Z

On Wed, 20 Mar 2024 at 07:35, Peter Eisentraut <peter@eisentraut.org> wrote:
> If we want to be robust without any guarantees from gettimeofday(), then
> arguably gettimeofday() is not the right underlying function to use for
> UUIDv7.

There's also clock_gettime which exposes its resolution using clock_getres

Re: What is a typical precision of gettimeofday()?

Andrey Borodin <x4mmm@yandex-team.ru> — 2024-06-18T05:47:52Z

> On 19 Mar 2024, at 13:28, Peter Eisentraut <peter@eisentraut.org> wrote:
> 
> I feel that we don't actually have any information about this portability concern.  Does anyone know what precision we can expect from gettimeofday()?  Can we expect the full microsecond precision usually?

At PGConf.dev Hannu Krossing draw attention to pg_test_timing module. I’ve tried this module(slightly modified to measure nanoseconds) on some systems, and everywhere I found ~100ns resolution (95% of ticks fall into 64ns and 128ns buckets).

I’ll add cc Hannu, and also pg_test_timing module authors Ants ang Greg. Maybe they can add some context.

Best regards, Andrey Borodin.

Re: What is a typical precision of gettimeofday()?

Hannu Krosing <hannuk@google.com> — 2024-06-18T15:08:57Z

I plan to send patch to pg_test_timing in a day or two

the underlying time precision on modern linux seems to be

2 ns for some Intel CPUs
10 ns for Zen4
40 ns for ARM (Ampere)

---
Hannu



|




On Tue, Jun 18, 2024 at 7:48 AM Andrey M. Borodin <x4mmm@yandex-team.ru>
wrote:

>
>
> > On 19 Mar 2024, at 13:28, Peter Eisentraut <peter@eisentraut.org> wrote:
> >
> > I feel that we don't actually have any information about this
> portability concern.  Does anyone know what precision we can expect from
> gettimeofday()?  Can we expect the full microsecond precision usually?
>
> At PGConf.dev Hannu Krossing draw attention to pg_test_timing module. I’ve
> tried this module(slightly modified to measure nanoseconds) on some
> systems, and everywhere I found ~100ns resolution (95% of ticks fall into
> 64ns and 128ns buckets).
>
> I’ll add cc Hannu, and also pg_test_timing module authors Ants ang Greg.
> Maybe they can add some context.
>
>
> Best regards, Andrey Borodin.

Re: What is a typical precision of gettimeofday()?

Hannu Krosing <hannuk@google.com> — 2024-06-19T10:55:10Z

Here is the output of nanosecond-precision pg_test_timing on M1 Macbook Air

/work/postgres/src/bin/pg_test_timing % ./pg_test_timing
Testing timing overhead for 3 seconds.
Per loop time including overhead: 21.54 ns
Histogram of timing durations:
   <= ns   % of total  running %      count
       0      49.1655    49.1655   68481688
       1       0.0000    49.1655          0
       3       0.0000    49.1655          0
       7       0.0000    49.1655          0
      15       0.0000    49.1655          0
      31       0.0000    49.1655          0
      63      50.6890    99.8545   70603742
     127       0.1432    99.9976     199411
     255       0.0015    99.9991       2065
     511       0.0001    99.9992         98
    1023       0.0001    99.9993        140
    2047       0.0002    99.9995        284
    4095       0.0000    99.9995         50
    8191       0.0000    99.9996         65
   16383       0.0002    99.9997        240
   32767       0.0001    99.9998        128
   65535       0.0001    99.9999         97
  131071       0.0000    99.9999         58
  262143       0.0000   100.0000         44
  524287       0.0000   100.0000         22
 1048575       0.0000   100.0000          7
 2097151       0.0000   100.0000          2
First 128 exact nanoseconds:
       0      49.1655    49.1655   68481688
      41      16.8964    66.0619   23534708
      42      33.7926    99.8545   47069034
      83       0.0835    99.9380     116362
      84       0.0419    99.9799      58349
     125       0.0177    99.9976      24700

As you see the 40 ns internal tick gets somehow blurred into
not-quite-40-ns timing step

On Linux / ARM Ampere where __builtin_readcyclecounter() works (it
compiles but crashes on Mac OS M1, I have not yet tested on Linux M1)
the tick is exactly 40 ns and I'd expect it to be the same on M1.


On Tue, Jun 18, 2024 at 5:08 PM Hannu Krosing <hannuk@google.com> wrote:
>
> I plan to send patch to pg_test_timing in a day or two
>
> the underlying time precision on modern linux seems to be
>
> 2 ns for some Intel CPUs
> 10 ns for Zen4
> 40 ns for ARM (Ampere)
>
> ---
> Hannu
>
>
>
> |
>
>
>
>
> On Tue, Jun 18, 2024 at 7:48 AM Andrey M. Borodin <x4mmm@yandex-team.ru> wrote:
>>
>>
>>
>> > On 19 Mar 2024, at 13:28, Peter Eisentraut <peter@eisentraut.org> wrote:
>> >
>> > I feel that we don't actually have any information about this portability concern.  Does anyone know what precision we can expect from gettimeofday()?  Can we expect the full microsecond precision usually?
>>
>> At PGConf.dev Hannu Krossing draw attention to pg_test_timing module. I’ve tried this module(slightly modified to measure nanoseconds) on some systems, and everywhere I found ~100ns resolution (95% of ticks fall into 64ns and 128ns buckets).
>>
>> I’ll add cc Hannu, and also pg_test_timing module authors Ants ang Greg. Maybe they can add some context.
>>
>>
>> Best regards, Andrey Borodin.

Re: What is a typical precision of gettimeofday()?

Peter Eisentraut <peter@eisentraut.org> — 2024-06-19T15:44:45Z

On 18.06.24 07:47, Andrey M. Borodin wrote:
> 
> 
>> On 19 Mar 2024, at 13:28, Peter Eisentraut <peter@eisentraut.org> wrote:
>>
>> I feel that we don't actually have any information about this portability concern.  Does anyone know what precision we can expect from gettimeofday()?  Can we expect the full microsecond precision usually?
> 
> At PGConf.dev Hannu Krossing draw attention to pg_test_timing module. I’ve tried this module(slightly modified to measure nanoseconds) on some systems, and everywhere I found ~100ns resolution (95% of ticks fall into 64ns and 128ns buckets).

AFAICT, pg_test_timing doesn't use gettimeofday(), so this doesn't 
really address the original question.

Re: What is a typical precision of gettimeofday()?

Tom Lane <tgl@sss.pgh.pa.us> — 2024-06-19T16:36:34Z

Peter Eisentraut <peter@eisentraut.org> writes:
> AFAICT, pg_test_timing doesn't use gettimeofday(), so this doesn't 
> really address the original question.

It's not exactly hard to make it do so (see attached).

I tried this on several different machines, and my conclusion is that
gettimeofday() reports full microsecond precision on any platform
anybody is likely to be running PG on today.  Even my one surviving
pet dinosaur, NetBSD 10 on PowerPC Mac (mamba), shows results like
this:

$ ./pg_test_timing
Testing timing overhead for 3 seconds.
Per loop time including overhead: 901.41 ns
Histogram of timing durations:
  < us   % of total      count
     1     10.46074     348148
     2     89.51495    2979181
     4      0.00574        191
     8      0.00430        143
    16      0.00691        230
    32      0.00376        125
    64      0.00012          4
   128      0.00303        101
   256      0.00027          9
   512      0.00009          3
  1024      0.00009          3

I also modified pg_test_timing to measure nanoseconds not
microseconds (second patch attached), and got this:

$ ./pg_test_timing
Testing timing overhead for 3 seconds.
Per loop time including overhead: 805.50 ns
Histogram of timing durations:
  < ns   % of total      count
     1     19.84234     739008
     2      0.00000          0
     4      0.00000          0
     8      0.00000          0
    16      0.00000          0
    32      0.00000          0
    64      0.00000          0
   128      0.00000          0
   256      0.00000          0
   512      0.00000          0
  1024     80.14013    2984739
  2048      0.00078         29
  4096      0.00658        245
  8192      0.00290        108
 16384      0.00252         94
 32768      0.00250         93
 65536      0.00016          6
131072      0.00185         69
262144      0.00008          3
524288      0.00008          3
1048576      0.00008          3

confirming that when the result changes it generally does so by 1usec.

Applying just the second patch, I find that clock_gettime on this
old hardware seems to be limited to 1us resolution, but on my more
modern machines (mac M1, x86_64) it can tick at 40ns or less.
Even a raspberry pi 4 shows

$ ./pg_test_timing 
Testing timing overhead for 3 seconds.
Per loop time including overhead: 69.12 ns
Histogram of timing durations:
  < ns   % of total      count
     1      0.00000          0
     2      0.00000          0
     4      0.00000          0
     8      0.00000          0
    16      0.00000          0
    32      0.00000          0
    64     37.59583   16317040
   128     62.38568   27076131
   256      0.01674       7265
   512      0.00002          8
  1024      0.00000          0
  2048      0.00000          0
  4096      0.00153        662
  8192      0.00019         83
 16384      0.00001          3
 32768      0.00001          5

suggesting that the clock_gettime resolution is better than 64 ns.

So I concur with Hannu that it's time to adjust pg_test_timing to
resolve nanoseconds not microseconds.  I gather he's created a
patch that does more than mine below, so I'll wait for that.

			regards, tom lane

Re: What is a typical precision of gettimeofday()?

Hannu Krosing <hannuk@google.com> — 2024-06-20T10:41:54Z

(resending to list and other CC:s )

Hi Tom

This is my current patch which also adds running % and optionally uses
faster way to count leading zeros, though I did not  see a change from
that.

It also bucketizes first 128 ns to get better overview of exact behaviour.

We may want to put reporting this behind a flag

---
Hannu

On Wed, Jun 19, 2024 at 6:36 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
>
> Peter Eisentraut <peter@eisentraut.org> writes:
> > AFAICT, pg_test_timing doesn't use gettimeofday(), so this doesn't
> > really address the original question.
>
> It's not exactly hard to make it do so (see attached).
>
> I tried this on several different machines, and my conclusion is that
> gettimeofday() reports full microsecond precision on any platform
> anybody is likely to be running PG on today.  Even my one surviving
> pet dinosaur, NetBSD 10 on PowerPC Mac (mamba), shows results like
> this:
>
> $ ./pg_test_timing
> Testing timing overhead for 3 seconds.
> Per loop time including overhead: 901.41 ns
> Histogram of timing durations:
>   < us   % of total      count
>      1     10.46074     348148
>      2     89.51495    2979181
>      4      0.00574        191
>      8      0.00430        143
>     16      0.00691        230
>     32      0.00376        125
>     64      0.00012          4
>    128      0.00303        101
>    256      0.00027          9
>    512      0.00009          3
>   1024      0.00009          3
>
> I also modified pg_test_timing to measure nanoseconds not
> microseconds (second patch attached), and got this:
>
> $ ./pg_test_timing
> Testing timing overhead for 3 seconds.
> Per loop time including overhead: 805.50 ns
> Histogram of timing durations:
>   < ns   % of total      count
>      1     19.84234     739008
>      2      0.00000          0
>      4      0.00000          0
>      8      0.00000          0
>     16      0.00000          0
>     32      0.00000          0
>     64      0.00000          0
>    128      0.00000          0
>    256      0.00000          0
>    512      0.00000          0
>   1024     80.14013    2984739
>   2048      0.00078         29
>   4096      0.00658        245
>   8192      0.00290        108
>  16384      0.00252         94
>  32768      0.00250         93
>  65536      0.00016          6
> 131072      0.00185         69
> 262144      0.00008          3
> 524288      0.00008          3
> 1048576      0.00008          3
>
> confirming that when the result changes it generally does so by 1usec.
>
> Applying just the second patch, I find that clock_gettime on this
> old hardware seems to be limited to 1us resolution, but on my more
> modern machines (mac M1, x86_64) it can tick at 40ns or less.
> Even a raspberry pi 4 shows
>
> $ ./pg_test_timing
> Testing timing overhead for 3 seconds.
> Per loop time including overhead: 69.12 ns
> Histogram of timing durations:
>   < ns   % of total      count
>      1      0.00000          0
>      2      0.00000          0
>      4      0.00000          0
>      8      0.00000          0
>     16      0.00000          0
>     32      0.00000          0
>     64     37.59583   16317040
>    128     62.38568   27076131
>    256      0.01674       7265
>    512      0.00002          8
>   1024      0.00000          0
>   2048      0.00000          0
>   4096      0.00153        662
>   8192      0.00019         83
>  16384      0.00001          3
>  32768      0.00001          5
>
> suggesting that the clock_gettime resolution is better than 64 ns.
>
> So I concur with Hannu that it's time to adjust pg_test_timing to
> resolve nanoseconds not microseconds.  I gather he's created a
> patch that does more than mine below, so I'll wait for that.
>
>                         regards, tom lane
>

Re: What is a typical precision of gettimeofday()?

Hannu Krosing <hannuk@google.com> — 2024-06-20T10:54:55Z

I also have a variant that uses the low-level CPU cycle counter
directly (attached)

It currently only works on clang, as it is done using
__builtin_readcyclecounter() in order to support both x64 and ARM.

This one is there to understand the overhead of the calculations when
going from cycle counter to POSIX time struct

This works OK with Clang, but we should probably not integrate this
directly into the code as it has some interesting corner cases. For
example Apple's clang does compile  __builtin_readcyclecounter() but
crashes with unknown instruction when trying to run it.

Therefore I have not integrated it into Makefile so if you want to use
it, just copy it into src/bin/pg_test_timing and run

cd src/bin/pgtest_timing
mv pg_test_timing.c pg_test_timing.c.backup
cp pg_test_cyclecounter.c pg_test_timing.c
make
mv pg_test_timing pg_test_cyclecounter
mv pg_test_timing.c.backup pg_test_timing.c

It gives output like

Testing timing overhead for 3 seconds.
Total 25000001 ticks in 1000000073 ns, 24999999.175000 ticks per ns
This CPU is running at 24999999 ticks / second, will run test for 74999997 ticks
loop_count 287130958Per loop time including overhead: 10.45 ns, min: 0
ticks (0.0 ns), same: 212854591
Total ticks in: 74999997, in: 3000000541 nr
Log2 histogram of timing durations:
 < ticks (    < ns)   % of total  running %    count
       1 (    40.0)      74.1315   74.1315  212854591
       2 (    80.0)      25.8655   99.9970   74267876
       4 (   160.0)       0.0000   99.9970          7
       8 (   320.0)       0.0000   99.9970          3
      16 (   640.0)       0.0000   99.9970          1
      32 (  1280.0)       0.0000   99.9971         27
      64 (  2560.0)       0.0012   99.9983       3439
     128 (  5120.0)       0.0016   99.9999       4683
     256 ( 10240.0)       0.0001  100.0000        265
     512 ( 20480.0)       0.0000  100.0000         37
    1024 ( 40960.0)       0.0000  100.0000         23
    2048 ( 81920.0)       0.0000  100.0000          6
First 64 ticks --
       0 (     0.0)      74.1315   74.1315  212854591
       1 (    40.0)      25.8655   99.9970   74267876
       2 (    80.0)       0.0000   99.9970          2
       3 (   120.0)       0.0000   99.9970          5
       4 (   160.0)       0.0000   99.9970          2
       6 (   240.0)       0.0000   99.9983          1
      13 (   520.0)       0.0000  100.0000          1
...
      59 (  2360.0)       0.0000  100.0000        140
      60 (  2400.0)       0.0001  100.0000        210
      61 (  2440.0)       0.0002  100.0000        497
      62 (  2480.0)       0.0002  100.0000        524
      63 (  2520.0)       0.0001  100.0000        391


If you run on some interesting hardware, please share the results.

If we her enough I will put them together in a spreadsheet and share

I also attach my lightning talk slides here

---
Hannu

On Thu, Jun 20, 2024 at 12:41 PM Hannu Krosing <hannuk@google.com> wrote:
>
> (resending to list and other CC:s )
>
> Hi Tom
>
> This is my current patch which also adds running % and optionally uses
> faster way to count leading zeros, though I did not  see a change from
> that.
>
> It also bucketizes first 128 ns to get better overview of exact behaviour.
>
> We may want to put reporting this behind a flag
>
> ---
> Hannu
>
> On Wed, Jun 19, 2024 at 6:36 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
> >
> > Peter Eisentraut <peter@eisentraut.org> writes:
> > > AFAICT, pg_test_timing doesn't use gettimeofday(), so this doesn't
> > > really address the original question.
> >
> > It's not exactly hard to make it do so (see attached).
> >
> > I tried this on several different machines, and my conclusion is that
> > gettimeofday() reports full microsecond precision on any platform
> > anybody is likely to be running PG on today.  Even my one surviving
> > pet dinosaur, NetBSD 10 on PowerPC Mac (mamba), shows results like
> > this:
> >
> > $ ./pg_test_timing
> > Testing timing overhead for 3 seconds.
> > Per loop time including overhead: 901.41 ns
> > Histogram of timing durations:
> >   < us   % of total      count
> >      1     10.46074     348148
> >      2     89.51495    2979181
> >      4      0.00574        191
> >      8      0.00430        143
> >     16      0.00691        230
> >     32      0.00376        125
> >     64      0.00012          4
> >    128      0.00303        101
> >    256      0.00027          9
> >    512      0.00009          3
> >   1024      0.00009          3
> >
> > I also modified pg_test_timing to measure nanoseconds not
> > microseconds (second patch attached), and got this:
> >
> > $ ./pg_test_timing
> > Testing timing overhead for 3 seconds.
> > Per loop time including overhead: 805.50 ns
> > Histogram of timing durations:
> >   < ns   % of total      count
> >      1     19.84234     739008
> >      2      0.00000          0
> >      4      0.00000          0
> >      8      0.00000          0
> >     16      0.00000          0
> >     32      0.00000          0
> >     64      0.00000          0
> >    128      0.00000          0
> >    256      0.00000          0
> >    512      0.00000          0
> >   1024     80.14013    2984739
> >   2048      0.00078         29
> >   4096      0.00658        245
> >   8192      0.00290        108
> >  16384      0.00252         94
> >  32768      0.00250         93
> >  65536      0.00016          6
> > 131072      0.00185         69
> > 262144      0.00008          3
> > 524288      0.00008          3
> > 1048576      0.00008          3
> >
> > confirming that when the result changes it generally does so by 1usec.
> >
> > Applying just the second patch, I find that clock_gettime on this
> > old hardware seems to be limited to 1us resolution, but on my more
> > modern machines (mac M1, x86_64) it can tick at 40ns or less.
> > Even a raspberry pi 4 shows
> >
> > $ ./pg_test_timing
> > Testing timing overhead for 3 seconds.
> > Per loop time including overhead: 69.12 ns
> > Histogram of timing durations:
> >   < ns   % of total      count
> >      1      0.00000          0
> >      2      0.00000          0
> >      4      0.00000          0
> >      8      0.00000          0
> >     16      0.00000          0
> >     32      0.00000          0
> >     64     37.59583   16317040
> >    128     62.38568   27076131
> >    256      0.01674       7265
> >    512      0.00002          8
> >   1024      0.00000          0
> >   2048      0.00000          0
> >   4096      0.00153        662
> >   8192      0.00019         83
> >  16384      0.00001          3
> >  32768      0.00001          5
> >
> > suggesting that the clock_gettime resolution is better than 64 ns.
> >
> > So I concur with Hannu that it's time to adjust pg_test_timing to
> > resolve nanoseconds not microseconds.  I gather he's created a
> > patch that does more than mine below, so I'll wait for that.
> >
> >                         regards, tom lane
> >

Re: What is a typical precision of gettimeofday()?

Hannu Krosing <hannuk@google.com> — 2024-06-20T11:08:57Z

Another thing I changed in reporting was to report <= ns instead of < ns

This was inspired by not wanting to report "zero ns" as "< 1 ns" and
easiest was to change them all to <=

On Thu, Jun 20, 2024 at 12:41 PM Hannu Krosing <hannuk@google.com> wrote:
>
> (resending to list and other CC:s )
>
> Hi Tom
>
> This is my current patch which also adds running % and optionally uses
> faster way to count leading zeros, though I did not  see a change from
> that.
>
> It also bucketizes first 128 ns to get better overview of exact behaviour.
>
> We may want to put reporting this behind a flag
>
> ---
> Hannu
>
> On Wed, Jun 19, 2024 at 6:36 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
> >
> > Peter Eisentraut <peter@eisentraut.org> writes:
> > > AFAICT, pg_test_timing doesn't use gettimeofday(), so this doesn't
> > > really address the original question.
> >
> > It's not exactly hard to make it do so (see attached).
> >
> > I tried this on several different machines, and my conclusion is that
> > gettimeofday() reports full microsecond precision on any platform
> > anybody is likely to be running PG on today.  Even my one surviving
> > pet dinosaur, NetBSD 10 on PowerPC Mac (mamba), shows results like
> > this:
> >
> > $ ./pg_test_timing
> > Testing timing overhead for 3 seconds.
> > Per loop time including overhead: 901.41 ns
> > Histogram of timing durations:
> >   < us   % of total      count
> >      1     10.46074     348148
> >      2     89.51495    2979181
> >      4      0.00574        191
> >      8      0.00430        143
> >     16      0.00691        230
> >     32      0.00376        125
> >     64      0.00012          4
> >    128      0.00303        101
> >    256      0.00027          9
> >    512      0.00009          3
> >   1024      0.00009          3
> >
> > I also modified pg_test_timing to measure nanoseconds not
> > microseconds (second patch attached), and got this:
> >
> > $ ./pg_test_timing
> > Testing timing overhead for 3 seconds.
> > Per loop time including overhead: 805.50 ns
> > Histogram of timing durations:
> >   < ns   % of total      count
> >      1     19.84234     739008
> >      2      0.00000          0
> >      4      0.00000          0
> >      8      0.00000          0
> >     16      0.00000          0
> >     32      0.00000          0
> >     64      0.00000          0
> >    128      0.00000          0
> >    256      0.00000          0
> >    512      0.00000          0
> >   1024     80.14013    2984739
> >   2048      0.00078         29
> >   4096      0.00658        245
> >   8192      0.00290        108
> >  16384      0.00252         94
> >  32768      0.00250         93
> >  65536      0.00016          6
> > 131072      0.00185         69
> > 262144      0.00008          3
> > 524288      0.00008          3
> > 1048576      0.00008          3
> >
> > confirming that when the result changes it generally does so by 1usec.
> >
> > Applying just the second patch, I find that clock_gettime on this
> > old hardware seems to be limited to 1us resolution, but on my more
> > modern machines (mac M1, x86_64) it can tick at 40ns or less.
> > Even a raspberry pi 4 shows
> >
> > $ ./pg_test_timing
> > Testing timing overhead for 3 seconds.
> > Per loop time including overhead: 69.12 ns
> > Histogram of timing durations:
> >   < ns   % of total      count
> >      1      0.00000          0
> >      2      0.00000          0
> >      4      0.00000          0
> >      8      0.00000          0
> >     16      0.00000          0
> >     32      0.00000          0
> >     64     37.59583   16317040
> >    128     62.38568   27076131
> >    256      0.01674       7265
> >    512      0.00002          8
> >   1024      0.00000          0
> >   2048      0.00000          0
> >   4096      0.00153        662
> >   8192      0.00019         83
> >  16384      0.00001          3
> >  32768      0.00001          5
> >
> > suggesting that the clock_gettime resolution is better than 64 ns.
> >
> > So I concur with Hannu that it's time to adjust pg_test_timing to
> > resolve nanoseconds not microseconds.  I gather he's created a
> > patch that does more than mine below, so I'll wait for that.
> >
> >                         regards, tom lane
> >

Re: What is a typical precision of gettimeofday()?

Tom Lane <tgl@sss.pgh.pa.us> — 2024-06-21T20:51:15Z

Hannu Krosing <hannuk@google.com> writes:
> This is my current patch which also adds running % and optionally uses
> faster way to count leading zeros, though I did not  see a change from
> that.

I've not read the patch yet, but I did create a CF entry [1]
to get some CI cycles on this.  The cfbot complains [2] about

[19:24:31.951] pg_test_timing.c: In function ‘output’:
[19:24:31.951] pg_test_timing.c:229:11: error: format ‘%ld’ expects argument of type ‘long int’, but argument 3 has type ‘int64’ {aka ‘long long int’} [-Werror=format=]
[19:24:31.951]   229 |    printf("%*ld    %*.4f  %*.4f %*lld\n",
[19:24:31.951]       |           ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
[19:24:31.951]   230 |       Max(8, len1), i,
[19:24:31.951]       |                     ~
[19:24:31.951]       |                     |
[19:24:31.951]       |                     int64 {aka long long int}

which seems a bit confused, but anyway you cannot assume that int64 is
a match for "%ld", or "%lld" either.  What we generally do for this
elsewhere is to explicitly cast printf arguments to long long int.

Also there's this on Windows:

[19:23:48.231] ../src/bin/pg_test_timing/pg_test_timing.c(162): warning C4067: unexpected tokens following preprocessor directive - expected a newline

			regards, tom lane

[1] https://commitfest.postgresql.org/48/5066/
[2] http://cfbot.cputube.org/highlights/all.html#5066

Re: What is a typical precision of gettimeofday()?

Tom Lane <tgl@sss.pgh.pa.us> — 2024-07-02T16:55:53Z

I wrote:
> Hannu Krosing <hannuk@google.com> writes:
>> This is my current patch which also adds running % and optionally uses
>> faster way to count leading zeros, though I did not  see a change from
>> that.

> I've not read the patch yet, but I did create a CF entry [1]
> to get some CI cycles on this.  The cfbot complains [2] about
> [ a couple of things ]

Here's a cleaned-up code patch addressing the cfbot complaints
and making the output logic a bit neater.

I think this is committable code-wise, but the documentation needs
work, if not indeed a complete rewrite.  The examples are now
horribly out of date, and it seems that the "Clock Hardware and Timing
Accuracy" section is quite obsolete as well, since it suggests that
the best available accuracy is ~100ns.

TBH I'm inclined to rip most of the OS-specific and hardware-specific
information out of there, as it's not something we're likely to
maintain well even if we got it right for current reality.

			regards, tom lane

Re: What is a typical precision of gettimeofday()?

Tom Lane <tgl@sss.pgh.pa.us> — 2024-07-02T17:20:14Z

BTW, getting back to the original point of the thread: I duplicated
Hannu's result showing that on Apple M1 the clock tick seems to be
about 40ns.  But look at what I got with the v2 patch on my main
workstation (full output attached):

$ ./pg_test_timing
...
Per loop time including overhead: 16.60 ns
...
Timing durations less than 128 ns:
      ns   % of total  running %      count
      15       3.2738     3.2738    5914914
      16      49.0772    52.3510   88668783
      17      36.4662    88.8172   65884173
      18       9.5639    98.3810   17279249
      19       1.5746    99.9556    2844873
      20       0.0416    99.9972      75125
      21       0.0004    99.9976        757
...

It sure looks like this is exact-to-the-nanosecond results,
since the modal values match the overall per-loop timing,
and there are no zero measurements.

This is a Dell tower from 2021, running RHEL8 on an Intel Xeon W-2245.
Not exactly top-of-the-line stuff.

			regards, tom lane

Re: What is a typical precision of gettimeofday()?

Hannu Krosing <hannuk@google.com> — 2024-07-02T17:31:21Z

Hi Tom,

On various Intel CPUs I got either steps close to single nanosecond or
sometimes a little more on older ones

One specific CPU moved in in 2 tick increments while the ration to ns
was 2,1/1 or 2100 ticks per microsecond.

On Zen4 AMD the step seems to  be 10 ns, even though the tick-to-ns
ratio is 2.6 / 1 , so reading ticks directly gives 26, 54, ...

Also, reading directly in ticks on M1 gave "loop time including
overhead: 2.13 ns" (attached code works on Clang, not sure about GCC)


I'll also take a look at the docs and try to propose something

Do we also need tests for this one ?

----
Hannu



On Tue, Jul 2, 2024 at 7:20 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
>
> BTW, getting back to the original point of the thread: I duplicated
> Hannu's result showing that on Apple M1 the clock tick seems to be
> about 40ns.  But look at what I got with the v2 patch on my main
> workstation (full output attached):
>
> $ ./pg_test_timing
> ...
> Per loop time including overhead: 16.60 ns
> ...
> Timing durations less than 128 ns:
>       ns   % of total  running %      count
>       15       3.2738     3.2738    5914914
>       16      49.0772    52.3510   88668783
>       17      36.4662    88.8172   65884173
>       18       9.5639    98.3810   17279249
>       19       1.5746    99.9556    2844873
>       20       0.0416    99.9972      75125
>       21       0.0004    99.9976        757
> ...
>
> It sure looks like this is exact-to-the-nanosecond results,
> since the modal values match the overall per-loop timing,
> and there are no zero measurements.
>
> This is a Dell tower from 2021, running RHEL8 on an Intel Xeon W-2245.
> Not exactly top-of-the-line stuff.
>
>                         regards, tom lane
>

Re: What is a typical precision of gettimeofday()?

Hannu Krosing <hannuk@google.com> — 2024-07-02T17:37:35Z

Also the step on M1 is slightly above 40ns (41.7ns) , but exactly 40
ns on Ampere Altra.

## M1 on MacBooc Air

Testing timing overhead for 3 seconds.
Total 24000177 ticks in 1000000056 ns, 24000175.655990 ticks per ns
This CPU is running at 24000175 ticks / second, will run test for 72000525 ticks
loop_count 1407639953Per loop time including overhead: 2.13 ns, min: 0
ticks (0.0 ns), same: 1335774969
Total ticks in: 72000525, in: 3000002260 nr
Log2(x+1) histogram of timing durations:
<= ticks ( <= ns) % of total running % count
0 ( 41.7) 94.8946 94.8946 1335774969
2 ( 83.3) 5.1051 99.9997 71861227
6 ( 166.7) 0.0001 99.9998 757
14 ( 333.3) 0.0000 99.9998 0
30 ( 666.7) 0.0002 99.9999 2193
62 ( 1333.3) 0.0000 100.0000 274
126 ( 2666.6) 0.0000 100.0000 446
254 ( 5333.3) 0.0000 100.0000 87
First 64 ticks --
0 ( 0.0) 94.8946 94.8946 1335774969
1 ( 41.7) 5.1032 99.9997 71834980
2 ( 83.3) 0.0019 99.9998 26247
3 ( 125.0) 0.0001 99.9998 757
15 ( 625.0) 0.0000 100.0000 1

## Ampere Altra

Testing timing overhead for 3 seconds.
Total 25000002 ticks in 1000000074 ns, 25000000.150000 ticks per ns
This CPU is running at 25000000 ticks / second, will run test for 75000000 ticks
loop_count 291630863Per loop time including overhead: 10.29 ns, min: 0
ticks (0.0 ns), same: 217288944
Total ticks in: 75000000, in: 3000000542 nr
Log2(x+1) histogram of timing durations:
<= ticks ( <= ns) % of total running % count
0 ( 40.0) 74.5082 74.5082 217288944
2 ( 80.0) 25.4886 99.9968 74332703
6 ( 160.0) 0.0000 99.9968 5
14 ( 320.0) 0.0000 99.9968 0
30 ( 640.0) 0.0000 99.9968 31
62 ( 1280.0) 0.0011 99.9979 3123
126 ( 2560.0) 0.0020 99.9999 5848
254 ( 5120.0) 0.0001 100.0000 149
510 ( 10240.0) 0.0000 100.0000 38
1022 ( 20480.0) 0.0000 100.0000 21
2046 ( 40960.0) 0.0000 100.0000 1
First 64 ticks --
0 ( 0.0) 74.5082 74.5082 217288944
1 ( 40.0) 25.4886 99.9968 74332699
2 ( 80.0) 0.0000 99.9968 4
3 ( 120.0) 0.0000 99.9968 1
4 ( 160.0) 0.0000 99.9968 3

On Tue, Jul 2, 2024 at 7:31 PM Hannu Krosing <hannuk@google.com> wrote:
>
> Hi Tom,
>
> On various Intel CPUs I got either steps close to single nanosecond or
> sometimes a little more on older ones
>
> One specific CPU moved in in 2 tick increments while the ration to ns
> was 2,1/1 or 2100 ticks per microsecond.
>
> On Zen4 AMD the step seems to  be 10 ns, even though the tick-to-ns
> ratio is 2.6 / 1 , so reading ticks directly gives 26, 54, ...
>
> Also, reading directly in ticks on M1 gave "loop time including
> overhead: 2.13 ns" (attached code works on Clang, not sure about GCC)
>
>
> I'll also take a look at the docs and try to propose something
>
> Do we also need tests for this one ?
>
> ----
> Hannu
>
>
>
> On Tue, Jul 2, 2024 at 7:20 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
> >
> > BTW, getting back to the original point of the thread: I duplicated
> > Hannu's result showing that on Apple M1 the clock tick seems to be
> > about 40ns.  But look at what I got with the v2 patch on my main
> > workstation (full output attached):
> >
> > $ ./pg_test_timing
> > ...
> > Per loop time including overhead: 16.60 ns
> > ...
> > Timing durations less than 128 ns:
> >       ns   % of total  running %      count
> >       15       3.2738     3.2738    5914914
> >       16      49.0772    52.3510   88668783
> >       17      36.4662    88.8172   65884173
> >       18       9.5639    98.3810   17279249
> >       19       1.5746    99.9556    2844873
> >       20       0.0416    99.9972      75125
> >       21       0.0004    99.9976        757
> > ...
> >
> > It sure looks like this is exact-to-the-nanosecond results,
> > since the modal values match the overall per-loop timing,
> > and there are no zero measurements.
> >
> > This is a Dell tower from 2021, running RHEL8 on an Intel Xeon W-2245.
> > Not exactly top-of-the-line stuff.
> >
> >                         regards, tom lane
> >

Re: What is a typical precision of gettimeofday()?

Tom Lane <tgl@sss.pgh.pa.us> — 2024-07-02T17:50:13Z

Hannu Krosing <hannuk@google.com> writes:
> Also, reading directly in ticks on M1 gave "loop time including
> overhead: 2.13 ns" (attached code works on Clang, not sure about GCC)

I don't think we should mess with that, given the portability
problems you mentioned upthread.

> I'll also take a look at the docs and try to propose something

OK.

> Do we also need tests for this one ?

Yeah, it was annoying me that we are eating the overhead of a TAP test
for pg_test_timing and yet it covers barely a third of the code [1].
We obviously can't expect any specific numbers out of a test, but I
was contemplating running "pg_test_timing -d 1" and just checking for
(a) zero exit code and (b) the expected header lines in the output.

			regards, tom lane

[1] https://coverage.postgresql.org/src/bin/pg_test_timing/pg_test_timing.c.gcov.html

Re: What is a typical precision of gettimeofday()?

Hannu Krosing <hannuk@google.com> — 2024-07-02T18:15:59Z

On Tue, Jul 2, 2024 at 7:50 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
>

> > Do we also need tests for this one ?
>
> Yeah, it was annoying me that we are eating the overhead of a TAP test
> for pg_test_timing and yet it covers barely a third of the code [1].
> We obviously can't expect any specific numbers out of a test, but I
> was contemplating running "pg_test_timing -d 1" and just checking for
> (a) zero exit code and (b) the expected header lines in the output.

At least "does it run" tests should be there -

For example with the current toolchain on MacOS I was able to compile
__builtin_readcyclecounter(); but it crashed when the result was
executed.

The same code compiled *and run* fine on same laptop with Ubuntu 24.04

We might also want to have some testing about available speedups from
pg_bitmanip.h being used, but that could be tricky to test in an
universal way.

--
Hannu

Re: What is a typical precision of gettimeofday()?

Tom Lane <tgl@sss.pgh.pa.us> — 2024-07-02T18:33:41Z

Hannu Krosing <hannuk@google.com> writes:
> At least "does it run" tests should be there -

> For example with the current toolchain on MacOS I was able to compile
> __builtin_readcyclecounter(); but it crashed when the result was
> executed.

> The same code compiled *and run* fine on same laptop with Ubuntu 24.04

> We might also want to have some testing about available speedups from
> pg_bitmanip.h being used, but that could be tricky to test in an
> universal way.

Keep in mind that pg_test_timing is not just some random exercise in a
vacuum.  The point of it IMV is to provide data about the performance
one can expect from the instr_time.h infrastructure, which bears on
what kind of resolution EXPLAIN ANALYZE and other features have.  So
if we did want to depend on read_tsc() or __builtin_readcyclecounter()
or what-have-you, the way to go about it would be to change
instr_time.h to compile code that uses that.  I would consider that
to be a separate patch from what we're doing to pg_test_timing here.

			regards, tom lane

Re: What is a typical precision of gettimeofday()?

Andrey Borodin <x4mmm@yandex-team.ru> — 2024-07-03T05:43:19Z

> On 2 Jul 2024, at 22:20, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> 
> It sure looks like this is exact-to-the-nanosecond results,
> since the modal values match the overall per-loop timing,
> and there are no zero measurements.

That’s a very interesting result, from the UUID POV!
If time is almost always advancing, using time readings instead of a counter is very reasonable: we have interprocess monotonicity almost for free.
Though time is advancing in a very small steps… RFC assumes that we use microseconds, I’m not sure it’s ok to use 10 more bits for nanoseconds…

Thanks!

Best regards, Andrey Borodin.

Re: What is a typical precision of gettimeofday()?

Tom Lane <tgl@sss.pgh.pa.us> — 2024-07-03T08:03:16Z

"Andrey M. Borodin" <x4mmm@yandex-team.ru> writes:
> That’s a very interesting result, from the UUID POV!
> If time is almost always advancing, using time readings instead of a counter is very reasonable: we have interprocess monotonicity almost for free.
> Though time is advancing in a very small steps… RFC assumes that we use microseconds, I’m not sure it’s ok to use 10 more bits for nanoseconds…

Keep in mind also that instr_time.h does not pretend to provide
real time --- the clock origin is arbitrary.  But these results
do give me additional confidence that gettimeofday() should be
good to the microsecond on any remotely-modern platform.

			regards, tom lane

Re: What is a typical precision of gettimeofday()?

Aleksander Alekseev <aleksander@timescale.com> — 2024-07-03T08:48:44Z

Hi,

> That’s a very interesting result, from the UUID POV!
> If time is almost always advancing, using time readings instead of a counter is very reasonable: we have interprocess monotonicity almost for free.
> Though time is advancing in a very small steps… RFC assumes that we use microseconds, I’m not sure it’s ok to use 10 more bits for nanoseconds…

A counter is mandatory since someone can for instance change the
system's time while the process is generating UUIDs. You can't
generally assume that local time of the system is monotonic.

-- 
Best regards,
Aleksander Alekseev

Re: What is a typical precision of gettimeofday()?

Hannu Krosing <hannuk@google.com> — 2024-07-03T10:31:27Z

On Wed, Jul 3, 2024 at 10:03 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:
Keep in mind also that instr_time.h does not pretend to provide
> real time --- the clock origin is arbitrary.  But these results
> do give me additional confidence that gettimeofday() should be
> good to the microsecond on any remotely-modern platform.

The only platform I have found where the resolution is only a
microsecond is RISC-V ( https://www.sifive.com/boards/hifive-unmatched
)

Everywhere else it seems to be much more precise.

--
Hannu

Re: What is a typical precision of gettimeofday()?

Andrey Borodin <x4mmm@yandex-team.ru> — 2024-07-03T10:38:14Z


> On 3 Jul 2024, at 13:48, Aleksander Alekseev <aleksander@timescale.com> wrote:
> 
> Hi,
> 
>> That’s a very interesting result, from the UUID POV!
>> If time is almost always advancing, using time readings instead of a counter is very reasonable: we have interprocess monotonicity almost for free.
>> Though time is advancing in a very small steps… RFC assumes that we use microseconds, I’m not sure it’s ok to use 10 more bits for nanoseconds…
> 
> A counter is mandatory since someone can for instance change the
> system's time while the process is generating UUIDs. You can't
> generally assume that local time of the system is monotonic.

AFAIR according to RFC when time jumps backwards, we just use time microseconds as a counter. Until time starts to advance again.


Best regards, Andrey Borodin.

Re: What is a typical precision of gettimeofday()?

Hannu Krosing <hannuk@google.com> — 2024-07-03T11:29:22Z

We currently do something similar with OIDs where we just keep
generating them and then testing for conflicts.

I don't think this is the best way to do it but it mostly works when
you can actually test for uniqueness, like for example in TOAST or
system tables.

Not sure this works even reasonably well for UUIDv7.

--
Hannu

On Wed, Jul 3, 2024 at 12:38 PM Andrey M. Borodin <x4mmm@yandex-team.ru> wrote:
>
>
>
> > On 3 Jul 2024, at 13:48, Aleksander Alekseev <aleksander@timescale.com> wrote:
> >
> > Hi,
> >
> >> That’s a very interesting result, from the UUID POV!
> >> If time is almost always advancing, using time readings instead of a counter is very reasonable: we have interprocess monotonicity almost for free.
> >> Though time is advancing in a very small steps… RFC assumes that we use microseconds, I’m not sure it’s ok to use 10 more bits for nanoseconds…
> >
> > A counter is mandatory since someone can for instance change the
> > system's time while the process is generating UUIDs. You can't
> > generally assume that local time of the system is monotonic.
>
> AFAIR according to RFC when time jumps backwards, we just use time microseconds as a counter. Until time starts to advance again.
>
>
> Best regards, Andrey Borodin.

Re: What is a typical precision of gettimeofday()?

Andrey Borodin <x4mmm@yandex-team.ru> — 2024-07-03T11:46:30Z

> On 3 Jul 2024, at 16:29, Hannu Krosing <hannuk@google.com> wrote:
> 
> We currently do something similar with OIDs where we just keep
> generating them and then testing for conflicts.
> 
> I don't think this is the best way to do it but it mostly works when
> you can actually test for uniqueness, like for example in TOAST or
> system tables.
> 
> Not sure this works even reasonably well for UUIDv7.

Uniqueness is ensured with extra 60+ bits of randomness. Timestamp and counter\microseconds are there to promote sortability (thus ensuring data locality).

Best regards, Andrey Borodin.

Re: What is a typical precision of gettimeofday()?

Aleksander Alekseev <aleksander@timescale.com> — 2024-07-03T11:47:26Z

Hi,

> We currently do something similar with OIDs where we just keep
> generating them and then testing for conflicts.
>
> I don't think this is the best way to do it but it mostly works when
> you can actually test for uniqueness, like for example in TOAST or
> system tables.
>
> Not sure this works even reasonably well for UUIDv7.

UUIDv7 is not guaranteed to be unique. It just does it best to reduce
the number of possible conflicts. So I don't think we should worry
about it.


-- 
Best regards,
Aleksander Alekseev

Re: What is a typical precision of gettimeofday()?

Andrey Borodin <x4mmm@yandex-team.ru> — 2024-11-02T08:37:26Z

> On 2 Jul 2024, at 20:55, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> 
> Here's a cleaned-up code patch addressing the cfbot complaints
> and making the output logic a bit neater.
> 
> I think this is committable code-wise, but the documentation needs
> work, if not indeed a complete rewrite.  The examples are now
> horribly out of date, and it seems that the "Clock Hardware and Timing
> Accuracy" section is quite obsolete as well, since it suggests that
> the best available accuracy is ~100ns.
> 
> TBH I'm inclined to rip most of the OS-specific and hardware-specific
> information out of there, as it's not something we're likely to
> maintain well even if we got it right for current reality.

Hi Tom!

This thread has associated CF entry which is marked as RwF [0]. But the change proved to be useful [1] in understanding what we can expect from time source.
It was requested many times before [2,3]. Reading through this thread it seems to me that my questions about application of the pg_test_timing somehow switched focus from this patch. However, I'd appreciate if it was applied. Nanoseconds seem important to me.
Let me know if I can help in any way. Thanks!

Best regards, Andrey Borodin.

[0] https://commitfest.postgresql.org/48/5066/
[1] https://www.postgresql.org/message-id/CAD21AoC4iAr7M_OgtHA0HZMezot68_0vwUCQjjXKk2iW89w0Jg@mail.gmail.com
[2] https://www.postgresql.org/message-id/CAMT0RQQJWNoki_vmckYb5J1j-BENBE0YtD6jJmVg--Hyvt7Wjg%40mail.gmail.com
[3] https://www.postgresql.org/message-id/flat/198ef658-a5b7-9862-2017-faf85d59e3a8%40gmail.com#37d8292e93ec34407a41e7cbf56e5481

Re: What is a typical precision of gettimeofday()?

Tom Lane <tgl@sss.pgh.pa.us> — 2024-11-02T14:27:05Z

"Andrey M. Borodin" <x4mmm@yandex-team.ru> writes:
> This thread has associated CF entry which is marked as RwF [0]. But the change proved to be useful [1] in understanding what we can expect from time source.
> It was requested many times before [2,3]. Reading through this thread it seems to me that my questions about application of the pg_test_timing somehow switched focus from this patch. However, I'd appreciate if it was applied. Nanoseconds seem important to me.
> Let me know if I can help in any way. Thanks!

Basically, I think the code is ready, but I was awaiting Hannu's
proposal on rewriting the documentation for pg_test_timing.
Do you want to have a go at that?

			regards, tom lane

Re: What is a typical precision of gettimeofday()?

Hannu Krosing <hannuk@google.com> — 2024-11-03T22:15:33Z

Hi Tom,

Did I understand correctly that you would prefer the documentation part to
be much smaller than it is now and all current the discussion about things
that are not strictly about the pg_test_timing to be not in the docs for it
?

My current plan is to move the other discussions around timing from th
edocs to PostgreSQL Wiki.

Would this be good ?

---
Best Regards
Hannu

On Sat, Nov 2, 2024 at 3:27 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:

> "Andrey M. Borodin" <x4mmm@yandex-team.ru> writes:
> > This thread has associated CF entry which is marked as RwF [0]. But the
> change proved to be useful [1] in understanding what we can expect from
> time source.
> > It was requested many times before [2,3]. Reading through this thread it
> seems to me that my questions about application of the pg_test_timing
> somehow switched focus from this patch. However, I'd appreciate if it was
> applied. Nanoseconds seem important to me.
> > Let me know if I can help in any way. Thanks!
>
> Basically, I think the code is ready, but I was awaiting Hannu's
> proposal on rewriting the documentation for pg_test_timing.
> Do you want to have a go at that?
>
>                         regards, tom lane
>

Re: What is a typical precision of gettimeofday()?

Tom Lane <tgl@sss.pgh.pa.us> — 2024-11-03T22:19:09Z

Hannu Krosing <hannuk@google.com> writes:
> Did I understand correctly that you would prefer the documentation part to
> be much smaller than it is now and all current the discussion about things
> that are not strictly about the pg_test_timing to be not in the docs for it
> ?

Well, I would like for the docs not to readily get stale again.
I don't foresee us maintaining this page better in future than
we have so far.

> My current plan is to move the other discussions around timing from th
> edocs to PostgreSQL Wiki.

That could work.

			regards, tom lane

Re: What is a typical precision of gettimeofday()?

Hannu Krosing <hannuk@google.com> — 2025-07-06T18:22:25Z

Here is the latest patch with documentation only for the utility
itself. Old general discussion moved to PostgreSQL Wiki with link to
it in "See Also " section

Also added a flag to select number of direct values to show

On Sun, Nov 3, 2024 at 11:19 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
>
> Hannu Krosing <hannuk@google.com> writes:
> > Did I understand correctly that you would prefer the documentation part to
> > be much smaller than it is now and all current the discussion about things
> > that are not strictly about the pg_test_timing to be not in the docs for it
> > ?
>
> Well, I would like for the docs not to readily get stale again.
> I don't foresee us maintaining this page better in future than
> we have so far.
>
> > My current plan is to move the other discussions around timing from th
> > edocs to PostgreSQL Wiki.
>
> That could work.
>
>                         regards, tom lane

Re: What is a typical precision of gettimeofday()?

Tom Lane <tgl@sss.pgh.pa.us> — 2025-07-07T21:38:29Z

Hannu Krosing <hannuk@google.com> writes:
> Here is the latest patch with documentation only for the utility
> itself. Old general discussion moved to PostgreSQL Wiki with link to
> it in "See Also " section

Thanks for continuing to work on this!

> Also added a flag to select number of direct values to show

Hmm ... I agree with having a way to control the length of that output,
but I don't think that specifying a count is the most useful way to
do it.  Particularly with a default of only 10, it seems way too
likely to cut off important information.

What do you think of instead specifying the limit as the maximum
running-percentage to print, with a default of say 99.99%?  That
gives me results like

Observed timing durations up to 99.9900%:
      ns   % of total  running %      count
      15       4.5452     4.5452    8313178
      16      58.3785    62.9237  106773354
      17      33.6840    96.6078   61607584
      18       3.1151    99.7229    5697480
      19       0.2638    99.9867     482570
      20       0.0093    99.9960      17054

In the attached I also made it print the largest observed
duration, which seems like it might be useful information.

As previously threatened, I also added a test case to
improve the code coverage.

			regards, tom lane

Re: What is a typical precision of gettimeofday()?

Hannu Krosing <hannuk@google.com> — 2025-07-07T23:39:59Z

On Mon, Jul 7, 2025 at 11:38 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
>

> > Also added a flag to select number of direct values to show
>
> Hmm ... I agree with having a way to control the length of that output,
> but I don't think that specifying a count is the most useful way to
> do it.  Particularly with a default of only 10, it seems way too
> likely to cut off important information.
>
> What do you think of instead specifying the limit as the maximum
> running-percentage to print, with a default of say 99.99%?  That
> gives me results like

I agree that percentage covered is a much better metric indeed.
And I am equally ok with a default of either 99.9% or 99.99%.

I briefly thought of it but decided a simple count is simpler to
explain, especially for some potential corner cases of % .
But as pg_test_timing is not part of the server we really do not need
to worry about rare edge cases.


> Observed timing durations up to 99.9900%:
>       ns   % of total  running %      count
>       15       4.5452     4.5452    8313178
>       16      58.3785    62.9237  106773354
>       17      33.6840    96.6078   61607584
>       18       3.1151    99.7229    5697480
>       19       0.2638    99.9867     482570
>       20       0.0093    99.9960      17054
>
> In the attached I also made it print the largest observed
> duration, which seems like it might be useful information.

Yes, a useful piece of information indeed.

> As previously threatened, I also added a test case to
> improve the code coverage.

Thanks!

Re: What is a typical precision of gettimeofday()?

Vik Fearing <vik@postgresfriends.org> — 2025-07-08T00:03:29Z

On 19/03/2024 09:28, Peter Eisentraut wrote:
> Does anyone know what precision we can expect from gettimeofday()?  
> Can we expect the full microsecond precision usually? 

Having read through this thread, is there any chance at all that we 
might be able to implement feature F555, “Enhanced seconds precision”?

I feel we may have dug ourselves into a hole with integer timestamps 
that span ridiculously long ranges.

-- 

Vik Fearing

Re: What is a typical precision of gettimeofday()?

Tom Lane <tgl@sss.pgh.pa.us> — 2025-07-08T00:37:15Z

Vik Fearing <vik@postgresfriends.org> writes:
> Having read through this thread, is there any chance at all that we 
> might be able to implement feature F555, “Enhanced seconds precision”?

Don't see how we could do that without an on-disk compatibility break
for timestamps.  Also, AFAICS there's no way to stuff nanosecond
precision and a reasonable timestamp range (at least a few thousand
years IMO) into 64 bits, so the compatibility break would include
expending more disk space.  Hard to believe that it's worth it.

(If we did decide to break compatibility, my own first priority
would be to make timestamptz actually include a timezone ...)

			regards, tom lane

Re: What is a typical precision of gettimeofday()?

Vik Fearing <vik@postgresfriends.org> — 2025-07-08T00:46:17Z

On 08/07/2025 02:37, Tom Lane wrote:
> Vik Fearing <vik@postgresfriends.org> writes:
>> Having read through this thread, is there any chance at all that we
>> might be able to implement feature F555, “Enhanced seconds precision”?
> Don't see how we could do that without an on-disk compatibility break
> for timestamps.


Yeah, I don't see how either.


> (If we did decide to break compatibility, my own first priority
> would be to make timestamptz actually include a timezone ...)


That comes with its own set of issues, but I don't want to hijack this 
thread more than I already have.

-- 

Vik Fearing

Re: What is a typical precision of gettimeofday()?

Tom Lane <tgl@sss.pgh.pa.us> — 2025-07-08T15:25:01Z

Hannu Krosing <hannuk@google.com> writes:
> On Mon, Jul 7, 2025 at 11:38 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> What do you think of instead specifying the limit as the maximum
>> running-percentage to print, with a default of say 99.99%?  That
>> gives me results like

> I agree that percentage covered is a much better metric indeed.
> And I am equally ok with a default of either 99.9% or 99.99%.

OK, pushed after a bit more fooling with the documentation.

			regards, tom lane

Re: What is a typical precision of gettimeofday()?

Tom Lane <tgl@sss.pgh.pa.us> — 2025-07-08T18:07:55Z

BTW, returning to the original topic of this thread:

The new exact-delays table from pg_test_timing is really quite
informative.  For example, on my M4 Macbook:

Observed timing durations up to 99.9900%:
      ns   % of total  running %      count
       0      62.2124    62.2124  118127987
      41      12.5826    74.7951   23891661
      42      25.1653    99.9604   47783489
      83       0.0194    99.9797      36744
      84       0.0096    99.9893      18193
     125       0.0020    99.9913       3784
...
   31042       0.0000   100.0000          1

The fact that the clock tick is about 40ns is extremely 
obvious in this presentation.

Even more interesting is what I got from an ancient PPC Macbook
(mamba's host, running NetBSD):

Testing timing overhead for 3 seconds.
Per loop time including overhead: 731.26 ns
...
Observed timing durations up to 99.9900%:
      ns   % of total  running %      count
     705      39.9162    39.9162    1637570
     706      17.6040    57.5203     722208
     759      18.6797    76.2000     766337
     760      23.7851    99.9851     975787
     813       0.0002    99.9853          9
     814       0.0004    99.9857         17
     868       0.0001    99.9858          4
     922       0.0001    99.9859          3
...
  564950       0.0000   100.0000          1

I had previously reported that that machine had microsecond
timing precision, but this shows that the real problem is that
it takes most of a microsecond to go 'round the timing loop.
It seems clear that the system clock ticks about every 50ns,
even on this decades-old hardware.

			regards, tom lane

Re: What is a typical precision of gettimeofday()?

Andrey Borodin <x4mmm@yandex-team.ru> — 2025-07-08T18:25:44Z

> On 8 Jul 2025, at 23:07, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> 
> The fact that the clock tick is about 40ns is extremely 
> obvious in this presentation.

FWIW while working on UUID v7 Masahiko found that if we try to read real time with clock_gettime(CLOCK_REALTIME,) measurement is truncated to microseconds.

Best regards, Andrey Borodin.

Re: What is a typical precision of gettimeofday()?

Tom Lane <tgl@sss.pgh.pa.us> — 2025-07-08T19:29:48Z

Andrey Borodin <x4mmm@yandex-team.ru> writes:
>> On 8 Jul 2025, at 23:07, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> The fact that the clock tick is about 40ns is extremely 
>> obvious in this presentation.

> FWIW while working on UUID v7 Masahiko found that if we try to read real time with clock_gettime(CLOCK_REALTIME,) measurement is truncated to microseconds.

Yeah.  Bear in mind that instr_time.h uses CLOCK_MONOTONIC_RAW on
macOS, so that's what we're looking at here.

			regards, tom lane

Re: What is a typical precision of gettimeofday()?

Hannu Krosing <hannuk@google.com> — 2025-07-08T19:37:07Z

On Tue, Jul 8, 2025 at 8:07 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
>
> BTW, returning to the original topic of this thread:
>
> The new exact-delays table from pg_test_timing is really quite
> informative.

Maybe we should collect some of it in the PostgreSQL Wiki for easy reference ?

I had some interesting results with some RISC-V SBC which were similar
to ARM but
seemed to indicate that the chosen "CPU CLOCK"  used by the
rtdsc-equivalent instruction was counting in exact multiples of a
nanosecond

And "the rtdsc-equivalent instruction" on both ARM and RISC-V is
reading a special register which exposes the faked "clock counter".


> For example, on my M4 Macbook:
>
> Observed timing durations up to 99.9900%:
>       ns   % of total  running %      count
>        0      62.2124    62.2124  118127987
>       41      12.5826    74.7951   23891661
>       42      25.1653    99.9604   47783489
>       83       0.0194    99.9797      36744
>       84       0.0096    99.9893      18193
>      125       0.0020    99.9913       3784
> ...
>    31042       0.0000   100.0000          1
>
> The fact that the clock tick is about 40ns is extremely
> obvious in this presentation.
>
> Even more interesting is what I got from an ancient PPC Macbook
> (mamba's host, running NetBSD):
>
> Testing timing overhead for 3 seconds.
> Per loop time including overhead: 731.26 ns
> ...
> Observed timing durations up to 99.9900%:
>       ns   % of total  running %      count
>      705      39.9162    39.9162    1637570
>      706      17.6040    57.5203     722208
>      759      18.6797    76.2000     766337
>      760      23.7851    99.9851     975787
>      813       0.0002    99.9853          9
>      814       0.0004    99.9857         17
>      868       0.0001    99.9858          4
>      922       0.0001    99.9859          3

Do we have a fencepost error in the limit code so that it stops before
printing out the 99.9900% limit row ?

The docs in your latest patch indicated that it prints out the row >=  99.9900%

---
Hannu

Re: What is a typical precision of gettimeofday()?

Tom Lane <tgl@sss.pgh.pa.us> — 2025-07-08T20:01:25Z

Hannu Krosing <hannuk@google.com> writes:
> On Tue, Jul 8, 2025 at 8:07 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> Even more interesting is what I got from an ancient PPC Macbook
>> (mamba's host, running NetBSD):
>> 
>> Testing timing overhead for 3 seconds.
>> Per loop time including overhead: 731.26 ns
>> ...
>> Observed timing durations up to 99.9900%:
>> ns   % of total  running %      count
>> 705      39.9162    39.9162    1637570
>> 706      17.6040    57.5203     722208
>> 759      18.6797    76.2000     766337
>> 760      23.7851    99.9851     975787
>> 813       0.0002    99.9853          9
>> 814       0.0004    99.9857         17
>> 868       0.0001    99.9858          4
>> 922       0.0001    99.9859          3

> Do we have a fencepost error in the limit code so that it stops before
> printing out the 99.9900% limit row ?

No, I think what's happening there is that we get to NUM_DIRECT before
reaching the 99.99% mark.  Running the test a bit longer, I do get a
hit at the next plausible 50ns step:

$ ./pg_test_timing -d 10
Testing timing overhead for 10 seconds.
Per loop time including overhead: 729.79 ns
Histogram of timing durations:
   <= ns   % of total  running %      count
       0       0.0000     0.0000          0
       1       0.0000     0.0000          0
       3       0.0000     0.0000          0
       7       0.0000     0.0000          0
      15       0.0000     0.0000          0
      31       0.0000     0.0000          0
      63       0.0000     0.0000          0
     127       0.0000     0.0000          0
     255       0.0000     0.0000          0
     511       0.0000     0.0000          0
    1023      99.9879    99.9879   13700887
    2047       0.0000    99.9880          2
    4095       0.0063    99.9942        859
    8191       0.0019    99.9962        267
   16383       0.0017    99.9978        227
   32767       0.0012    99.9990        166
   65535       0.0001    99.9992         16
  131071       0.0007    99.9998         90
  262143       0.0000    99.9998          5
  524287       0.0001    99.9999         11
 1048575       0.0001   100.0000         10

Observed timing durations up to 99.9900%:
      ns   % of total  running %      count
     705      40.7623    40.7623    5585475
     706      17.9732    58.7355    2462787
     759      18.1392    76.8747    2485525
     760      23.1129    99.9876    3167060
     813       0.0000    99.9877          5
     814       0.0002    99.9878         23
     868       0.0000    99.9879          5
     869       0.0000    99.9879          1
     922       0.0000    99.9879          3
     923       0.0000    99.9879          2
     976       0.0000    99.9879          1
...
  625444       0.0000   100.0000          1

amd the next step after that would be 1026 ns which is past
the NUM_DIRECT array size.

I considered raising NUM_DIRECT some more, but I think it'd be
overkill.  This machine is surely an order of magnitude slower
than anything anyone would consider of practical interest today.
Just for fun, though, I tried a run with NUM_DIRECT = 10240:

$ ./pg_test_timing -d 10
Testing timing overhead for 10 seconds.
Per loop time including overhead: 729.23 ns
Histogram of timing durations:
   <= ns   % of total  running %      count
       0       0.0000     0.0000          0
       1       0.0000     0.0000          0
       3       0.0000     0.0000          0
       7       0.0000     0.0000          0
      15       0.0000     0.0000          0
      31       0.0000     0.0000          0
      63       0.0000     0.0000          0
     127       0.0000     0.0000          0
     255       0.0000     0.0000          0
     511       0.0000     0.0000          0
    1023      99.9878    99.9878   13711494
    2047       0.0000    99.9878          5
    4095       0.0062    99.9941        854
    8191       0.0021    99.9962        289
   16383       0.0017    99.9979        236
   32767       0.0011    99.9990        153
   65535       0.0002    99.9992         24
  131071       0.0006    99.9998         85
  262143       0.0001    99.9999          8
  524287       0.0001    99.9999          9
 1048575       0.0001   100.0000          7
 2097151       0.0000   100.0000          0
 4194303       0.0000   100.0000          0
 8388607       0.0000   100.0000          0
16777215       0.0000   100.0000          0
33554431       0.0000   100.0000          1
67108863       0.0000   100.0000          1

Observed timing durations up to 99.9900%:
      ns   % of total  running %      count
     705      50.3534    50.3534    6905051
     706      22.1988    72.5522    3044153
     759      12.0613    84.6135    1653990
     760      15.3732    99.9867    2108150
     813       0.0000    99.9867          2
     814       0.0002    99.9869         27
     868       0.0006    99.9875         85
     869       0.0000    99.9876          2
     922       0.0001    99.9877         20
     923       0.0001    99.9878          9
     976       0.0000    99.9878          2
     977       0.0000    99.9878          3
    1031       0.0000    99.9878          4
    1248       0.0000    99.9878          1
    2550       0.0002    99.9880         26
    2604       0.0008    99.9889        114
    2605       0.0002    99.9891         30
    2658       0.0005    99.9896         75
    2659       0.0004    99.9901         61
...
65362171       0.0000   100.0000          1

This is probably showing something interesting about the
behavior of NetBSD's scheduler, but I dunno what exactly.

			regards, tom lane

Re: What is a typical precision of gettimeofday()?

Tom Lane <tgl@sss.pgh.pa.us> — 2025-07-08T22:17:43Z

Hannu Krosing <hannuk@google.com> writes:
> On Tue, Jul 8, 2025 at 10:01 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> No, I think what's happening there is that we get to NUM_DIRECT before
>> reaching the 99.99% mark.

> Makes sense.
> Should we change the header to something like
> "Showing values covering up to 99.9900% of total observed timing
> durations below 1 us. "

I think that'd just confuse people more not less.

> And maybe 10,001 would be a better value for collection, especially on
> older machines which could in fact have some wose timer resolution ?

I don't have any objection to boosting NUM_DIRECT to 10K or so.
It will cause the stats display loop to take microscopically longer,
but that shouldn't matter, even on slow machines.

One other thing that bothers me as I look at the output is

	Per loop time including overhead: 731.26 ns

That's stated in a way that makes it sound like that is a
very solid number, when in fact it's just the average.
We see from these test cases that there are frequently
a few outliers that are far from the average.  I'm tempted
to rephrase as

	Average loop time including overhead: 731.26 ns

or some variant of that.  Thoughts?

			regards, tom lane

Re: What is a typical precision of gettimeofday()?

Laurenz Albe <laurenz.albe@cybertec.at> — 2025-07-09T06:42:46Z

On Tue, 2025-07-08 at 18:17 -0400, Tom Lane wrote:
> One other thing that bothers me as I look at the output is
> 
> 	Per loop time including overhead: 731.26 ns
> 
> That's stated in a way that makes it sound like that is a
> very solid number, when in fact it's just the average.
> We see from these test cases that there are frequently
> a few outliers that are far from the average.  I'm tempted
> to rephrase as
> 
> 	Average loop time including overhead: 731.26 ns
> 
> or some variant of that.  Thoughts?

I think that is a good idea.

Yours,
Laurenz Albe

Re: What is a typical precision of gettimeofday()?

Hannu Krosing <hannuk@google.com> — 2025-07-09T11:14:06Z

Yes, this should say average

On Wed, Jul 9, 2025 at 8:42 AM Laurenz Albe <laurenz.albe@cybertec.at> wrote:
>
> On Tue, 2025-07-08 at 18:17 -0400, Tom Lane wrote:
> > One other thing that bothers me as I look at the output is
> >
> >       Per loop time including overhead: 731.26 ns
> >
> > That's stated in a way that makes it sound like that is a
> > very solid number, when in fact it's just the average.
> > We see from these test cases that there are frequently
> > a few outliers that are far from the average.  I'm tempted
> > to rephrase as
> >
> >       Average loop time including overhead: 731.26 ns
> >
> > or some variant of that.  Thoughts?
>
> I think that is a good idea.
>
> Yours,
> Laurenz Albe

Re: What is a typical precision of gettimeofday()?

Tom Lane <tgl@sss.pgh.pa.us> — 2025-07-09T15:33:18Z

Hannu Krosing <hannuk@google.com> writes:
> Yes, this should say average

OK, I tweaked that and increased NUM_DIRECT to 10000,
along with a couple of nitpicky code improvements.

			regards, tom lane

Re: What is a typical precision of gettimeofday()?

Bernd Helmle <mailings@oopsware.de> — 2025-07-11T09:56:28Z

Am Dienstag, dem 08.07.2025 um 11:25 -0400 schrieb Tom Lane:
> Hannu Krosing <hannuk@google.com> writes:
> > On Mon, Jul 7, 2025 at 11:38 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:
> > > What do you think of instead specifying the limit as the maximum
> > > running-percentage to print, with a default of say 99.99%?  That
> > > gives me results like
> 
> > I agree that percentage covered is a much better metric indeed.
> > And I am equally ok with a default of either 99.9% or 99.99%.
> 
> OK, pushed after a bit more fooling with the documentation.

FYI, since this commit TAP test pg_test_timing/001_basic on my machine
with de_DE.UTF8 locale keeps failing with:

stderr:
#   Failed test 'pg_test_timing: sanity check: matches'

[...]

# Observed timing durations up to 99,9900%:
#       ns   % of total  running %      count
#       20      60,2761    60,2761   25185754
#       21       2,3724    62,6485     991291
#       30      35,0016    97,6501   14625052
#       31       2,1129    99,7631     882874
#       40       0,2038    99,9669      85169
#       41       0,0166    99,9835       6933
#       50       0,0086    99,9921       3584
# ...
#   230806       0,0000   100,0000          1
# '
#     doesn't match '(?^sx:
# Testing\ timing\ overhead\ for\ 1\ second\..*
# Histogram\ of\ timing\ durations\:.*
# Observed\ timing\ durations\ up\ to\ 99\.9900\%\:
# )'
# Looks like you failed 1 test of 18.

(test program exited with status code 1)

Of course this is because of the localized comma in 99,9900%, as
executing with

LANG=C meson test -q --print-errorlogs pg_test_timing/001_basic

let this test succeed.

	Bernd

Re: What is a typical precision of gettimeofday()?

Tom Lane <tgl@sss.pgh.pa.us> — 2025-07-11T15:27:29Z

Bernd Helmle <mailings@oopsware.de> writes:
> FYI, since this commit TAP test pg_test_timing/001_basic on my machine
> with de_DE.UTF8 locale keeps failing with:
> ...
> Of course this is because of the localized comma in 99,9900%

Ah.  I had the idea that we forced C locale in TAP tests,
but evidently that's not happening here.  Will fix, thanks
for the report!

			regards, tom lane