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 1 : uint64 loop_count = 0;
156 : instr_time start_time,
157 : end_time,
158 : prev,
159 : cur;
160 :
161 : /*
162 : * Pre-zero the statistics data structures. They're already zero by
163 : * default, but this helps bring them into processor cache and avoid
164 : * possible timing glitches due to COW behavior.
165 : */
166 1 : memset(direct_histogram, 0, sizeof(direct_histogram));
167 1 : memset(histogram, 0, sizeof(histogram));
168 1 : largest_diff = 0;
169 1 : largest_diff_count = 0;
170 :
171 1 : INSTR_TIME_SET_CURRENT(start_time);
172 1 : cur = start_time;
173 :
174 1 : end_time = start_time;
175 1 : INSTR_TIME_ADD_NANOSEC(end_time, duration * NS_PER_S);
176 :
177 3768507 : while (INSTR_TIME_GT(end_time, cur))
178 : {
179 : int32 diff,
180 : bits;
181 : instr_time diff_time;
182 :
183 3768506 : prev = cur;
184 3768506 : INSTR_TIME_SET_CURRENT(cur);
185 :
186 3768506 : diff_time = cur;
187 3768506 : INSTR_TIME_SUBTRACT(diff_time, prev);
188 3768506 : diff = INSTR_TIME_GET_NANOSEC(diff_time);
189 :
190 : /* Did time go backwards? */
191 3768506 : if (unlikely(diff < 0))
192 : {
193 0 : fprintf(stderr, _("Detected clock going backwards in time.\n"));
194 0 : fprintf(stderr, _("Time warp: %d ms\n"), diff);
195 0 : exit(1);
196 : }
197 :
198 : /* What is the highest bit in the time diff? */
199 3768506 : if (diff > 0)
200 3768506 : bits = pg_leftmost_one_pos32(diff) + 1;
201 : else
202 0 : bits = 0;
203 :
204 : /* Update appropriate duration bucket */
205 3768506 : histogram[bits]++;
206 :
207 : /* Update direct histogram of time diffs */
208 3768506 : if (diff < NUM_DIRECT)
209 3768274 : direct_histogram[diff]++;
210 :
211 : /* Also track the largest observed duration, even if >= NUM_DIRECT */
212 3768506 : if (diff > largest_diff)
213 : {
214 10 : largest_diff = diff;
215 10 : largest_diff_count = 1;
216 : }
217 3768496 : else if (diff == largest_diff)
218 0 : largest_diff_count++;
219 :
220 3768506 : loop_count++;
221 : }
222 :
223 : /* Refresh end time to be the actual time spent (vs the target end time) */
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 5 : while (max_bit > 0 && histogram[max_bit] == 0)
252 4 : 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 29 : for (int i = 0; i <= max_bit; i++)
269 : {
270 28 : double prct = (double) histogram[i] * 100 / loop_count;
271 :
272 28 : rprct += prct;
273 28 : 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 489 : double prct = (double) direct_histogram[i] * 100 / loop_count;
293 489 : bool print_it = !stopped;
294 :
295 489 : rprct += prct;
296 :
297 : /* if largest diff is < NUM_DIRECT, be sure we print it */
298 489 : if (i == largest_diff)
299 : {
300 0 : if (stopped)
301 0 : printf("...\n");
302 0 : print_it = true;
303 : }
304 :
305 489 : if (print_it)
306 362 : printf("%*d %*.4f %*.4f %*lld\n",
307 : len1, i,
308 : len2, prct,
309 : len3, rprct,
310 : len4, direct_histogram[i]);
311 489 : if (rprct >= max_rprct)
312 128 : 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 : }
|
