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[32];
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 int32 largest_diff;
29 : static long long int largest_diff_count;
30 :
31 :
32 : static void handle_args(int argc, char *argv[]);
33 : static uint64 test_timing(unsigned int duration);
34 : static void output(uint64 loop_count);
35 :
36 : int
37 7 : main(int argc, char *argv[])
38 : {
39 : uint64 loop_count;
40 :
41 7 : set_pglocale_pgservice(argv[0], PG_TEXTDOMAIN("pg_test_timing"));
42 7 : progname = get_progname(argv[0]);
43 :
44 7 : handle_args(argc, argv);
45 :
46 1 : loop_count = test_timing(test_duration);
47 :
48 1 : output(loop_count);
49 :
50 1 : return 0;
51 : }
52 :
53 : static void
54 7 : handle_args(int argc, char *argv[])
55 : {
56 : static struct option long_options[] = {
57 : {"duration", required_argument, NULL, 'd'},
58 : {"cutoff", required_argument, NULL, 'c'},
59 : {NULL, 0, NULL, 0}
60 : };
61 :
62 : int option; /* Command line option */
63 7 : int optindex = 0; /* used by getopt_long */
64 : unsigned long optval; /* used for option parsing */
65 : char *endptr;
66 :
67 7 : if (argc > 1)
68 : {
69 7 : if (strcmp(argv[1], "--help") == 0 || strcmp(argv[1], "-?") == 0)
70 : {
71 1 : printf(_("Usage: %s [-d DURATION] [-c CUTOFF]\n"), progname);
72 1 : exit(0);
73 : }
74 6 : if (strcmp(argv[1], "--version") == 0 || strcmp(argv[1], "-V") == 0)
75 : {
76 1 : puts("pg_test_timing (PostgreSQL) " PG_VERSION);
77 1 : exit(0);
78 : }
79 : }
80 :
81 6 : while ((option = getopt_long(argc, argv, "d:c:",
82 6 : long_options, &optindex)) != -1)
83 : {
84 5 : switch (option)
85 : {
86 3 : case 'd':
87 3 : errno = 0;
88 3 : optval = strtoul(optarg, &endptr, 10);
89 :
90 3 : if (endptr == optarg || *endptr != '\0' ||
91 2 : errno != 0 || optval != (unsigned int) optval)
92 : {
93 1 : fprintf(stderr, _("%s: invalid argument for option %s\n"),
94 : progname, "--duration");
95 1 : fprintf(stderr, _("Try \"%s --help\" for more information.\n"), progname);
96 1 : exit(1);
97 : }
98 :
99 2 : test_duration = (unsigned int) optval;
100 2 : if (test_duration == 0)
101 : {
102 1 : fprintf(stderr, _("%s: %s must be in range %u..%u\n"),
103 : progname, "--duration", 1, UINT_MAX);
104 1 : exit(1);
105 : }
106 1 : break;
107 :
108 1 : case 'c':
109 1 : errno = 0;
110 1 : max_rprct = strtod(optarg, &endptr);
111 :
112 1 : if (endptr == optarg || *endptr != '\0' || errno != 0)
113 : {
114 0 : fprintf(stderr, _("%s: invalid argument for option %s\n"),
115 : progname, "--cutoff");
116 0 : fprintf(stderr, _("Try \"%s --help\" for more information.\n"), progname);
117 0 : exit(1);
118 : }
119 :
120 1 : if (max_rprct < 0 || max_rprct > 100)
121 : {
122 1 : fprintf(stderr, _("%s: %s must be in range %u..%u\n"),
123 : progname, "--cutoff", 0, 100);
124 1 : exit(1);
125 : }
126 0 : break;
127 :
128 1 : default:
129 1 : fprintf(stderr, _("Try \"%s --help\" for more information.\n"),
130 : progname);
131 1 : exit(1);
132 : break;
133 : }
134 : }
135 :
136 1 : if (argc > optind)
137 : {
138 0 : fprintf(stderr,
139 0 : _("%s: too many command-line arguments (first is \"%s\")\n"),
140 0 : progname, argv[optind]);
141 0 : fprintf(stderr, _("Try \"%s --help\" for more information.\n"),
142 : progname);
143 0 : exit(1);
144 : }
145 :
146 1 : printf(ngettext("Testing timing overhead for %u second.\n",
147 : "Testing timing overhead for %u seconds.\n",
148 : test_duration),
149 : test_duration);
150 1 : }
151 :
152 : static uint64
153 1 : test_timing(unsigned int duration)
154 : {
155 : uint64 total_time;
156 1 : int64 time_elapsed = 0;
157 1 : uint64 loop_count = 0;
158 : uint64 prev,
159 : cur;
160 : instr_time start_time,
161 : end_time,
162 : temp;
163 :
164 : /*
165 : * Pre-zero the statistics data structures. They're already zero by
166 : * default, but this helps bring them into processor cache and avoid
167 : * possible timing glitches due to COW behavior.
168 : */
169 1 : memset(direct_histogram, 0, sizeof(direct_histogram));
170 1 : memset(histogram, 0, sizeof(histogram));
171 1 : largest_diff = 0;
172 1 : largest_diff_count = 0;
173 :
174 1 : total_time = duration > 0 ? duration * INT64CONST(1000000000) : 0;
175 :
176 1 : INSTR_TIME_SET_CURRENT(start_time);
177 1 : cur = INSTR_TIME_GET_NANOSEC(start_time);
178 :
179 9898041 : while (time_elapsed < total_time)
180 : {
181 : int32 diff,
182 : bits;
183 :
184 9898040 : prev = cur;
185 9898040 : INSTR_TIME_SET_CURRENT(temp);
186 9898040 : cur = INSTR_TIME_GET_NANOSEC(temp);
187 9898040 : diff = cur - prev;
188 :
189 : /* Did time go backwards? */
190 9898040 : if (unlikely(diff < 0))
191 : {
192 0 : fprintf(stderr, _("Detected clock going backwards in time.\n"));
193 0 : fprintf(stderr, _("Time warp: %d ms\n"), diff);
194 0 : exit(1);
195 : }
196 :
197 : /* What is the highest bit in the time diff? */
198 9898040 : if (diff > 0)
199 9898040 : bits = pg_leftmost_one_pos32(diff) + 1;
200 : else
201 0 : bits = 0;
202 :
203 : /* Update appropriate duration bucket */
204 9898040 : histogram[bits]++;
205 :
206 : /* Update direct histogram of time diffs */
207 9898040 : if (diff < NUM_DIRECT)
208 9897774 : direct_histogram[diff]++;
209 :
210 : /* Also track the largest observed duration, even if >= NUM_DIRECT */
211 9898040 : if (diff > largest_diff)
212 : {
213 8 : largest_diff = diff;
214 8 : largest_diff_count = 1;
215 : }
216 9898032 : else if (diff == largest_diff)
217 0 : largest_diff_count++;
218 :
219 9898040 : loop_count++;
220 9898040 : INSTR_TIME_SUBTRACT(temp, start_time);
221 9898040 : time_elapsed = INSTR_TIME_GET_NANOSEC(temp);
222 : }
223 :
224 1 : INSTR_TIME_SET_CURRENT(end_time);
225 :
226 1 : INSTR_TIME_SUBTRACT(end_time, start_time);
227 :
228 1 : printf(_("Average loop time including overhead: %0.2f ns\n"),
229 : INSTR_TIME_GET_DOUBLE(end_time) * 1e9 / loop_count);
230 :
231 1 : return loop_count;
232 : }
233 :
234 : static void
235 1 : output(uint64 loop_count)
236 : {
237 1 : int max_bit = 31;
238 1 : const char *header1 = _("<= ns");
239 1 : const char *header1b = _("ns");
240 1 : const char *header2 = /* xgettext:no-c-format */ _("% of total");
241 1 : const char *header3 = /* xgettext:no-c-format */ _("running %");
242 1 : const char *header4 = _("count");
243 1 : int len1 = strlen(header1);
244 1 : int len2 = strlen(header2);
245 1 : int len3 = strlen(header3);
246 1 : int len4 = strlen(header4);
247 : double rprct;
248 1 : bool stopped = false;
249 :
250 : /* find highest bit value */
251 6 : while (max_bit > 0 && histogram[max_bit] == 0)
252 5 : max_bit--;
253 :
254 : /* set minimum column widths */
255 1 : len1 = Max(8, len1);
256 1 : len2 = Max(10, len2);
257 1 : len3 = Max(10, len3);
258 1 : len4 = Max(10, len4);
259 :
260 1 : printf(_("Histogram of timing durations:\n"));
261 1 : printf("%*s %*s %*s %*s\n",
262 : len1, header1,
263 : len2, header2,
264 : len3, header3,
265 : len4, header4);
266 :
267 1 : rprct = 0;
268 28 : for (int i = 0; i <= max_bit; i++)
269 : {
270 27 : double prct = (double) histogram[i] * 100 / loop_count;
271 :
272 27 : rprct += prct;
273 27 : printf("%*ld %*.4f %*.4f %*lld\n",
274 : len1, (1L << i) - 1,
275 : len2, prct,
276 : len3, rprct,
277 : len4, histogram[i]);
278 : }
279 :
280 1 : printf(_("\nObserved timing durations up to %.4f%%:\n"), max_rprct);
281 1 : printf("%*s %*s %*s %*s\n",
282 : len1, header1b,
283 : len2, header2,
284 : len3, header3,
285 : len4, header4);
286 :
287 1 : rprct = 0;
288 10001 : for (int i = 0; i < NUM_DIRECT; i++)
289 : {
290 10000 : if (direct_histogram[i])
291 : {
292 817 : double prct = (double) direct_histogram[i] * 100 / loop_count;
293 817 : bool print_it = !stopped;
294 :
295 817 : rprct += prct;
296 :
297 : /* if largest diff is < NUM_DIRECT, be sure we print it */
298 817 : if (i == largest_diff)
299 : {
300 0 : if (stopped)
301 0 : printf("...\n");
302 0 : print_it = true;
303 : }
304 :
305 817 : if (print_it)
306 436 : printf("%*d %*.4f %*.4f %*lld\n",
307 : len1, i,
308 : len2, prct,
309 : len3, rprct,
310 : len4, direct_histogram[i]);
311 817 : if (rprct >= max_rprct)
312 382 : stopped = true;
313 : }
314 : }
315 :
316 : /* print largest diff when it's outside the array range */
317 1 : if (largest_diff >= NUM_DIRECT)
318 : {
319 1 : double prct = (double) largest_diff_count * 100 / loop_count;
320 :
321 1 : printf("...\n");
322 1 : printf("%*d %*.4f %*.4f %*lld\n",
323 : len1, largest_diff,
324 : len2, prct,
325 : len3, 100.0,
326 : len4, largest_diff_count);
327 : }
328 1 : }
|
