diff options
| -rw-r--r-- | contrib/pg_test_timing/pg_test_timing.c | 68 | ||||
| -rw-r--r-- | doc/src/sgml/pgtesttiming.sgml | 38 |
2 files changed, 59 insertions, 47 deletions
diff --git a/contrib/pg_test_timing/pg_test_timing.c b/contrib/pg_test_timing/pg_test_timing.c index b3f98abe5cb..8d79c7bd74f 100644 --- a/contrib/pg_test_timing/pg_test_timing.c +++ b/contrib/pg_test_timing/pg_test_timing.c @@ -14,16 +14,24 @@ static const char *progname; static int32 test_duration = 3; static void handle_args(int argc, char *argv[]); -static void test_timing(int32); +static uint64 test_timing(int32); +static void output(uint64 loop_count); + +/* record duration in powers of 2 microseconds */ +int64 histogram[32]; int main(int argc, char *argv[]) { + uint64 loop_count; + progname = get_progname(argv[0]); handle_args(argc, argv); - test_timing(test_duration); + loop_count = test_timing(test_duration); + + output(loop_count); return 0; } @@ -95,25 +103,14 @@ handle_args(int argc, char *argv[]) } } -static void +static uint64 test_timing(int32 duration) { uint64 total_time; int64 time_elapsed = 0; uint64 loop_count = 0; - uint64 prev, - cur; - int32 diff, - i, - bits, - found; - - instr_time start_time, - end_time, - temp; - - static int64 histogram[32]; - char buf[100]; + uint64 prev, cur; + instr_time start_time, end_time, temp; total_time = duration > 0 ? duration * 1000000 : 0; @@ -122,11 +119,14 @@ test_timing(int32 duration) while (time_elapsed < total_time) { + int32 diff, 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) { printf("Detected clock going backwards in time.\n"); @@ -134,12 +134,14 @@ test_timing(int32 duration) exit(1); } - bits = 0; + /* What is the highest bit in the time diff? */ while (diff) { diff >>= 1; bits++; } + + /* Update appropriate duration bucket */ histogram[bits]++; loop_count++; @@ -153,19 +155,29 @@ test_timing(int32 duration) printf("Per loop time including overhead: %0.2f nsec\n", INSTR_TIME_GET_DOUBLE(end_time) * 1e9 / loop_count); + + return loop_count; +} + +static void +output(uint64 loop_count) +{ + int64 max_bit = 31, i; + + /* find highest bit value */ + while (max_bit > 0 && histogram[max_bit] == 0) + max_bit--; + printf("Histogram of timing durations:\n"); - printf("%9s: %10s %9s\n", "< usec", "count", "percent"); + printf("%6s %10s %10s\n", "< usec", "% of total", "count"); - found = 0; - for (i = 31; i >= 0; i--) + for (i = 0; i <= max_bit; i++) { - if (found || histogram[i]) - { - found = 1; - /* lame hack to work around INT64_FORMAT deficiencies */ - snprintf(buf, sizeof(buf), INT64_FORMAT, histogram[i]); - printf("%9ld: %10s %8.5f%%\n", 1l << i, buf, - (double) histogram[i] * 100 / loop_count); - } + char buf[100]; + + /* lame hack to work around INT64_FORMAT deficiencies */ + snprintf(buf, sizeof(buf), INT64_FORMAT, histogram[i]); + printf("%6ld %9.5f %10s\n", 1l << i, + (double) histogram[i] * 100 / loop_count, buf); } } diff --git a/doc/src/sgml/pgtesttiming.sgml b/doc/src/sgml/pgtesttiming.sgml index f74d63e6883..45ee80c23db 100644 --- a/doc/src/sgml/pgtesttiming.sgml +++ b/doc/src/sgml/pgtesttiming.sgml @@ -98,12 +98,12 @@ Testing timing overhead for 3 seconds. Per loop time including overhead: 35.96 nsec Histogram of timing durations: - < usec: count percent - 16: 2 0.00000% - 8: 13 0.00002% - 4: 126 0.00015% - 2: 2999652 3.59518% - 1: 80435604 96.40465% +< usec % of total count + 1 96.40465 80435604 + 2 3.59518 2999652 + 4 0.00015 126 + 8 0.00002 13 + 16 0.00000 2 </screen> </para> @@ -159,12 +159,12 @@ tsc hpet acpi_pm # pg_test_timing Per loop time including overhead: 722.92 nsec Histogram of timing durations: - < usec: count percent - 16: 3 0.00007% - 8: 563 0.01357% - 4: 3241 0.07810% - 2: 2990371 72.05956% - 1: 1155682 27.84870% +< usec % of total count + 1 27.84870 1155682 + 2 72.05956 2990371 + 4 0.07810 3241 + 8 0.01357 563 + 16 0.00007 3 </screen> </para> @@ -206,13 +206,13 @@ $ pg_test_timing Testing timing overhead for 3 seconds. Per timing duration including loop overhead: 97.75 ns Histogram of timing durations: - < usec: count percent - 32: 1 0.00000% - 16: 1 0.00000% - 8: 22 0.00007% - 4: 3010 0.00981% - 2: 2993204 9.75277% - 1: 27694571 90.23734% +< usec % of total count + 1 90.23734 27694571 + 2 9.75277 2993204 + 4 0.00981 3010 + 8 0.00007 22 + 16 0.00000 1 + 32 0.00000 1 </screen></para> </refsect2> |