database/postgres
database/postgres
1
0
Fork 0
mirror of https://github.com/postgres/postgres.git synced 2025-04-21 12:05:57 +03:00
Code

Adjust pg_test_timing to show shortest test durations first, place

Browse Source 
percentage column before count column.  Docs updated.
This commit is contained in:
Bruce Momjian 2012-08-28 12:57:13 -04:00
parent 65b2ee27ad
commit 0f3351aacf
2 changed files with 60 additions and 48 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

70
contrib/pg_test_timing/pg_test_timing.c
View File

@ -14,16 +14,24 @@ static const char *progname;
static int32 test_duration = 3; static int32 test_duration = 3;
static void handle_args(int argc, char *argv[]); 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 int
main(int argc, char *argv[]) main(int argc, char *argv[])
{ {
uint64 loop_count;
progname = get_progname(argv[0]); progname = get_progname(argv[0]);
handle_args(argc, argv); handle_args(argc, argv);
test_timing(test_duration); loop_count = test_timing(test_duration);
output(loop_count);
return 0; return 0;
} }
@ -95,25 +103,14 @@ handle_args(int argc, char *argv[])
} }
} }
static void static uint64
test_timing(int32 duration) test_timing(int32 duration)
{ {
uint64 total_time; uint64 total_time;
int64 time_elapsed = 0; int64 time_elapsed = 0;
uint64 loop_count = 0; uint64 loop_count = 0;
uint64 prev, uint64 prev, cur;
cur; instr_time start_time, end_time, temp;
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; total_time = duration > 0 ? duration * 1000000 : 0;
@ -122,11 +119,14 @@ test_timing(int32 duration)
while (time_elapsed < total_time) while (time_elapsed < total_time)
{ {
int32 diff, bits = 0;
prev = cur; prev = cur;
INSTR_TIME_SET_CURRENT(temp); INSTR_TIME_SET_CURRENT(temp);
cur = INSTR_TIME_GET_MICROSEC(temp); cur = INSTR_TIME_GET_MICROSEC(temp);
diff = cur - prev; diff = cur - prev;
/* Did time go backwards? */
if (diff < 0) if (diff < 0)
{ {
printf("Detected clock going backwards in time.\n"); printf("Detected clock going backwards in time.\n");
@ -134,12 +134,14 @@ test_timing(int32 duration)
exit(1); exit(1);
} }
bits = 0; /* What is the highest bit in the time diff? */
while (diff) while (diff)
{ {
diff >>= 1; diff >>= 1;
bits++; bits++;
} }
/* Update appropriate duration bucket */
histogram[bits]++; histogram[bits]++;
loop_count++; loop_count++;
@ -153,19 +155,29 @@ test_timing(int32 duration)
printf("Per loop time including overhead: %0.2f nsec\n", printf("Per loop time including overhead: %0.2f nsec\n",
INSTR_TIME_GET_DOUBLE(end_time) * 1e9 / loop_count); 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; return loop_count;
for (i = 31; i >= 0; i--) }
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++)
{ {
if (found || histogram[i]) char buf[100];
{
found = 1; /* lame hack to work around INT64_FORMAT deficiencies */
/* lame hack to work around INT64_FORMAT deficiencies */ snprintf(buf, sizeof(buf), INT64_FORMAT, histogram[i]);
snprintf(buf, sizeof(buf), INT64_FORMAT, histogram[i]); printf("%6ld %9.5f %10s\n", 1l << i,
printf("%9ld: %10s %8.5f%%\n", 1l << i, buf, (double) histogram[i] * 100 / loop_count, buf);
(double) histogram[i] * 100 / loop_count);
}
} }
} }

38
doc/src/sgml/pgtesttiming.sgml
View File

@ -98,12 +98,12 @@
Testing timing overhead for 3 seconds. Testing timing overhead for 3 seconds.
Per loop time including overhead: 35.96 nsec Per loop time including overhead: 35.96 nsec
Histogram of timing durations: Histogram of timing durations:
< usec: count percent < usec % of total count
16: 2 0.00000% 1 96.40465 80435604
8: 13 0.00002% 2 3.59518 2999652
4: 126 0.00015% 4 0.00015 126
2: 2999652 3.59518% 8 0.00002 13
1: 80435604 96.40465% 16 0.00000 2
</screen> </screen>
</para> </para>
@ -159,12 +159,12 @@ tsc hpet acpi_pm
# pg_test_timing # pg_test_timing
Per loop time including overhead: 722.92 nsec Per loop time including overhead: 722.92 nsec
Histogram of timing durations: Histogram of timing durations:
< usec: count percent < usec % of total count
16: 3 0.00007% 1 27.84870 1155682
8: 563 0.01357% 2 72.05956 2990371
4: 3241 0.07810% 4 0.07810 3241
2: 2990371 72.05956% 8 0.01357 563
1: 1155682 27.84870% 16 0.00007 3
</screen> </screen>
</para> </para>
@ -206,13 +206,13 @@ $ pg_test_timing
Testing timing overhead for 3 seconds. Testing timing overhead for 3 seconds.
Per timing duration including loop overhead: 97.75 ns Per timing duration including loop overhead: 97.75 ns
Histogram of timing durations: Histogram of timing durations:
< usec: count percent < usec % of total count
32: 1 0.00000% 1 90.23734 27694571
16: 1 0.00000% 2 9.75277 2993204
8: 22 0.00007% 4 0.00981 3010
4: 3010 0.00981% 8 0.00007 22
2: 2993204 9.75277% 16 0.00000 1
1: 27694571 90.23734% 32 0.00000 1
</screen></para> </screen></para>
</refsect2> </refsect2>