On Mon, Aug 20, 2012 at 03:11:51PM -0400, Robert Haas wrote:
> On Thu, Aug 16, 2012 at 10:28 PM, Bruce Momjian <[email protected]> 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 <[email protected]> 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 ([email protected])
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
