Currently pg_test_timing utility measures its timing overhead in
microseconds, giving results like this
~$ /usr/lib/postgresql/15/bin/pg_test_timing
Testing timing overhead for 3 seconds.
Per loop time including overhead: 18.97 ns
Histogram of timing durations:
< us % of total count
1 98.11132 155154419
2 1.88756 2985010
4 0.00040 630
8 0.00012 184
16 0.00058 919
32 0.00003 40
64 0.00000 6
I got curious and wanted to see how the 98.1% timings are distributed
(raw uncleaned patch attached)
And this is what I got when I increased the measuring resolution to nanoseconds
hannuk@hannuk1:~/work/postgres15_uni_dist_on/src/bin/pg_test_timing$
./pg_test_timing
Testing timing overhead for 3 seconds.
Per loop time including overhead: 17.34 ns, min: 15, same: 0
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 1.14387 1979085
32 98.47924 170385392
64 0.21666 374859
128 0.15654 270843
256 0.00297 5139
512 0.00016 272
1024 0.00004 73
2048 0.00018 306
4096 0.00022 375
8192 0.00006 99
16384 0.00005 80
32768 0.00001 20
65536 0.00000 6
131072 0.00000 2
As most of the samples seems to be in ranges 8..15 and 16..32
nanoseconds the current way of measuring at microsecond resolution is
clearly inadequate.
The attached patch is not meant to be applied as-is but is rather
there as a helper to easily verify the above numbers.
QUESTIONS
1. Do you think it is ok to just change pg_test_timing to return the
result in nanoseconds or should there be a flag that asks for
nanosecond resolution ?
2. Should the output be changed to give ranges instead of `<ns`
numbers for better clarity, and leave out the "too small numbers" from
the beginning as well ?
So the first few lines would look like
8 .. 15 ....
16 .. 32 .....
....
---
Best Regards,
Hannu
*** pg_test_timing.c.orig 2023-01-16 01:09:51.839251695 +0100
--- pg_test_timing.c 2023-01-16 22:24:49.768037225 +0100
***************
*** 11,16 ****
--- 11,20 ----
#include "getopt_long.h"
#include "portability/instr_time.h"
+ #define INSTR_TIME_GET_NANOSEC(t) \
+ (((uint64) (t).tv_sec * (uint64) 1000000000) + (uint64) ((t).tv_nsec))
+
+
static const char *progname;
static unsigned int test_duration = 3;
***************
*** 19,26 ****
static uint64 test_timing(unsigned int duration);
static void output(uint64 loop_count);
! /* record duration in powers of 2 microseconds */
! long long int histogram[32];
int
main(int argc, char *argv[])
--- 23,30 ----
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];
int
main(int argc, char *argv[])
***************
*** 124,139 ****
uint64 total_time;
int64 time_elapsed = 0;
uint64 loop_count = 0;
uint64 prev,
cur;
instr_time start_time,
end_time,
temp;
! total_time = duration > 0 ? duration * INT64CONST(1000000) : 0;
INSTR_TIME_SET_CURRENT(start_time);
! cur = INSTR_TIME_GET_MICROSEC(start_time);
while (time_elapsed < total_time)
{
--- 128,145 ----
uint64 total_time;
int64 time_elapsed = 0;
uint64 loop_count = 0;
+ uint64 same_count = 0;
+ uint64 min_diff = UINT64_MAX;
uint64 prev,
cur;
instr_time start_time,
end_time,
temp;
! total_time = duration > 0 ? duration * INT64CONST(1000000000) : 0;
INSTR_TIME_SET_CURRENT(start_time);
! cur = INSTR_TIME_GET_NANOSEC(start_time);
while (time_elapsed < total_time)
{
***************
*** 141,157 ****
bits = 0;
prev = cur;
INSTR_TIME_SET_CURRENT(temp);
! cur = INSTR_TIME_GET_MICROSEC(temp);
diff = cur - prev;
/* Did time go backwards? */
! if (diff < 0)
{
fprintf(stderr, _("Detected clock going backwards in time.\n"));
fprintf(stderr, _("Time warp: %d ms\n"), diff);
exit(1);
}
/* What is the highest bit in the time diff? */
while (diff)
--- 147,172 ----
bits = 0;
prev = cur;
+ // INSTR_TIME_SET_CURRENT(temp);
+ // prev = INSTR_TIME_GET_NANOSEC(temp);
INSTR_TIME_SET_CURRENT(temp);
! cur = INSTR_TIME_GET_NANOSEC(temp);
diff = cur - prev;
/* Did time go backwards? */
! if (unlikely(diff <= 0))
{
+ if (diff == 0 )
+ same_count ++;
+ else
+ {
fprintf(stderr, _("Detected clock going backwards in time.\n"));
fprintf(stderr, _("Time warp: %d ms\n"), diff);
exit(1);
+ }
}
+ if (min_diff > diff)
+ min_diff = diff;
/* What is the highest bit in the time diff? */
while (diff)
***************
*** 165,179 ****
loop_count++;
INSTR_TIME_SUBTRACT(temp, start_time);
! time_elapsed = INSTR_TIME_GET_MICROSEC(temp);
}
INSTR_TIME_SET_CURRENT(end_time);
INSTR_TIME_SUBTRACT(end_time, start_time);
! printf(_("Per loop time including overhead: %0.2f ns\n"),
! INSTR_TIME_GET_DOUBLE(end_time) * 1e9 / loop_count);
return loop_count;
}
--- 180,194 ----
loop_count++;
INSTR_TIME_SUBTRACT(temp, start_time);
! time_elapsed = INSTR_TIME_GET_NANOSEC(temp);
}
INSTR_TIME_SET_CURRENT(end_time);
INSTR_TIME_SUBTRACT(end_time, start_time);
! printf(_("Per loop time including overhead: %0.2f ns, min: %ld, same: %ld\n"),
! INSTR_TIME_GET_DOUBLE(end_time) * 1e9 / loop_count, min_diff, same_count);
return loop_count;
}
***************
*** 181,189 ****
static void
output(uint64 loop_count)
{
! int64 max_bit = 31,
i;
! char *header1 = _("< us");
char *header2 = /* xgettext:no-c-format */ _("% of total");
char *header3 = _("count");
int len1 = strlen(header1);
--- 196,204 ----
static void
output(uint64 loop_count)
{
! int64 max_bit = 63,
i;
! char *header1 = _("< ns");
char *header2 = /* xgettext:no-c-format */ _("% of total");
char *header3 = _("count");
int len1 = strlen(header1);
***************
*** 196,208 ****
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]);
}
--- 211,223 ----
printf(_("Histogram of timing durations:\n"));
printf("%*s %*s %*s\n",
! Max(7, len1), header1,
Max(10, len2), header2,
Max(10, len3), header3);
for (i = 0; i <= max_bit; i++)
printf("%*ld %*.5f %*lld\n",
! Max(7, len1), 1l << i,
Max(10, len2) - 1, (double) histogram[i] * 100 / loop_count,
Max(10, len3), histogram[i]);
}
