Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1sJyIi-007dhq-Mg for pgsql-hackers@arkaria.postgresql.org; Wed, 19 Jun 2024 16:36:48 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.94.2) (envelope-from ) id 1sJyIf-002LoR-J4 for pgsql-hackers@arkaria.postgresql.org; Wed, 19 Jun 2024 16:36:46 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1sJyIf-002LoJ-8W for pgsql-hackers@lists.postgresql.org; Wed, 19 Jun 2024 16:36:46 +0000 Received: from sss.pgh.pa.us ([68.162.161.243]) by magus.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1sJyIZ-002Uxm-8X for pgsql-hackers@postgresql.org; Wed, 19 Jun 2024 16:36:45 +0000 Received: from sss1.sss.pgh.pa.us (localhost [127.0.0.1]) by sss.pgh.pa.us (8.15.2/8.15.2) with ESMTP id 45JGaY2N130997; Wed, 19 Jun 2024 12:36:34 -0400 From: Tom Lane To: Peter Eisentraut cc: "Andrey M. Borodin" , Hannu Krosing , pgsql-hackers Subject: Re: What is a typical precision of gettimeofday()? In-reply-to: <9e7b21e7-4c63-4299-87f4-780a0699a7d8@eisentraut.org> References: <47AEACEE-E5CC-40E4-8611-01F3A465AF16@yandex-team.ru> <9e7b21e7-4c63-4299-87f4-780a0699a7d8@eisentraut.org> Comments: In-reply-to Peter Eisentraut message dated "Wed, 19 Jun 2024 17:44:45 +0200" MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="----- =_aaaaaaaaaa0" Content-ID: <130913.1718814955.0@sss.pgh.pa.us> Date: Wed, 19 Jun 2024 12:36:34 -0400 Message-ID: <130996.1718814994@sss.pgh.pa.us> List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk ------- =_aaaaaaaaaa0 Content-Type: text/plain; charset="us-ascii" Content-ID: <130913.1718814955.1@sss.pgh.pa.us> Peter Eisentraut 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 ------- =_aaaaaaaaaa0 Content-Type: text/x-diff; name="use-gettimeofday-for-instr_time.patch"; charset="us-ascii" Content-ID: <130913.1718814955.2@sss.pgh.pa.us> Content-Description: use-gettimeofday-for-instr_time.patch Content-Transfer-Encoding: quoted-printable diff --git a/src/include/portability/instr_time.h b/src/include/portabilit= y/instr_time.h index a6fc1922f2..5509d23d2f 100644 --- a/src/include/portability/instr_time.h +++ b/src/include/portability/instr_time.h @@ -84,7 +84,7 @@ typedef struct instr_time = /* Use clock_gettime() */ = -#include +#include = /* * The best clockid to use according to the POSIX spec is CLOCK_MONOTONIC= , @@ -111,10 +111,10 @@ static inline instr_time pg_clock_gettime_ns(void) { instr_time now; - struct timespec tmp; + struct timeval tmp; = - clock_gettime(PG_INSTR_CLOCK, &tmp); - now.ticks =3D tmp.tv_sec * NS_PER_S + tmp.tv_nsec; + gettimeofday(&tmp, NULL); + now.ticks =3D tmp.tv_sec * NS_PER_S + tmp.tv_usec * 1000; = return now; } ------- =_aaaaaaaaaa0 Content-Type: text/x-diff; name="measure-nsec-in-pg_test_timing.patch"; charset="us-ascii" Content-ID: <130913.1718814955.3@sss.pgh.pa.us> Content-Description: measure-nsec-in-pg_test_timing.patch Content-Transfer-Encoding: quoted-printable diff --git a/src/bin/pg_test_timing/pg_test_timing.c b/src/bin/pg_test_tim= ing/pg_test_timing.c index c29d6f8762..ea2b565b14 100644 --- a/src/bin/pg_test_timing/pg_test_timing.c +++ b/src/bin/pg_test_timing/pg_test_timing.c @@ -133,7 +133,7 @@ test_timing(unsigned int duration) total_time =3D duration > 0 ? duration * INT64CONST(1000000) : 0; = INSTR_TIME_SET_CURRENT(start_time); - cur =3D INSTR_TIME_GET_MICROSEC(start_time); + cur =3D INSTR_TIME_GET_NANOSEC(start_time); = while (time_elapsed < total_time) { @@ -142,7 +142,7 @@ test_timing(unsigned int duration) = prev =3D cur; INSTR_TIME_SET_CURRENT(temp); - cur =3D INSTR_TIME_GET_MICROSEC(temp); + cur =3D INSTR_TIME_GET_NANOSEC(temp); diff =3D cur - prev; = /* Did time go backwards? */ @@ -183,7 +183,7 @@ output(uint64 loop_count) { int64 max_bit =3D 31, i; - char *header1 =3D _("< us"); + char *header1 =3D _("< ns"); char *header2 =3D /* xgettext:no-c-format */ _("% of total"); char *header3 =3D _("count"); int len1 =3D strlen(header1); ------- =_aaaaaaaaaa0--