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