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
41 7 : main(int argc, char *argv[])
42 : {
43 7 : set_pglocale_pgservice(argv[0], PG_TEXTDOMAIN("pg_test_timing"));
44 7 : progname = get_progname(argv[0]);
45 :
46 7 : handle_args(argc, argv);
47 :
48 : /* initialize timing infrastructure (required for INSTR_* calls) */
49 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 :
57 1 : return 0;
58 : }
59 :
60 : static void
61 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 */
70 7 : int optindex = 0; /* used by getopt_long */
71 : unsigned long optval; /* used for option parsing */
72 : char *endptr;
73 :
74 7 : if (argc > 1)
75 : {
76 7 : if (strcmp(argv[1], "--help") == 0 || strcmp(argv[1], "-?") == 0)
77 : {
78 1 : printf(_("Usage: %s [-d DURATION] [-c CUTOFF]\n"), progname);
79 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 :
88 6 : while ((option = getopt_long(argc, argv, "d:c:",
89 6 : long_options, &optindex)) != -1)
90 : {
91 5 : switch (option)
92 : {
93 3 : case 'd':
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 : }
113 1 : break;
114 :
115 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 : {
121 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 :
127 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 : }
133 0 : break;
134 :
135 1 : default:
136 1 : fprintf(stderr, _("Try \"%s --help\" for more information.\n"),
137 : progname);
138 1 : exit(1);
139 : break;
140 : }
141 : }
142 :
143 1 : if (argc > optind)
144 : {
145 0 : fprintf(stderr,
146 0 : _("%s: too many command-line arguments (first is \"%s\")\n"),
147 0 : progname, argv[optind]);
148 0 : fprintf(stderr, _("Try \"%s --help\" for more information.\n"),
149 : progname);
150 0 : exit(1);
151 : }
152 :
153 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);
157 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
164 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
207 0 : printf(_("TSC calibration did not converge\n"));
208 :
209 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
213 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"));
217 1 : }
218 : #endif
219 :
220 : static uint64
221 3 : test_timing(unsigned int duration, TimingClockSourceType source, bool fast_timing)
222 : {
223 3 : uint64 loop_count = 0;
224 : instr_time start_time,
225 : end_time,
226 : prev,
227 : cur;
228 3 : const char *time_source = NULL;
229 :
230 3 : if (!pg_set_timing_clock_source(source))
231 0 : return 0;
232 :
233 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 : */
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 :
257 3 : INSTR_TIME_SET_CURRENT(start_time);
258 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 15817568 : while (INSTR_TIME_GT(end_time, cur))
264 : {
265 : int64 diff;
266 : int32 bits;
267 : instr_time diff_time;
268 :
269 15817565 : prev = cur;
270 :
271 15817565 : if (fast_timing)
272 8819376 : INSTR_TIME_SET_CURRENT_FAST(cur);
273 : else
274 6998189 : INSTR_TIME_SET_CURRENT(cur);
275 :
276 15817565 : diff_time = cur;
277 15817565 : INSTR_TIME_SUBTRACT(diff_time, prev);
278 15817565 : diff = INSTR_TIME_GET_NANOSEC(diff_time);
279 :
280 : /* Did time go backwards? */
281 15817565 : if (unlikely(diff < 0))
282 : {
283 0 : fprintf(stderr, _("Detected clock going backwards in time.\n"));
284 0 : fprintf(stderr, _("Time warp: %" PRId64 " ns\n"), diff);
285 0 : exit(1);
286 : }
287 :
288 : /* What is the highest bit in the time diff? */
289 15817565 : if (diff > 0)
290 : {
291 15817565 : bits = pg_leftmost_one_pos64(diff) + 1;
292 : /* histogram should be defined large enough */
293 : Assert(bits < lengthof(histogram));
294 : }
295 : else
296 0 : bits = 0;
297 :
298 : /* Update appropriate duration bucket */
299 15817565 : histogram[bits]++;
300 :
301 : /* Update direct histogram of time diffs */
302 15817565 : if (diff < NUM_DIRECT)
303 15816568 : direct_histogram[diff]++;
304 :
305 : /* Also track the largest observed duration, even if >= NUM_DIRECT */
306 15817565 : if (diff > largest_diff)
307 : {
308 27 : largest_diff = diff;
309 27 : largest_diff_count = 1;
310 : }
311 15817538 : else if (diff == largest_diff)
312 1 : largest_diff_count++;
313 :
314 15817565 : 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 :
322 3 : printf(_("Average loop time including overhead: %0.2f ns\n"),
323 : INSTR_TIME_GET_DOUBLE(end_time) * NS_PER_S / loop_count);
324 :
325 3 : return loop_count;
326 : }
327 :
328 : static void
329 3 : output(uint64 loop_count)
330 : {
331 3 : int max_bit = lengthof(histogram) - 1;
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");
337 3 : int len1 = strlen(header1);
338 3 : int len2 = strlen(header2);
339 3 : int len3 = strlen(header3);
340 3 : int len4 = strlen(header4);
341 : double rprct;
342 3 : bool stopped = false;
343 :
344 : /* find highest bit value */
345 111 : while (max_bit > 0 && histogram[max_bit] == 0)
346 108 : max_bit--;
347 :
348 : /* set minimum column widths */
349 3 : len1 = Max(19, len1);
350 3 : len2 = Max(10, len2);
351 3 : len3 = Max(10, len3);
352 3 : len4 = Max(10, len4);
353 :
354 3 : printf(_("Histogram of timing durations:\n"));
355 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 87 : for (int i = 0; i <= max_bit; i++)
363 : {
364 84 : double prct = (double) histogram[i] * 100 / loop_count;
365 :
366 84 : rprct += prct;
367 84 : printf("%*llu %*.4f %*.4f %*lld\n",
368 : len1, (1ULL << i) - 1,
369 : len2, prct,
370 : len3, rprct,
371 : len4, histogram[i]);
372 : }
373 :
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 1753 : double prct = (double) direct_histogram[i] * 100 / loop_count;
387 1753 : bool print_it = !stopped;
388 :
389 1753 : rprct += prct;
390 :
391 : /* if largest diff is < NUM_DIRECT, be sure we print it */
392 1753 : if (i == largest_diff)
393 : {
394 0 : if (stopped)
395 0 : printf("...\n");
396 0 : print_it = true;
397 : }
398 :
399 1753 : if (print_it)
400 1309 : printf("%*d %*.4f %*.4f %*lld\n",
401 : len1, i,
402 : len2, prct,
403 : len3, rprct,
404 : len4, direct_histogram[i]);
405 1753 : if (rprct >= max_rprct)
406 447 : 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");
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 : }
422 3 : }
|
