Line data Source code
1 : /*
2 : * pg_test_timing.c
3 : * tests overhead of timing calls and their monotonicity: that
4 : * they always move forward
5 : */
6 :
7 : #include "postgres_fe.h"
8 :
9 : #include <limits.h>
10 : #include <math.h>
11 :
12 : #include "getopt_long.h"
13 : #include "port/pg_bitutils.h"
14 : #include "portability/instr_time.h"
15 :
16 : static const char *progname;
17 :
18 : static unsigned int test_duration = 3;
19 : static double max_rprct = 99.99;
20 :
21 : /* record duration in powers of 2 nanoseconds */
22 : static long long int histogram[64];
23 :
24 : /* record counts of first 10K durations directly */
25 : #define NUM_DIRECT 10000
26 : static long long int direct_histogram[NUM_DIRECT];
27 :
28 : /* separately record highest observed duration */
29 : static int64 largest_diff;
30 : static long long int largest_diff_count;
31 :
32 :
33 : static void handle_args(int argc, char *argv[]);
34 : static void test_system_timing(void);
35 : #if PG_INSTR_TSC_CLOCK
36 : static void test_tsc_timing(void);
37 : #endif
38 : static uint64 test_timing(unsigned int duration, TimingClockSourceType source, bool fast_timing);
39 : static void output(uint64 loop_count);
40 :
41 : int
42 7 : main(int argc, char *argv[])
43 : {
44 7 : set_pglocale_pgservice(argv[0], PG_TEXTDOMAIN("pg_test_timing"));
45 7 : progname = get_progname(argv[0]);
46 :
47 7 : handle_args(argc, argv);
48 :
49 : /* initialize timing infrastructure (required for INSTR_* calls) */
50 1 : pg_initialize_timing();
51 :
52 1 : test_system_timing();
53 :
54 : #if PG_INSTR_TSC_CLOCK
55 1 : test_tsc_timing();
56 : #endif
57 :
58 1 : return 0;
59 : }
60 :
61 : static void
62 7 : handle_args(int argc, char *argv[])
63 : {
64 : static struct option long_options[] = {
65 : {"duration", required_argument, NULL, 'd'},
66 : {"cutoff", required_argument, NULL, 'c'},
67 : {NULL, 0, NULL, 0}
68 : };
69 :
70 : int option; /* Command line option */
71 7 : int optindex = 0; /* used by getopt_long */
72 : unsigned long optval; /* used for option parsing */
73 : char *endptr;
74 :
75 7 : if (argc > 1)
76 : {
77 7 : if (strcmp(argv[1], "--help") == 0 || strcmp(argv[1], "-?") == 0)
78 : {
79 1 : printf(_("Usage: %s [-d DURATION] [-c CUTOFF]\n"), progname);
80 1 : exit(0);
81 : }
82 6 : if (strcmp(argv[1], "--version") == 0 || strcmp(argv[1], "-V") == 0)
83 : {
84 1 : puts("pg_test_timing (PostgreSQL) " PG_VERSION);
85 1 : exit(0);
86 : }
87 : }
88 :
89 6 : while ((option = getopt_long(argc, argv, "d:c:",
90 6 : long_options, &optindex)) != -1)
91 : {
92 5 : switch (option)
93 : {
94 3 : case 'd':
95 3 : errno = 0;
96 3 : optval = strtoul(optarg, &endptr, 10);
97 :
98 3 : if (endptr == optarg || *endptr != '\0' ||
99 2 : errno != 0 || optval != (unsigned int) optval)
100 : {
101 1 : fprintf(stderr, _("%s: invalid argument for option %s\n"),
102 : progname, "--duration");
103 1 : fprintf(stderr, _("Try \"%s --help\" for more information.\n"), progname);
104 1 : exit(1);
105 : }
106 :
107 2 : test_duration = (unsigned int) optval;
108 2 : if (test_duration == 0)
109 : {
110 1 : fprintf(stderr, _("%s: %s must be in range %u..%u\n"),
111 : progname, "--duration", 1, UINT_MAX);
112 1 : exit(1);
113 : }
114 1 : break;
115 :
116 1 : case 'c':
117 1 : errno = 0;
118 1 : max_rprct = strtod(optarg, &endptr);
119 :
120 1 : if (endptr == optarg || *endptr != '\0' || errno != 0)
121 : {
122 0 : fprintf(stderr, _("%s: invalid argument for option %s\n"),
123 : progname, "--cutoff");
124 0 : fprintf(stderr, _("Try \"%s --help\" for more information.\n"), progname);
125 0 : exit(1);
126 : }
127 :
128 1 : if (max_rprct < 0 || max_rprct > 100)
129 : {
130 1 : fprintf(stderr, _("%s: %s must be in range %u..%u\n"),
131 : progname, "--cutoff", 0, 100);
132 1 : exit(1);
133 : }
134 0 : break;
135 :
136 1 : default:
137 1 : fprintf(stderr, _("Try \"%s --help\" for more information.\n"),
138 : progname);
139 1 : exit(1);
140 : break;
141 : }
142 : }
143 :
144 1 : if (argc > optind)
145 : {
146 0 : fprintf(stderr,
147 0 : _("%s: too many command-line arguments (first is \"%s\")\n"),
148 0 : progname, argv[optind]);
149 0 : fprintf(stderr, _("Try \"%s --help\" for more information.\n"),
150 : progname);
151 0 : exit(1);
152 : }
153 :
154 1 : printf(ngettext("Testing timing overhead for %u second.\n\n",
155 : "Testing timing overhead for %u seconds.\n\n",
156 : test_duration),
157 : test_duration);
158 1 : }
159 :
160 : /*
161 : * This tests default (non-fast) timing code. A clock source for that is
162 : * always available. Hence, we can unconditionally output the result.
163 : */
164 : static void
165 1 : test_system_timing(void)
166 : {
167 : uint64 loop_count;
168 :
169 1 : loop_count = test_timing(test_duration, TIMING_CLOCK_SOURCE_SYSTEM, false);
170 1 : output(loop_count);
171 1 : }
172 :
173 : /*
174 : * If on a supported architecture, test the TSC clock source. This clock
175 : * source is not always available. In that case we print an informational
176 : * message indicating as such.
177 : *
178 : * We first emit "slow" timings (RDTSCP on x86), which are used for higher
179 : * precision measurements when the TSC clock source is enabled. We emit
180 : * "fast" timings second (RDTSC on x86), which is used for faster timing
181 : * measurements with lower precision.
182 : */
183 : #if PG_INSTR_TSC_CLOCK
184 : static void
185 1 : test_tsc_timing(void)
186 : {
187 : uint64 loop_count;
188 : const TscClockSourceInfo *info;
189 :
190 1 : printf("\n");
191 1 : loop_count = test_timing(test_duration, TIMING_CLOCK_SOURCE_TSC, false);
192 1 : if (loop_count > 0)
193 : {
194 1 : output(loop_count);
195 1 : printf("\n");
196 :
197 : /* Now, emit fast timing measurements */
198 1 : loop_count = test_timing(test_duration, TIMING_CLOCK_SOURCE_TSC, true);
199 1 : output(loop_count);
200 1 : printf("\n");
201 : }
202 :
203 : /*
204 : * Report TSC information regardless of whether it was usable, makes
205 : * debugging a lot easier.
206 : */
207 1 : info = pg_timing_tsc_clock_source_info();
208 1 : if (info->frequency_source[0] != '\0')
209 1 : printf(_("TSC frequency source: %s\n"), info->frequency_source);
210 1 : printf(_("TSC frequency in use: %d kHz\n"), info->frequency_khz);
211 :
212 1 : if (info->calibrated_frequency_khz > 0)
213 : {
214 : double diff_pct;
215 :
216 1 : printf(_("TSC frequency from calibration: %d kHz\n"), info->calibrated_frequency_khz);
217 :
218 1 : diff_pct = fabs((double) info->calibrated_frequency_khz - info->frequency_khz) /
219 1 : info->frequency_khz * 100.0;
220 :
221 1 : if (diff_pct > 10.0)
222 : {
223 0 : printf(_("WARNING: Calibrated TSC frequency differs by %.1f%% from the TSC frequency in use\n"),
224 : diff_pct);
225 0 : printf(_("HINT: Consider setting timing_clock_source to 'system'. Report bugs to <%s>.\n"), PACKAGE_BUGREPORT);
226 0 : exit(1);
227 : }
228 : }
229 : else
230 0 : printf(_("TSC calibration did not converge\n"));
231 :
232 : /*
233 : * Report whether TSC was usable and, if so, whether it will be used
234 : * automatically.
235 : */
236 1 : if (loop_count > 0)
237 : {
238 1 : pg_set_timing_clock_source(TIMING_CLOCK_SOURCE_AUTO);
239 1 : if (pg_current_timing_clock_source() == TIMING_CLOCK_SOURCE_TSC)
240 1 : printf(_("\nTSC clock source will be used by default, unless timing_clock_source is set to 'system'.\n"));
241 : else
242 0 : printf(_("\nTSC clock source will not be used by default, unless timing_clock_source is set to 'tsc'.\n"));
243 : }
244 : else
245 0 : printf(_("\nTSC clock source is not usable. Likely unable to determine TSC frequency. Are you running in an unsupported virtualized environment?\n"));
246 1 : }
247 : #endif
248 :
249 : static uint64
250 3 : test_timing(unsigned int duration, TimingClockSourceType source, bool fast_timing)
251 : {
252 3 : uint64 loop_count = 0;
253 : instr_time start_time,
254 : end_time,
255 : prev,
256 : cur;
257 3 : const char *time_source = NULL;
258 :
259 3 : if (!pg_set_timing_clock_source(source))
260 0 : return 0;
261 :
262 3 : time_source = PG_INSTR_SYSTEM_CLOCK_NAME;
263 :
264 : #if PG_INSTR_TSC_CLOCK
265 3 : if (pg_current_timing_clock_source() == TIMING_CLOCK_SOURCE_TSC)
266 2 : time_source = fast_timing ? PG_INSTR_TSC_CLOCK_NAME_FAST : PG_INSTR_TSC_CLOCK_NAME;
267 : #endif
268 :
269 3 : if (fast_timing)
270 1 : printf(_("Fast clock source: %s\n"), time_source);
271 2 : else if (source == TIMING_CLOCK_SOURCE_SYSTEM)
272 1 : printf(_("System clock source: %s\n"), time_source);
273 : else
274 1 : printf(_("Clock source: %s\n"), time_source);
275 :
276 : /*
277 : * Pre-zero the statistics data structures. They're already zero by
278 : * default, but this helps bring them into processor cache and avoid
279 : * possible timing glitches due to COW behavior.
280 : */
281 3 : memset(direct_histogram, 0, sizeof(direct_histogram));
282 3 : memset(histogram, 0, sizeof(histogram));
283 3 : largest_diff = 0;
284 3 : largest_diff_count = 0;
285 :
286 3 : INSTR_TIME_SET_CURRENT(start_time);
287 3 : cur = start_time;
288 :
289 3 : end_time = start_time;
290 3 : INSTR_TIME_ADD_NANOSEC(end_time, duration * NS_PER_S);
291 :
292 11378833 : while (INSTR_TIME_GT(end_time, cur))
293 : {
294 : int64 diff;
295 : int32 bits;
296 : instr_time diff_time;
297 :
298 11378830 : prev = cur;
299 :
300 11378830 : if (fast_timing)
301 4019633 : INSTR_TIME_SET_CURRENT_FAST(cur);
302 : else
303 7359197 : INSTR_TIME_SET_CURRENT(cur);
304 :
305 11378830 : diff_time = cur;
306 11378830 : INSTR_TIME_SUBTRACT(diff_time, prev);
307 11378830 : diff = INSTR_TIME_GET_NANOSEC(diff_time);
308 :
309 : /* Did time go backwards? */
310 11378830 : if (unlikely(diff < 0))
311 : {
312 0 : fprintf(stderr, _("Detected clock going backwards in time.\n"));
313 0 : fprintf(stderr, _("Time warp: %" PRId64 " ns\n"), diff);
314 0 : exit(1);
315 : }
316 :
317 : /* What is the highest bit in the time diff? */
318 11378830 : if (diff > 0)
319 : {
320 11378830 : bits = pg_leftmost_one_pos64(diff) + 1;
321 : /* histogram should be defined large enough */
322 : Assert(bits < lengthof(histogram));
323 : }
324 : else
325 0 : bits = 0;
326 :
327 : /* Update appropriate duration bucket */
328 11378830 : histogram[bits]++;
329 :
330 : /* Update direct histogram of time diffs */
331 11378830 : if (diff < NUM_DIRECT)
332 11378187 : direct_histogram[diff]++;
333 :
334 : /* Also track the largest observed duration, even if >= NUM_DIRECT */
335 11378830 : if (diff > largest_diff)
336 : {
337 26 : largest_diff = diff;
338 26 : largest_diff_count = 1;
339 : }
340 11378804 : else if (diff == largest_diff)
341 0 : largest_diff_count++;
342 :
343 11378830 : loop_count++;
344 : }
345 :
346 : /* Refresh end time to be the actual time spent (vs the target end time) */
347 3 : INSTR_TIME_SET_CURRENT(end_time);
348 :
349 3 : INSTR_TIME_SUBTRACT(end_time, start_time);
350 :
351 3 : printf(_("Average loop time including overhead: %0.2f ns\n"),
352 : INSTR_TIME_GET_DOUBLE(end_time) * NS_PER_S / loop_count);
353 :
354 3 : return loop_count;
355 : }
356 :
357 : static void
358 3 : output(uint64 loop_count)
359 : {
360 3 : int max_bit = lengthof(histogram) - 1;
361 3 : const char *header1 = _("<= ns");
362 3 : const char *header1b = _("ns");
363 3 : const char *header2 = /* xgettext:no-c-format */ _("% of total");
364 3 : const char *header3 = /* xgettext:no-c-format */ _("running %");
365 3 : const char *header4 = _("count");
366 3 : int len1 = strlen(header1);
367 3 : int len2 = strlen(header2);
368 3 : int len3 = strlen(header3);
369 3 : int len4 = strlen(header4);
370 : double rprct;
371 3 : bool stopped = false;
372 :
373 3 : if (loop_count == 0)
374 : {
375 0 : printf(_("WARNING: No timing measurements collected. Report this as a bug to <%s>.\n"), PACKAGE_BUGREPORT);
376 0 : return;
377 : }
378 :
379 : /* find highest bit value */
380 112 : while (max_bit > 0 && histogram[max_bit] == 0)
381 109 : max_bit--;
382 :
383 : /* set minimum column widths */
384 3 : len1 = Max(19, len1);
385 3 : len2 = Max(10, len2);
386 3 : len3 = Max(10, len3);
387 3 : len4 = Max(10, len4);
388 :
389 3 : printf(_("Histogram of timing durations:\n"));
390 3 : printf("%*s %*s %*s %*s\n",
391 : len1, header1,
392 : len2, header2,
393 : len3, header3,
394 : len4, header4);
395 :
396 3 : rprct = 0;
397 86 : for (int i = 0; i <= max_bit; i++)
398 : {
399 83 : double prct = (double) histogram[i] * 100 / loop_count;
400 :
401 83 : rprct += prct;
402 83 : printf("%*llu %*.4f %*.4f %*lld\n",
403 : len1, (1ULL << i) - 1,
404 : len2, prct,
405 : len3, rprct,
406 : len4, histogram[i]);
407 : }
408 :
409 3 : printf(_("\nObserved timing durations up to %.4f%%:\n"), max_rprct);
410 3 : printf("%*s %*s %*s %*s\n",
411 : len1, header1b,
412 : len2, header2,
413 : len3, header3,
414 : len4, header4);
415 :
416 3 : rprct = 0;
417 30003 : for (int i = 0; i < NUM_DIRECT; i++)
418 : {
419 30000 : if (direct_histogram[i])
420 : {
421 1342 : double prct = (double) direct_histogram[i] * 100 / loop_count;
422 1342 : bool print_it = !stopped;
423 :
424 1342 : rprct += prct;
425 :
426 : /* if largest diff is < NUM_DIRECT, be sure we print it */
427 1342 : if (i == largest_diff)
428 : {
429 0 : if (stopped)
430 0 : printf("...\n");
431 0 : print_it = true;
432 : }
433 :
434 1342 : if (print_it)
435 933 : printf("%*d %*.4f %*.4f %*lld\n",
436 : len1, i,
437 : len2, prct,
438 : len3, rprct,
439 : len4, direct_histogram[i]);
440 1342 : if (rprct >= max_rprct)
441 412 : stopped = true;
442 : }
443 : }
444 :
445 : /* print largest diff when it's outside the array range */
446 3 : if (largest_diff >= NUM_DIRECT)
447 : {
448 3 : double prct = (double) largest_diff_count * 100 / loop_count;
449 :
450 3 : printf("...\n");
451 3 : printf("%*lld %*.4f %*.4f %*lld\n",
452 : len1, (long long) largest_diff,
453 : len2, prct,
454 : len3, 100.0,
455 : len4, largest_diff_count);
456 : }
457 : }
|
