Adjust pg_test_timing to show shortest test durations first, place

percentage column before count column.  Docs updated.

diff --git a/contrib/pg_test_timing/pg_test_timing.c b/contrib/pg_test_timing/pg_test_timing.c
index b3f98abe5cb6b1bc37253d00d0ba68b6fd75e543..8d79c7bd74f7531114be794d412a5f6e0b16bbb6 100644 (file)
--- 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 f74d63e68831752f6a16e89b62b802676d327dda..45ee80c23dbec333c2fc7004c28e5c8151db4467 100644 (file)
--- 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>