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