Age Owner Branch data TLA 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
5177 rhaas@postgresql.org 42 :CBC 7 : main(int argc, char *argv[])
43 : : {
3515 peter_e@gmx.net 44 : 7 : set_pglocale_pgservice(argv[0], PG_TEXTDOMAIN("pg_test_timing"));
5177 rhaas@postgresql.org 45 : 7 : progname = get_progname(argv[0]);
46 : :
47 : 7 : handle_args(argc, argv);
48 : :
49 : : /* initialize timing infrastructure (required for INSTR_* calls) */
53 andres@anarazel.de 50 :GNC 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 : :
5177 rhaas@postgresql.org 58 :GBC 1 : return 0;
59 : : }
60 : :
61 : : static void
5177 rhaas@postgresql.org 62 :CBC 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 */
5102 bruce@momjian.us 71 : 7 : int optindex = 0; /* used by getopt_long */
72 : : unsigned long optval; /* used for option parsing */
73 : : char *endptr;
74 : :
5177 rhaas@postgresql.org 75 [ + - ]: 7 : if (argc > 1)
76 : : {
4716 bruce@momjian.us 77 [ + + - + ]: 7 : if (strcmp(argv[1], "--help") == 0 || strcmp(argv[1], "-?") == 0)
78 : : {
326 tgl@sss.pgh.pa.us 79 :GNC 1 : printf(_("Usage: %s [-d DURATION] [-c CUTOFF]\n"), progname);
5177 rhaas@postgresql.org 80 :CBC 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 : :
326 tgl@sss.pgh.pa.us 89 :GNC 6 : while ((option = getopt_long(argc, argv, "d:c:",
5177 rhaas@postgresql.org 90 [ + + ]:CBC 6 : long_options, &optindex)) != -1)
91 : : {
92 [ + + ]: 5 : switch (option)
[ + + + ]
93 : : {
94 : 3 : case 'd':
2070 michael@paquier.xyz 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 : : }
5177 rhaas@postgresql.org 114 :GBC 1 : break;
115 : :
326 tgl@sss.pgh.pa.us 116 :GNC 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 : : {
326 tgl@sss.pgh.pa.us 122 :UNC 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 : :
326 tgl@sss.pgh.pa.us 128 [ + - + - ]:GNC 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 : : }
326 tgl@sss.pgh.pa.us 134 :UNC 0 : break;
135 : :
5177 rhaas@postgresql.org 136 :CBC 1 : default:
3515 peter_e@gmx.net 137 : 1 : fprintf(stderr, _("Try \"%s --help\" for more information.\n"),
138 : : progname);
5177 rhaas@postgresql.org 139 : 1 : exit(1);
140 : : break;
141 : : }
142 : : }
143 : :
5177 rhaas@postgresql.org 144 [ - + ]:GBC 1 : if (argc > optind)
145 : : {
5177 rhaas@postgresql.org 146 :UBC 0 : fprintf(stderr,
3515 peter_e@gmx.net 147 : 0 : _("%s: too many command-line arguments (first is \"%s\")\n"),
5177 rhaas@postgresql.org 148 : 0 : progname, argv[optind]);
3515 peter_e@gmx.net 149 : 0 : fprintf(stderr, _("Try \"%s --help\" for more information.\n"),
150 : : progname);
5177 rhaas@postgresql.org 151 : 0 : exit(1);
152 : : }
153 : :
53 andres@anarazel.de 154 :GNC 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);
5177 rhaas@postgresql.org 158 :GBC 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
53 andres@anarazel.de 165 :GNC 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 : : */
14 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 : : {
14 andres@anarazel.de 223 :UNC 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 : : */
14 andres@anarazel.de 236 [ + - ]:GNC 1 : if (loop_count > 0)
237 : : {
53 238 : 1 : pg_set_timing_clock_source(TIMING_CLOCK_SOURCE_AUTO);
239 [ + - ]: 1 : if (pg_current_timing_clock_source() == TIMING_CLOCK_SOURCE_TSC)
14 240 : 1 : printf(_("\nTSC clock source will be used by default, unless timing_clock_source is set to 'system'.\n"));
241 : : else
14 andres@anarazel.de 242 :UNC 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"));
53 andres@anarazel.de 246 :GNC 1 : }
247 : : #endif
248 : :
249 : : static uint64
250 : 3 : test_timing(unsigned int duration, TimingClockSourceType source, bool fast_timing)
251 : : {
5102 bruce@momjian.us 252 :GBC 3 : uint64 loop_count = 0;
253 : : instr_time start_time,
254 : : end_time,
255 : : prev,
256 : : cur;
53 andres@anarazel.de 257 :GNC 3 : const char *time_source = NULL;
258 : :
259 [ - + ]: 3 : if (!pg_set_timing_clock_source(source))
53 andres@anarazel.de 260 :UNC 0 : return 0;
261 : :
53 andres@anarazel.de 262 :GNC 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 : : */
325 tgl@sss.pgh.pa.us 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 : :
5177 rhaas@postgresql.org 286 :GBC 3 : INSTR_TIME_SET_CURRENT(start_time);
59 andres@anarazel.de 287 :GNC 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 [ + + ]: 60083413 : while (INSTR_TIME_GT(end_time, cur))
293 : : {
294 : : int64 diff;
295 : : int32 bits;
296 : : instr_time diff_time;
297 : :
5177 rhaas@postgresql.org 298 :GBC 60083410 : prev = cur;
299 : :
53 andres@anarazel.de 300 [ + + ]:GNC 60083410 : if (fast_timing)
301 : 21412027 : INSTR_TIME_SET_CURRENT_FAST(cur);
302 : : else
303 : 38671383 : INSTR_TIME_SET_CURRENT(cur);
304 : :
59 305 : 60083410 : diff_time = cur;
306 : 60083410 : INSTR_TIME_SUBTRACT(diff_time, prev);
307 : 60083410 : diff = INSTR_TIME_GET_NANOSEC(diff_time);
308 : :
309 : : /* Did time go backwards? */
325 tgl@sss.pgh.pa.us 310 [ - + ]: 60083410 : if (unlikely(diff < 0))
311 : : {
3515 peter_e@gmx.net 312 :UBC 0 : fprintf(stderr, _("Detected clock going backwards in time.\n"));
35 peter@eisentraut.org 313 :UNC 0 : fprintf(stderr, _("Time warp: %" PRId64 " ns\n"), diff);
5177 rhaas@postgresql.org 314 :UBC 0 : exit(1);
315 : : }
316 : :
317 : : /* What is the highest bit in the time diff? */
326 tgl@sss.pgh.pa.us 318 [ + - ]:GNC 60083410 : if (diff > 0)
319 : : {
36 fujii@postgresql.org 320 : 60083410 : bits = pg_leftmost_one_pos64(diff) + 1;
321 : : /* histogram should be defined large enough */
322 [ - + ]: 60083410 : Assert(bits < lengthof(histogram));
323 : : }
324 : : else
326 tgl@sss.pgh.pa.us 325 :UNC 0 : bits = 0;
326 : :
327 : : /* Update appropriate duration bucket */
5177 rhaas@postgresql.org 328 :GBC 60083410 : histogram[bits]++;
329 : :
330 : : /* Update direct histogram of time diffs */
326 tgl@sss.pgh.pa.us 331 [ + + ]:GNC 60083410 : if (diff < NUM_DIRECT)
332 : 60080485 : direct_histogram[diff]++;
333 : :
334 : : /* Also track the largest observed duration, even if >= NUM_DIRECT */
335 [ + + ]: 60083410 : if (diff > largest_diff)
336 : : {
337 : 32 : largest_diff = diff;
338 : 32 : largest_diff_count = 1;
339 : : }
340 [ + + ]: 60083378 : else if (diff == largest_diff)
341 : 1 : largest_diff_count++;
342 : :
5177 rhaas@postgresql.org 343 :GBC 60083410 : 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 : :
325 tgl@sss.pgh.pa.us 351 :GNC 3 : printf(_("Average loop time including overhead: %0.2f ns\n"),
352 : : INSTR_TIME_GET_DOUBLE(end_time) * NS_PER_S / loop_count);
353 : :
5023 bruce@momjian.us 354 :GBC 3 : return loop_count;
355 : : }
356 : :
357 : : static void
358 : 3 : output(uint64 loop_count)
359 : : {
36 fujii@postgresql.org 360 :GNC 3 : int max_bit = lengthof(histogram) - 1;
326 tgl@sss.pgh.pa.us 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");
3199 peter_e@gmx.net 366 :GBC 3 : int len1 = strlen(header1);
367 : 3 : int len2 = strlen(header2);
368 : 3 : int len3 = strlen(header3);
326 tgl@sss.pgh.pa.us 369 :GNC 3 : int len4 = strlen(header4);
370 : : double rprct;
371 : 3 : bool stopped = false;
372 : :
14 andres@anarazel.de 373 [ - + ]: 3 : if (loop_count == 0)
374 : : {
14 andres@anarazel.de 375 :UNC 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 */
5023 bruce@momjian.us 380 [ + - + + ]:GBC 126 : while (max_bit > 0 && histogram[max_bit] == 0)
381 : 123 : max_bit--;
382 : :
383 : : /* set minimum column widths */
36 fujii@postgresql.org 384 :GNC 3 : len1 = Max(19, len1);
326 tgl@sss.pgh.pa.us 385 : 3 : len2 = Max(10, len2);
386 : 3 : len3 = Max(10, len3);
387 : 3 : len4 = Max(10, len4);
388 : :
3515 peter_e@gmx.net 389 :GBC 3 : printf(_("Histogram of timing durations:\n"));
326 tgl@sss.pgh.pa.us 390 :GNC 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 [ + + ]: 72 : for (int i = 0; i <= max_bit; i++)
398 : : {
399 : 69 : double prct = (double) histogram[i] * 100 / loop_count;
400 : :
401 : 69 : rprct += prct;
36 fujii@postgresql.org 402 : 69 : printf("%*llu %*.4f %*.4f %*lld\n",
403 : : len1, (1ULL << i) - 1,
404 : : len2, prct,
405 : : len3, rprct,
406 : : len4, histogram[i]);
407 : : }
408 : :
326 tgl@sss.pgh.pa.us 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 : 1348 : double prct = (double) direct_histogram[i] * 100 / loop_count;
422 : 1348 : bool print_it = !stopped;
423 : :
424 : 1348 : rprct += prct;
425 : :
426 : : /* if largest diff is < NUM_DIRECT, be sure we print it */
427 [ - + ]: 1348 : if (i == largest_diff)
428 : : {
326 tgl@sss.pgh.pa.us 429 [ # # ]:UNC 0 : if (stopped)
430 : 0 : printf("...\n");
431 : 0 : print_it = true;
432 : : }
433 : :
326 tgl@sss.pgh.pa.us 434 [ + + ]:GNC 1348 : if (print_it)
435 : 363 : printf("%*d %*.4f %*.4f %*lld\n",
436 : : len1, i,
437 : : len2, prct,
438 : : len3, rprct,
439 : : len4, direct_histogram[i]);
440 [ + + ]: 1348 : if (rprct >= max_rprct)
441 : 988 : 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");
36 fujii@postgresql.org 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 : : }
5177 rhaas@postgresql.org 457 :EUB : }
|
