public inbox for [email protected]
help / color / mirror / Atom feed[PATCH 1/3] bootstrap: convert Typ to a List*
17+ messages / 5 participants
[nested] [flat]
* [PATCH 1/3] bootstrap: convert Typ to a List*
@ 2020-11-20 02:48 Justin Pryzby <[email protected]>
0 siblings, 0 replies; 17+ messages in thread
From: Justin Pryzby @ 2020-11-20 02:48 UTC (permalink / raw)
---
src/backend/bootstrap/bootstrap.c | 69 ++++++++++++++-----------------
1 file changed, 31 insertions(+), 38 deletions(-)
diff --git a/src/backend/bootstrap/bootstrap.c b/src/backend/bootstrap/bootstrap.c
index 6f615e6622..18eb62ca47 100644
--- a/src/backend/bootstrap/bootstrap.c
+++ b/src/backend/bootstrap/bootstrap.c
@@ -159,7 +159,7 @@ struct typmap
FormData_pg_type am_typ;
};
-static struct typmap **Typ = NULL;
+static List *Typ = NIL; /* List of struct typmap* */
static struct typmap *Ap = NULL;
static Datum values[MAXATTR]; /* current row's attribute values */
@@ -597,7 +597,7 @@ boot_openrel(char *relname)
* pg_type must be filled before any OPEN command is executed, hence we
* can now populate the Typ array if we haven't yet.
*/
- if (Typ == NULL)
+ if (Typ == NIL)
populate_typ_array();
if (boot_reldesc != NULL)
@@ -688,7 +688,7 @@ DefineAttr(char *name, char *type, int attnum, int nullness)
typeoid = gettype(type);
- if (Typ != NULL)
+ if (Typ != NIL)
{
attrtypes[attnum]->atttypid = Ap->am_oid;
attrtypes[attnum]->attlen = Ap->am_typ.typlen;
@@ -877,36 +877,25 @@ populate_typ_array(void)
Relation rel;
TableScanDesc scan;
HeapTuple tup;
- int nalloc;
- int i;
-
- Assert(Typ == NULL);
- nalloc = 512;
- Typ = (struct typmap **)
- MemoryContextAlloc(TopMemoryContext, nalloc * sizeof(struct typmap *));
+ Assert(Typ == NIL);
rel = table_open(TypeRelationId, NoLock);
scan = table_beginscan_catalog(rel, 0, NULL);
- i = 0;
while ((tup = heap_getnext(scan, ForwardScanDirection)) != NULL)
{
Form_pg_type typForm = (Form_pg_type) GETSTRUCT(tup);
+ struct typmap *newtyp;
+ MemoryContext old;
- /* make sure there will be room for a trailing NULL pointer */
- if (i >= nalloc - 1)
- {
- nalloc *= 2;
- Typ = (struct typmap **)
- repalloc(Typ, nalloc * sizeof(struct typmap *));
- }
- Typ[i] = (struct typmap *)
- MemoryContextAlloc(TopMemoryContext, sizeof(struct typmap));
- Typ[i]->am_oid = typForm->oid;
- memcpy(&(Typ[i]->am_typ), typForm, sizeof(Typ[i]->am_typ));
- i++;
+ old = MemoryContextSwitchTo(TopMemoryContext);
+ newtyp = (struct typmap *) palloc(sizeof(struct typmap));
+ Typ = lappend(Typ, newtyp);
+ MemoryContextSwitchTo(old);
+
+ newtyp->am_oid = typForm->oid;
+ memcpy(&newtyp->am_typ, typForm, sizeof(newtyp->am_typ));
}
- Typ[i] = NULL; /* Fill trailing NULL pointer */
table_endscan(scan);
table_close(rel, NoLock);
}
@@ -925,16 +914,17 @@ populate_typ_array(void)
static Oid
gettype(char *type)
{
- if (Typ != NULL)
+ if (Typ != NIL)
{
- struct typmap **app;
+ ListCell *lc;
- for (app = Typ; *app != NULL; app++)
+ foreach (lc, Typ)
{
- if (strncmp(NameStr((*app)->am_typ.typname), type, NAMEDATALEN) == 0)
+ struct typmap *app = lfirst(lc);
+ if (strncmp(NameStr(app->am_typ.typname), type, NAMEDATALEN) == 0)
{
- Ap = *app;
- return (*app)->am_oid;
+ Ap = app;
+ return app->am_oid;
}
}
}
@@ -980,14 +970,17 @@ boot_get_type_io_data(Oid typid,
if (Typ != NULL)
{
/* We have the boot-time contents of pg_type, so use it */
- struct typmap **app;
- struct typmap *ap;
-
- app = Typ;
- while (*app && (*app)->am_oid != typid)
- ++app;
- ap = *app;
- if (ap == NULL)
+ struct typmap *ap = NULL;
+ ListCell *lc;
+
+ foreach (lc, Typ)
+ {
+ ap = lfirst(lc);
+ if (ap->am_oid == typid)
+ break;
+ }
+
+ if (!ap || ap->am_oid != typid)
elog(ERROR, "type OID %u not found in Typ list", typid);
*typlen = ap->am_typ.typlen;
--
2.26.2
--------------76B8D0DC8AE327D516738282
Content-Type: text/x-patch; charset=UTF-8;
name="0002-Allow-composite-types-in-bootstrap-20210108.patch"
Content-Transfer-Encoding: 7bit
Content-Disposition: attachment;
filename="0002-Allow-composite-types-in-bootstrap-20210108.patch"
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: What is a typical precision of gettimeofday()?
@ 2024-06-18 05:47 Andrey M. Borodin <[email protected]>
0 siblings, 2 replies; 17+ messages in thread
From: Andrey M. Borodin @ 2024-06-18 05:47 UTC (permalink / raw)
To: Peter Eisentraut <[email protected]>; Hannu Krosing <[email protected]>; Ants Aasma <[email protected]>; [email protected]; +Cc: pgsql-hackers
> On 19 Mar 2024, at 13:28, Peter Eisentraut <[email protected]> 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.
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: What is a typical precision of gettimeofday()?
@ 2024-06-18 15:08 Hannu Krosing <[email protected]>
parent: Andrey M. Borodin <[email protected]>
1 sibling, 1 reply; 17+ messages in thread
From: Hannu Krosing @ 2024-06-18 15:08 UTC (permalink / raw)
To: Andrey M. Borodin <[email protected]>; +Cc: Peter Eisentraut <[email protected]>; Ants Aasma <[email protected]>; [email protected]; pgsql-hackers
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 <[email protected]>
wrote:
>
>
> > On 19 Mar 2024, at 13:28, Peter Eisentraut <[email protected]> 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.
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: What is a typical precision of gettimeofday()?
@ 2024-06-19 10:55 Hannu Krosing <[email protected]>
parent: Hannu Krosing <[email protected]>
0 siblings, 0 replies; 17+ messages in thread
From: Hannu Krosing @ 2024-06-19 10:55 UTC (permalink / raw)
To: Peter Eisentraut <[email protected]>; +Cc: Ants Aasma <[email protected]>; [email protected]; pgsql-hackers; Andrey M. Borodin <[email protected]>
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 <[email protected]> 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 <[email protected]> wrote:
>>
>>
>>
>> > On 19 Mar 2024, at 13:28, Peter Eisentraut <[email protected]> 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.
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: What is a typical precision of gettimeofday()?
@ 2024-06-19 15:44 Peter Eisentraut <[email protected]>
parent: Andrey M. Borodin <[email protected]>
1 sibling, 1 reply; 17+ messages in thread
From: Peter Eisentraut @ 2024-06-19 15:44 UTC (permalink / raw)
To: Andrey M. Borodin <[email protected]>; Hannu Krosing <[email protected]>; +Cc: pgsql-hackers
On 18.06.24 07:47, Andrey M. Borodin wrote:
>
>
>> On 19 Mar 2024, at 13:28, Peter Eisentraut <[email protected]> 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.
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: What is a typical precision of gettimeofday()?
@ 2024-06-19 16:36 Tom Lane <[email protected]>
parent: Peter Eisentraut <[email protected]>
0 siblings, 1 reply; 17+ messages in thread
From: Tom Lane @ 2024-06-19 16:36 UTC (permalink / raw)
To: Peter Eisentraut <[email protected]>; +Cc: Andrey M. Borodin <[email protected]>; Hannu Krosing <[email protected]>; pgsql-hackers
Peter Eisentraut <[email protected]> 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
Attachments:
[text/x-diff] use-gettimeofday-for-instr_time.patch (747B, ../../[email protected]/2-use-gettimeofday-for-instr_time.patch)
download | inline diff:
diff --git a/src/include/portability/instr_time.h b/src/include/portability/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 <time.h>
+#include <sys/time.h>
/*
* 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 = tmp.tv_sec * NS_PER_S + tmp.tv_nsec;
+ gettimeofday(&tmp, NULL);
+ now.ticks = tmp.tv_sec * NS_PER_S + tmp.tv_usec * 1000;
return now;
}
[text/x-diff] measure-nsec-in-pg_test_timing.patch (1.0K, ../../[email protected]/3-measure-nsec-in-pg_test_timing.patch)
download | inline diff:
diff --git a/src/bin/pg_test_timing/pg_test_timing.c b/src/bin/pg_test_timing/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 = duration > 0 ? duration * INT64CONST(1000000) : 0;
INSTR_TIME_SET_CURRENT(start_time);
- cur = INSTR_TIME_GET_MICROSEC(start_time);
+ cur = INSTR_TIME_GET_NANOSEC(start_time);
while (time_elapsed < total_time)
{
@@ -142,7 +142,7 @@ test_timing(unsigned int duration)
prev = cur;
INSTR_TIME_SET_CURRENT(temp);
- cur = INSTR_TIME_GET_MICROSEC(temp);
+ cur = INSTR_TIME_GET_NANOSEC(temp);
diff = cur - prev;
/* Did time go backwards? */
@@ -183,7 +183,7 @@ output(uint64 loop_count)
{
int64 max_bit = 31,
i;
- char *header1 = _("< us");
+ char *header1 = _("< ns");
char *header2 = /* xgettext:no-c-format */ _("% of total");
char *header3 = _("count");
int len1 = strlen(header1);
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: What is a typical precision of gettimeofday()?
@ 2024-06-20 10:41 Hannu Krosing <[email protected]>
parent: Tom Lane <[email protected]>
0 siblings, 1 reply; 17+ messages in thread
From: Hannu Krosing @ 2024-06-20 10:41 UTC (permalink / raw)
To: Tom Lane <[email protected]>; +Cc: Peter Eisentraut <[email protected]>; Andrey M. Borodin <[email protected]>; pgsql-hackers
(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 <[email protected]> wrote:
>
> Peter Eisentraut <[email protected]> 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
>
Attachments:
[text/x-patch] pg_test_timing.nanoseconds.patch (3.5K, ../../CAMT0RQSdKQra6QC4b+eAynpqZ0SYdHDfGBBE7hty33OD9jx7Jg@mail.gmail.com/2-pg_test_timing.nanoseconds.patch)
download | inline diff:
diff --git a/src/bin/pg_test_timing/pg_test_timing.c b/src/bin/pg_test_timing/pg_test_timing.c
index c29d6f8762..20b2785f50 100644
--- a/src/bin/pg_test_timing/pg_test_timing.c
+++ b/src/bin/pg_test_timing/pg_test_timing.c
@@ -19,9 +19,12 @@ static void handle_args(int argc, char *argv[]);
static uint64 test_timing(unsigned int duration);
static void output(uint64 loop_count);
-/* record duration in powers of 2 microseconds */
+/* record duration in powers of 2 nanoseconds */
long long int histogram[32];
+/* record duration of first 128 ns directly */
+long long int direct_histogram[128];
+
int
main(int argc, char *argv[])
{
@@ -130,10 +133,10 @@ test_timing(unsigned int duration)
end_time,
temp;
- total_time = duration > 0 ? duration * INT64CONST(1000000) : 0;
+ total_time = duration > 0 ? duration * INT64CONST(1000000000) : 0;
INSTR_TIME_SET_CURRENT(start_time);
- cur = INSTR_TIME_GET_MICROSEC(start_time);
+ cur = INSTR_TIME_GET_NANOSEC(start_time);
while (time_elapsed < total_time)
{
@@ -142,7 +145,7 @@ test_timing(unsigned int duration)
prev = cur;
INSTR_TIME_SET_CURRENT(temp);
- cur = INSTR_TIME_GET_MICROSEC(temp);
+ cur = INSTR_TIME_GET_NANOSEC(temp);
diff = cur - prev;
/* Did time go backwards? */
@@ -153,19 +156,25 @@ test_timing(unsigned int duration)
exit(1);
}
+ if(likely(diff < 128))
+ direct_histogram[diff]++;
+
+#if defined(__has_builtin) && __has_builtin(__builtin_clz)
+ bits = 32 - __builtin_clz(diff);
+#else
/* What is the highest bit in the time diff? */
while (diff)
{
diff >>= 1;
bits++;
}
-
+#endif
/* Update appropriate duration bucket */
histogram[bits]++;
loop_count++;
INSTR_TIME_SUBTRACT(temp, start_time);
- time_elapsed = INSTR_TIME_GET_MICROSEC(temp);
+ time_elapsed = INSTR_TIME_GET_NANOSEC(temp);
}
INSTR_TIME_SET_CURRENT(end_time);
@@ -183,26 +192,46 @@ output(uint64 loop_count)
{
int64 max_bit = 31,
i;
- char *header1 = _("< us");
+ char *header1 = _("<= ns");
char *header2 = /* xgettext:no-c-format */ _("% of total");
+ char *header2a = /* xgettext:no-c-format */ _("running %");
char *header3 = _("count");
int len1 = strlen(header1);
int len2 = strlen(header2);
+ int len2a = strlen(header2a);
int len3 = strlen(header3);
+ float rprct;
/* find highest bit value */
while (max_bit > 0 && histogram[max_bit] == 0)
max_bit--;
printf(_("Histogram of timing durations:\n"));
- printf("%*s %*s %*s\n",
- Max(6, len1), header1,
+ printf("%*s %*s %*s %*s\n",
+ Max(8, len1), header1,
Max(10, len2), header2,
+ Max(10, len2a), header2a,
Max(10, len3), header3);
- for (i = 0; i <= max_bit; i++)
- printf("%*ld %*.5f %*lld\n",
- Max(6, len1), 1l << i,
- Max(10, len2) - 1, (double) histogram[i] * 100 / loop_count,
- Max(10, len3), histogram[i]);
+ for (i = 0, rprct=0; i <= max_bit; i++){
+ rprct += (double) histogram[i] * 100 / loop_count;
+ printf("%*ld %*.4f %*.4f %*lld\n",
+ Max(8, len1), (1l << i) - 1,
+ Max(10, len2) - 1, (double) histogram[i] * 100 / loop_count,
+ Max(10, len2a) - 1, rprct,
+ Max(10, len3), histogram[i]);
+ }
+
+ printf("First 128 nanoseconds:\n");
+ for (i = 0, rprct=0; i < 128; i++){
+ rprct += (double) direct_histogram[i] * 100 / loop_count;
+ if (direct_histogram[i])
+ printf("%*ld %*.4f %*.4f %*lld\n",
+ Max(8, len1), i,
+ Max(10, len2) - 1, (double) direct_histogram[i] * 100 / loop_count,
+ Max(10, len2a) - 1, rprct,
+ Max(10, len3), direct_histogram[i]);
+ }
+
}
+
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: What is a typical precision of gettimeofday()?
@ 2024-06-21 20:51 Tom Lane <[email protected]>
parent: Hannu Krosing <[email protected]>
0 siblings, 1 reply; 17+ messages in thread
From: Tom Lane @ 2024-06-21 20:51 UTC (permalink / raw)
To: Hannu Krosing <[email protected]>; +Cc: Peter Eisentraut <[email protected]>; Andrey M. Borodin <[email protected]>; pgsql-hackers
Hannu Krosing <[email protected]> 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
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: What is a typical precision of gettimeofday()?
@ 2024-07-02 16:55 Tom Lane <[email protected]>
parent: Tom Lane <[email protected]>
0 siblings, 2 replies; 17+ messages in thread
From: Tom Lane @ 2024-07-02 16:55 UTC (permalink / raw)
To: Hannu Krosing <[email protected]>; +Cc: Peter Eisentraut <[email protected]>; Andrey M. Borodin <[email protected]>; pgsql-hackers
I wrote:
> Hannu Krosing <[email protected]> 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
Attachments:
[text/x-diff] v2-pg_test_timing-nanoseconds.patch (4.3K, ../../[email protected]/2-v2-pg_test_timing-nanoseconds.patch)
download | inline diff:
diff --git a/src/bin/pg_test_timing/pg_test_timing.c b/src/bin/pg_test_timing/pg_test_timing.c
index ce7aad4b25..a6a271aef1 100644
--- a/src/bin/pg_test_timing/pg_test_timing.c
+++ b/src/bin/pg_test_timing/pg_test_timing.c
@@ -9,19 +9,24 @@
#include <limits.h>
#include "getopt_long.h"
+#include "port/pg_bitutils.h"
#include "portability/instr_time.h"
static const char *progname;
static unsigned int test_duration = 3;
+/* record duration in powers of 2 nanoseconds */
+static long long int histogram[32];
+
+/* record counts of first 128 durations directly */
+#define NUM_DIRECT 128
+static long long int direct_histogram[NUM_DIRECT];
+
static void handle_args(int argc, char *argv[]);
static uint64 test_timing(unsigned int duration);
static void output(uint64 loop_count);
-/* record duration in powers of 2 microseconds */
-static long long int histogram[32];
-
int
main(int argc, char *argv[])
{
@@ -111,7 +116,6 @@ handle_args(int argc, char *argv[])
exit(1);
}
-
printf(ngettext("Testing timing overhead for %u second.\n",
"Testing timing overhead for %u seconds.\n",
test_duration),
@@ -130,19 +134,19 @@ test_timing(unsigned int duration)
end_time,
temp;
- total_time = duration > 0 ? duration * INT64CONST(1000000) : 0;
+ total_time = duration > 0 ? duration * INT64CONST(1000000000) : 0;
INSTR_TIME_SET_CURRENT(start_time);
- cur = INSTR_TIME_GET_MICROSEC(start_time);
+ cur = INSTR_TIME_GET_NANOSEC(start_time);
while (time_elapsed < total_time)
{
int32 diff,
- bits = 0;
+ bits;
prev = cur;
INSTR_TIME_SET_CURRENT(temp);
- cur = INSTR_TIME_GET_MICROSEC(temp);
+ cur = INSTR_TIME_GET_NANOSEC(temp);
diff = cur - prev;
/* Did time go backwards? */
@@ -154,18 +158,21 @@ test_timing(unsigned int duration)
}
/* What is the highest bit in the time diff? */
- while (diff)
- {
- diff >>= 1;
- bits++;
- }
+ if (diff > 0)
+ bits = pg_leftmost_one_pos32(diff) + 1;
+ else
+ bits = 0;
/* Update appropriate duration bucket */
histogram[bits]++;
+ /* Update direct histogram of time diffs */
+ if (diff < NUM_DIRECT)
+ direct_histogram[diff]++;
+
loop_count++;
INSTR_TIME_SUBTRACT(temp, start_time);
- time_elapsed = INSTR_TIME_GET_MICROSEC(temp);
+ time_elapsed = INSTR_TIME_GET_NANOSEC(temp);
}
INSTR_TIME_SET_CURRENT(end_time);
@@ -181,28 +188,65 @@ test_timing(unsigned int duration)
static void
output(uint64 loop_count)
{
- int64 max_bit = 31,
+ int max_bit = 31,
i;
- char *header1 = _("< us");
+ char *header1 = _("<= ns");
+ char *header1b = _("ns");
char *header2 = /* xgettext:no-c-format */ _("% of total");
- char *header3 = _("count");
+ char *header3 = /* xgettext:no-c-format */ _("running %");
+ char *header4 = _("count");
int len1 = strlen(header1);
int len2 = strlen(header2);
int len3 = strlen(header3);
+ int len4 = strlen(header4);
+ double rprct;
/* find highest bit value */
while (max_bit > 0 && histogram[max_bit] == 0)
max_bit--;
+ /* set minimum column widths */
+ len1 = Max(8, len1);
+ len2 = Max(10, len2);
+ len3 = Max(10, len3);
+ len4 = Max(10, len4);
+
printf(_("Histogram of timing durations:\n"));
- printf("%*s %*s %*s\n",
- Max(6, len1), header1,
- Max(10, len2), header2,
- Max(10, len3), header3);
-
- for (i = 0; i <= max_bit; i++)
- printf("%*ld %*.5f %*lld\n",
- Max(6, len1), 1l << i,
- Max(10, len2) - 1, (double) histogram[i] * 100 / loop_count,
- Max(10, len3), histogram[i]);
+ printf("%*s %*s %*s %*s\n",
+ len1, header1,
+ len2, header2,
+ len3, header3,
+ len4, header4);
+
+ for (i = 0, rprct = 0; i <= max_bit; i++)
+ {
+ double prct = (double) histogram[i] * 100 / loop_count;
+
+ rprct += prct;
+ printf("%*ld %*.4f %*.4f %*lld\n",
+ len1, (1L << i) - 1,
+ len2, prct,
+ len3, rprct,
+ len4, histogram[i]);
+ }
+
+ printf(_("\nTiming durations less than %d ns:\n"), NUM_DIRECT);
+ printf("%*s %*s %*s %*s\n",
+ len1, header1b,
+ len2, header2,
+ len3, header3,
+ len4, header4);
+
+ for (i = 0, rprct = 0; i < NUM_DIRECT; i++)
+ {
+ double prct = (double) direct_histogram[i] * 100 / loop_count;
+
+ rprct += prct;
+ if (direct_histogram[i])
+ printf("%*d %*.4f %*.4f %*lld\n",
+ len1, i,
+ len2, prct,
+ len3, rprct,
+ len4, direct_histogram[i]);
+ }
}
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: What is a typical precision of gettimeofday()?
@ 2024-07-02 17:20 Tom Lane <[email protected]>
parent: Tom Lane <[email protected]>
1 sibling, 1 reply; 17+ messages in thread
From: Tom Lane @ 2024-07-02 17:20 UTC (permalink / raw)
To: Hannu Krosing <[email protected]>; +Cc: Peter Eisentraut <[email protected]>; Andrey M. Borodin <[email protected]>; pgsql-hackers
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
Testing timing overhead for 3 seconds.
Per loop time including overhead: 16.60 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 3.2738 3.2738 5914914
31 96.7241 99.9980 174753569
63 0.0001 99.9981 265
127 0.0001 99.9982 110
255 0.0000 99.9982 29
511 0.0000 99.9982 0
1023 0.0013 99.9995 2410
2047 0.0003 99.9999 586
4095 0.0000 99.9999 10
8191 0.0000 99.9999 3
16383 0.0001 100.0000 228
32767 0.0000 100.0000 1
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
22 0.0001 99.9978 252
23 0.0001 99.9978 101
24 0.0000 99.9979 50
25 0.0000 99.9979 32
26 0.0000 99.9979 28
27 0.0000 99.9979 27
28 0.0000 99.9979 19
29 0.0000 99.9979 21
30 0.0000 99.9980 34
31 0.0000 99.9980 45
32 0.0000 99.9980 42
33 0.0000 99.9980 30
34 0.0000 99.9980 17
35 0.0000 99.9980 14
36 0.0000 99.9980 13
37 0.0000 99.9981 13
38 0.0000 99.9981 13
39 0.0000 99.9981 12
40 0.0000 99.9981 8
41 0.0000 99.9981 13
42 0.0000 99.9981 12
43 0.0000 99.9981 9
44 0.0000 99.9981 9
45 0.0000 99.9981 5
46 0.0000 99.9981 3
47 0.0000 99.9981 3
48 0.0000 99.9981 5
49 0.0000 99.9981 5
50 0.0000 99.9981 4
51 0.0000 99.9981 4
52 0.0000 99.9981 2
53 0.0000 99.9981 2
54 0.0000 99.9981 2
55 0.0000 99.9981 4
56 0.0000 99.9981 1
57 0.0000 99.9981 2
58 0.0000 99.9981 2
59 0.0000 99.9981 4
60 0.0000 99.9981 2
61 0.0000 99.9981 6
62 0.0000 99.9981 2
63 0.0000 99.9981 2
64 0.0000 99.9981 2
65 0.0000 99.9981 2
66 0.0000 99.9981 2
67 0.0000 99.9981 2
72 0.0000 99.9981 1
73 0.0000 99.9981 1
74 0.0000 99.9981 1
77 0.0000 99.9981 1
78 0.0000 99.9981 2
87 0.0000 99.9981 1
91 0.0000 99.9981 1
94 0.0000 99.9981 4
95 0.0000 99.9981 3
96 0.0000 99.9982 16
97 0.0000 99.9982 5
98 0.0000 99.9982 7
99 0.0000 99.9982 14
100 0.0000 99.9982 10
101 0.0000 99.9982 10
102 0.0000 99.9982 4
103 0.0000 99.9982 2
104 0.0000 99.9982 2
105 0.0000 99.9982 1
106 0.0000 99.9982 3
107 0.0000 99.9982 1
108 0.0000 99.9982 4
109 0.0000 99.9982 4
112 0.0000 99.9982 1
115 0.0000 99.9982 2
127 0.0000 99.9982 1
Attachments:
[text/plain] pg_test_timing.results.txt (4.3K, ../../[email protected]/2-pg_test_timing.results.txt)
download | inline:
Testing timing overhead for 3 seconds.
Per loop time including overhead: 16.60 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 3.2738 3.2738 5914914
31 96.7241 99.9980 174753569
63 0.0001 99.9981 265
127 0.0001 99.9982 110
255 0.0000 99.9982 29
511 0.0000 99.9982 0
1023 0.0013 99.9995 2410
2047 0.0003 99.9999 586
4095 0.0000 99.9999 10
8191 0.0000 99.9999 3
16383 0.0001 100.0000 228
32767 0.0000 100.0000 1
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
22 0.0001 99.9978 252
23 0.0001 99.9978 101
24 0.0000 99.9979 50
25 0.0000 99.9979 32
26 0.0000 99.9979 28
27 0.0000 99.9979 27
28 0.0000 99.9979 19
29 0.0000 99.9979 21
30 0.0000 99.9980 34
31 0.0000 99.9980 45
32 0.0000 99.9980 42
33 0.0000 99.9980 30
34 0.0000 99.9980 17
35 0.0000 99.9980 14
36 0.0000 99.9980 13
37 0.0000 99.9981 13
38 0.0000 99.9981 13
39 0.0000 99.9981 12
40 0.0000 99.9981 8
41 0.0000 99.9981 13
42 0.0000 99.9981 12
43 0.0000 99.9981 9
44 0.0000 99.9981 9
45 0.0000 99.9981 5
46 0.0000 99.9981 3
47 0.0000 99.9981 3
48 0.0000 99.9981 5
49 0.0000 99.9981 5
50 0.0000 99.9981 4
51 0.0000 99.9981 4
52 0.0000 99.9981 2
53 0.0000 99.9981 2
54 0.0000 99.9981 2
55 0.0000 99.9981 4
56 0.0000 99.9981 1
57 0.0000 99.9981 2
58 0.0000 99.9981 2
59 0.0000 99.9981 4
60 0.0000 99.9981 2
61 0.0000 99.9981 6
62 0.0000 99.9981 2
63 0.0000 99.9981 2
64 0.0000 99.9981 2
65 0.0000 99.9981 2
66 0.0000 99.9981 2
67 0.0000 99.9981 2
72 0.0000 99.9981 1
73 0.0000 99.9981 1
74 0.0000 99.9981 1
77 0.0000 99.9981 1
78 0.0000 99.9981 2
87 0.0000 99.9981 1
91 0.0000 99.9981 1
94 0.0000 99.9981 4
95 0.0000 99.9981 3
96 0.0000 99.9982 16
97 0.0000 99.9982 5
98 0.0000 99.9982 7
99 0.0000 99.9982 14
100 0.0000 99.9982 10
101 0.0000 99.9982 10
102 0.0000 99.9982 4
103 0.0000 99.9982 2
104 0.0000 99.9982 2
105 0.0000 99.9982 1
106 0.0000 99.9982 3
107 0.0000 99.9982 1
108 0.0000 99.9982 4
109 0.0000 99.9982 4
112 0.0000 99.9982 1
115 0.0000 99.9982 2
127 0.0000 99.9982 1
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: What is a typical precision of gettimeofday()?
@ 2024-07-02 17:31 Hannu Krosing <[email protected]>
parent: Tom Lane <[email protected]>
0 siblings, 2 replies; 17+ messages in thread
From: Hannu Krosing @ 2024-07-02 17:31 UTC (permalink / raw)
To: Tom Lane <[email protected]>; +Cc: Peter Eisentraut <[email protected]>; Andrey M. Borodin <[email protected]>; pgsql-hackers
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 <[email protected]> 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
>
Attachments:
[text/x-csrc] pg_test_ticking.c (6.9K, ../../CAMT0RQTzzzSfO4j3PeF5riQ_mER_9BE_LNnjEUrM349ZhhDbww@mail.gmail.com/2-pg_test_ticking.c)
download | inline:
/*
* pg_test_timing.c
* tests overhead of timing calls and their monotonicity: that
* they always move forward
*/
#include "postgres_fe.h"
#include <limits.h>
#include "getopt_long.h"
#include "portability/instr_time.h"
#include "port/pg_bitutils.h"
static const char *progname;
static unsigned int test_duration = 3;
static void handle_args(int argc, char *argv[]);
static uint64 test_timing(unsigned int duration);
static void output(uint64 loop_count);
/* record duration in powers of 2 nanoseconds */
long long int histogram[64];
/* record duration up to 64 ticks directly */
long long int direct_histogram[64];
/* Current CPU speed in ticks per second*/
uint64 ticks_per_sec;
int
main(int argc, char *argv[])
{
uint64 loop_count;
set_pglocale_pgservice(argv[0], PG_TEXTDOMAIN("pg_test_timing"));
progname = get_progname(argv[0]);
handle_args(argc, argv);
loop_count = test_timing(test_duration);
output(loop_count);
return 0;
}
static void
handle_args(int argc, char *argv[])
{
static struct option long_options[] = {
{"duration", required_argument, NULL, 'd'},
{NULL, 0, NULL, 0}
};
int option; /* Command line option */
int optindex = 0; /* used by getopt_long */
unsigned long optval; /* used for option parsing */
char *endptr;
if (argc > 1)
{
if (strcmp(argv[1], "--help") == 0 || strcmp(argv[1], "-?") == 0)
{
printf(_("Usage: %s [-d DURATION]\n"), progname);
exit(0);
}
if (strcmp(argv[1], "--version") == 0 || strcmp(argv[1], "-V") == 0)
{
puts("pg_test_timing (PostgreSQL) " PG_VERSION);
exit(0);
}
}
while ((option = getopt_long(argc, argv, "d:",
long_options, &optindex)) != -1)
{
switch (option)
{
case 'd':
errno = 0;
optval = strtoul(optarg, &endptr, 10);
if (endptr == optarg || *endptr != '\0' ||
errno != 0 || optval != (unsigned int) optval)
{
fprintf(stderr, _("%s: invalid argument for option %s\n"),
progname, "--duration");
fprintf(stderr, _("Try \"%s --help\" for more information.\n"), progname);
exit(1);
}
test_duration = (unsigned int) optval;
if (test_duration == 0)
{
fprintf(stderr, _("%s: %s must be in range %u..%u\n"),
progname, "--duration", 1, UINT_MAX);
exit(1);
}
break;
default:
fprintf(stderr, _("Try \"%s --help\" for more information.\n"),
progname);
exit(1);
break;
}
}
if (argc > optind)
{
fprintf(stderr,
_("%s: too many command-line arguments (first is \"%s\")\n"),
progname, argv[optind]);
fprintf(stderr, _("Try \"%s --help\" for more information.\n"),
progname);
exit(1);
}
printf(ngettext("Testing timing overhead for %u second.\n",
"Testing timing overhead for %u seconds.\n",
test_duration),
test_duration);
}
inline uint64_t read_tsc(void) {
return __builtin_readcyclecounter();;
}
static uint64
test_timing(unsigned int duration)
{
// uint64 total_time;
int64 time_elapsed = 0;
uint64 loop_count = 0;
uint64 same_count = 0;
uint64 min_diff = UINT64_MAX;
uint64 ticks_elapsed = 0;
uint64 start_tick,
end_tick,
total_ticks,
prev,
cur;
instr_time start_time,
end_time,
temp;
// total_time = duration > 0 ? duration * INT64CONST(1000000000) : 0;
// measure tick timing
INSTR_TIME_SET_CURRENT(start_time);
start_tick = read_tsc();
while (time_elapsed < INT64CONST(1000000000))
{
INSTR_TIME_SET_CURRENT(temp);
INSTR_TIME_SUBTRACT(temp, start_time);
time_elapsed = INSTR_TIME_GET_NANOSEC(temp);
}
end_tick = read_tsc();
INSTR_TIME_SET_CURRENT(end_time);
INSTR_TIME_SUBTRACT(end_time, start_time);
printf(_("Total %ld ticks in %ld ns, %0.6f ticks per ns\n"),
end_tick - start_tick, INSTR_TIME_GET_NANOSEC(end_time), ((double)(end_tick - start_tick)) / INSTR_TIME_GET_DOUBLE(end_time));
ticks_per_sec = (end_tick - start_tick) * 1000000000 / INSTR_TIME_GET_NANOSEC(end_time);
total_ticks = duration > 0 ? duration * ticks_per_sec : 0;
printf("This CPU is running at %ld ticks / second, will run test for %ld ticks\n", ticks_per_sec, total_ticks);
// return 0;
INSTR_TIME_SET_CURRENT(start_time);
cur = start_tick = read_tsc();
while (ticks_elapsed < total_ticks)
{
int64 diff;
int32 bits;
prev = cur;
cur = read_tsc();
diff = cur - prev;
/* Did time go backwards? */
if (unlikely(diff <= 0))
{
if (likely (diff == 0 ))
same_count ++;
else
{
fprintf(stderr, _("Detected clock going backwards in time.\n"));
fprintf(stderr, _("Time warp: %ld ms\n"), diff);
exit(1);
}
}
if (unlikely(min_diff > diff))
min_diff = diff;
if(likely(diff < 64))
direct_histogram[diff]++;
bits = pg_leftmost_one_pos64(diff+1);
histogram[bits]++;
loop_count++;
ticks_elapsed = cur - start_tick;
}
end_tick = read_tsc();
INSTR_TIME_SET_CURRENT(end_time);
INSTR_TIME_SUBTRACT(end_time, start_time);
printf("loop_count %ld", loop_count);
printf(_("Per loop time including overhead: %0.2f ns, min: %ld ticks (%0.1f ns), same: %ld\n"),
INSTR_TIME_GET_DOUBLE(end_time) * 1e9 / loop_count, min_diff, (float) min_diff * 1000000000 / ticks_per_sec , same_count);
printf(_("Total ticks in: %ld, in: %ld nr\n"),
end_tick - start_tick, INSTR_TIME_GET_NANOSEC(end_time) );
return loop_count;
}
static void
output(uint64 loop_count)
{
int64 max_bit = 63,
i;
char *header1 = _("<= ticks");
char *header1a = _("<= ns");
char *header2 = /* xgettext:no-c-format */ _("% of total");
char *header2a = /* xgettext:no-c-format */ _("running %");
char *header3 = _("count");
int len1 = strlen(header1);
int len1a = strlen(header1a);
int len2 = strlen(header2);
int len2a = strlen(header2a);
int len3 = strlen(header3);
float rprct;
/* find highest bit value */
while (max_bit > 0 && histogram[max_bit] == 0)
max_bit--;
printf(_("Log2(x+1) histogram of timing durations:\n"));
printf("%*s (%*s) %*s %*s %*s\n",
Max(8, len1), header1,
Max(8, len1a), header1a,
Max(10, len2), header2,
Max(10, len2a), header2a,
Max(8, len3), header3);
for (i = 0, rprct=0; i <= max_bit; i++) {
rprct += (double) histogram[i] * 100 / loop_count;
printf("%*ld (%*.1f) %*.4f %*.4f %*lld\n",
Max(8, len1), (1l << (i+1)) - 2,
Max(8, len1a), (float) (1l << i) * 1000000000 / ticks_per_sec,
Max(10, len2) - 1, (double) histogram[i] * 100 / loop_count,
Max(10, len2) - 1, rprct,
Max(10, len3), histogram[i]);
}
printf("First 64 ticks --\n");
for (i = 0, rprct=0; i < 64; i++) {
rprct += (double) histogram[i] * 100 / loop_count;
if (direct_histogram[i])
printf("%*ld (%*.1f) %*.4f %*.4f %*lld\n",
Max(8, len1), (long int) i,
Max(8, len1a), (float) (i) * 1000000000 / ticks_per_sec,
Max(10, len2) - 1, (double) direct_histogram[i] * 100 / loop_count,
Max(10, len2) - 1, rprct,
Max(10, len3), direct_histogram[i]);
}
}
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: What is a typical precision of gettimeofday()?
@ 2024-07-02 17:37 Hannu Krosing <[email protected]>
parent: Hannu Krosing <[email protected]>
1 sibling, 0 replies; 17+ messages in thread
From: Hannu Krosing @ 2024-07-02 17:37 UTC (permalink / raw)
To: Tom Lane <[email protected]>; +Cc: Peter Eisentraut <[email protected]>; Andrey M. Borodin <[email protected]>; pgsql-hackers
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 <[email protected]> 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 <[email protected]> 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
> >
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: What is a typical precision of gettimeofday()?
@ 2024-07-02 17:50 Tom Lane <[email protected]>
parent: Hannu Krosing <[email protected]>
1 sibling, 1 reply; 17+ messages in thread
From: Tom Lane @ 2024-07-02 17:50 UTC (permalink / raw)
To: Hannu Krosing <[email protected]>; +Cc: Peter Eisentraut <[email protected]>; Andrey M. Borodin <[email protected]>; pgsql-hackers
Hannu Krosing <[email protected]> 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
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: What is a typical precision of gettimeofday()?
@ 2024-07-02 18:15 Hannu Krosing <[email protected]>
parent: Tom Lane <[email protected]>
0 siblings, 0 replies; 17+ messages in thread
From: Hannu Krosing @ 2024-07-02 18:15 UTC (permalink / raw)
To: Tom Lane <[email protected]>; +Cc: Peter Eisentraut <[email protected]>; Andrey M. Borodin <[email protected]>; pgsql-hackers
On Tue, Jul 2, 2024 at 7:50 PM Tom Lane <[email protected]> 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
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: What is a typical precision of gettimeofday()?
@ 2024-11-02 08:37 Andrey M. Borodin <[email protected]>
parent: Tom Lane <[email protected]>
1 sibling, 1 reply; 17+ messages in thread
From: Andrey M. Borodin @ 2024-11-02 08:37 UTC (permalink / raw)
To: Tom Lane <[email protected]>; +Cc: Hannu Krosing <[email protected]>; Peter Eisentraut <[email protected]>; pgsql-hackers
> On 2 Jul 2024, at 20:55, Tom Lane <[email protected]> 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/[email protected]...
[2] https://www.postgresql.org/message-id/CAMT0RQQJWNoki_vmckYb5J1j-BENBE0YtD6jJmVg--Hyvt7Wjg%40mail.gma...
[3] https://www.postgresql.org/message-id/flat/198ef658-a5b7-9862-2017-faf85d59e3a8%40gmail.com#37d8292e...
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: What is a typical precision of gettimeofday()?
@ 2024-11-02 14:27 Tom Lane <[email protected]>
parent: Andrey M. Borodin <[email protected]>
0 siblings, 1 reply; 17+ messages in thread
From: Tom Lane @ 2024-11-02 14:27 UTC (permalink / raw)
To: Andrey M. Borodin <[email protected]>; +Cc: Hannu Krosing <[email protected]>; Peter Eisentraut <[email protected]>; pgsql-hackers
"Andrey M. Borodin" <[email protected]> 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
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: What is a typical precision of gettimeofday()?
@ 2024-11-03 22:15 Hannu Krosing <[email protected]>
parent: Tom Lane <[email protected]>
0 siblings, 0 replies; 17+ messages in thread
From: Hannu Krosing @ 2024-11-03 22:15 UTC (permalink / raw)
To: Tom Lane <[email protected]>; +Cc: Andrey M. Borodin <[email protected]>; Peter Eisentraut <[email protected]>; pgsql-hackers
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 <[email protected]> wrote:
> "Andrey M. Borodin" <[email protected]> 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
>
^ permalink raw reply [nested|flat] 17+ messages in thread
end of thread, other threads:[~2024-11-03 22:15 UTC | newest]
Thread overview: 17+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2020-11-20 02:48 [PATCH 1/3] bootstrap: convert Typ to a List* Justin Pryzby <[email protected]>
2024-06-18 05:47 Re: What is a typical precision of gettimeofday()? Andrey M. Borodin <[email protected]>
2024-06-18 15:08 ` Re: What is a typical precision of gettimeofday()? Hannu Krosing <[email protected]>
2024-06-19 10:55 ` Re: What is a typical precision of gettimeofday()? Hannu Krosing <[email protected]>
2024-06-19 15:44 ` Re: What is a typical precision of gettimeofday()? Peter Eisentraut <[email protected]>
2024-06-19 16:36 ` Re: What is a typical precision of gettimeofday()? Tom Lane <[email protected]>
2024-06-20 10:41 ` Re: What is a typical precision of gettimeofday()? Hannu Krosing <[email protected]>
2024-06-21 20:51 ` Re: What is a typical precision of gettimeofday()? Tom Lane <[email protected]>
2024-07-02 16:55 ` Re: What is a typical precision of gettimeofday()? Tom Lane <[email protected]>
2024-07-02 17:20 ` Re: What is a typical precision of gettimeofday()? Tom Lane <[email protected]>
2024-07-02 17:31 ` Re: What is a typical precision of gettimeofday()? Hannu Krosing <[email protected]>
2024-07-02 17:37 ` Re: What is a typical precision of gettimeofday()? Hannu Krosing <[email protected]>
2024-07-02 17:50 ` Re: What is a typical precision of gettimeofday()? Tom Lane <[email protected]>
2024-07-02 18:15 ` Re: What is a typical precision of gettimeofday()? Hannu Krosing <[email protected]>
2024-11-02 08:37 ` Re: What is a typical precision of gettimeofday()? Andrey M. Borodin <[email protected]>
2024-11-02 14:27 ` Re: What is a typical precision of gettimeofday()? Tom Lane <[email protected]>
2024-11-03 22:15 ` Re: What is a typical precision of gettimeofday()? Hannu Krosing <[email protected]>
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox