On Mon, Aug 20, 2012 at 03:11:51PM -0400, Robert Haas wrote: > On Thu, Aug 16, 2012 at 10:28 PM, Bruce Momjian <br...@momjian.us> wrote: > > FYI, I am planning to go ahead and package this tool in /contrib for PG > > 9.3. > > Isn't this exactly what we already did, in 9.2, in the form of > contrib/pg_test_timing?
Sorry, not sure how I missed that commit. Anyway, I am attaching a patch for 9.3 that I think improves the output of the tool, plus adds some C comments. The new output has the lowest duration times first: Testing timing overhead for 3 seconds. Per loop time including overhead: 41.31 nsec Histogram of timing durations: < usec % of total count 1 95.87135 69627856 2 4.12759 2997719 4 0.00086 628 8 0.00018 133 16 0.00001 5 32 0.00000 1 This should make the output clearer to eyeball for problems --- a good timing has a high percentage on the first line, rather than on the last line. -- Bruce Momjian <br...@momjian.us> http://momjian.us EnterpriseDB http://enterprisedb.com + It's impossible for everything to be true. +
diff --git a/contrib/pg_test_timing/pg_test_timing.c b/contrib/pg_test_timing/pg_test_timing.c new file mode 100644 index b3f98ab..8d79c7b *** a/contrib/pg_test_timing/pg_test_timing.c --- b/contrib/pg_test_timing/pg_test_timing.c *************** static const char *progname; *** 14,29 **** static int32 test_duration = 3; static void handle_args(int argc, char *argv[]); ! static void test_timing(int32); int main(int argc, char *argv[]) { progname = get_progname(argv[0]); handle_args(argc, argv); ! test_timing(test_duration); return 0; } --- 14,37 ---- static int32 test_duration = 3; static void handle_args(int argc, char *argv[]); ! 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); ! loop_count = test_timing(test_duration); ! ! output(loop_count); return 0; } *************** handle_args(int argc, char *argv[]) *** 95,119 **** } } ! static void 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]; total_time = duration > 0 ? duration * 1000000 : 0; --- 103,116 ---- } } ! static uint64 test_timing(int32 duration) { 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 * 1000000 : 0; *************** test_timing(int32 duration) *** 122,132 **** --- 119,132 ---- 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"); *************** test_timing(int32 duration) *** 134,145 **** exit(1); } ! bits = 0; while (diff) { diff >>= 1; bits++; } histogram[bits]++; loop_count++; --- 134,147 ---- exit(1); } ! /* What is the highest bit in the time diff? */ while (diff) { diff >>= 1; bits++; } + + /* Update appropriate duration bucket */ histogram[bits]++; loop_count++; *************** test_timing(int32 duration) *** 153,171 **** printf("Per loop time including overhead: %0.2f nsec\n", INSTR_TIME_GET_DOUBLE(end_time) * 1e9 / loop_count); printf("Histogram of timing durations:\n"); ! printf("%9s: %10s %9s\n", "< usec", "count", "percent"); ! found = 0; ! for (i = 31; i >= 0; 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); ! } } } --- 155,183 ---- 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("%6s %10s %10s\n", "< usec", "% of total", "count"); ! for (i = 0; i <= max_bit; i++) { ! 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 new file mode 100644 index f74d63e..45ee80c *** a/doc/src/sgml/pgtesttiming.sgml --- b/doc/src/sgml/pgtesttiming.sgml *************** *** 98,109 **** 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% </screen> </para> --- 98,109 ---- Testing timing overhead for 3 seconds. Per loop time including overhead: 35.96 nsec Histogram of timing durations: ! < 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> *************** tsc hpet acpi_pm *** 159,170 **** # 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% </screen> </para> --- 159,170 ---- # pg_test_timing Per loop time including overhead: 722.92 nsec Histogram of timing durations: ! < 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> *************** $ pg_test_timing *** 206,218 **** 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% </screen></para> </refsect2> --- 206,218 ---- Testing timing overhead for 3 seconds. Per timing duration including loop overhead: 97.75 ns Histogram of timing durations: ! < 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>
-- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers