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[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
4911 rhaas@postgresql.org 37 :CBC 7 : main(int argc, char *argv[])
38 : : {
39 : : uint64 loop_count;
40 : :
3249 peter_e@gmx.net 41 : 7 : set_pglocale_pgservice(argv[0], PG_TEXTDOMAIN("pg_test_timing"));
4911 rhaas@postgresql.org 42 : 7 : progname = get_progname(argv[0]);
43 : :
44 : 7 : handle_args(argc, argv);
45 : :
4757 bruce@momjian.us 46 :GBC 1 : loop_count = test_timing(test_duration);
47 : :
48 : 1 : output(loop_count);
49 : :
4911 rhaas@postgresql.org 50 : 1 : return 0;
51 : : }
52 : :
53 : : static void
4911 rhaas@postgresql.org 54 :CBC 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 */
4836 bruce@momjian.us 63 : 7 : int optindex = 0; /* used by getopt_long */
64 : : unsigned long optval; /* used for option parsing */
65 : : char *endptr;
66 : :
4911 rhaas@postgresql.org 67 [ + - ]: 7 : if (argc > 1)
68 : : {
4450 bruce@momjian.us 69 [ + + - + ]: 7 : if (strcmp(argv[1], "--help") == 0 || strcmp(argv[1], "-?") == 0)
70 : : {
60 tgl@sss.pgh.pa.us 71 :GNC 1 : printf(_("Usage: %s [-d DURATION] [-c CUTOFF]\n"), progname);
4911 rhaas@postgresql.org 72 :CBC 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 : :
60 tgl@sss.pgh.pa.us 81 :GNC 6 : while ((option = getopt_long(argc, argv, "d:c:",
4911 rhaas@postgresql.org 82 [ + + ]:CBC 6 : long_options, &optindex)) != -1)
83 : : {
84 [ + + + ]: 5 : switch (option)
85 : : {
86 : 3 : case 'd':
1804 michael@paquier.xyz 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 : : }
4911 rhaas@postgresql.org 106 :GBC 1 : break;
107 : :
60 tgl@sss.pgh.pa.us 108 :GNC 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 : : {
60 tgl@sss.pgh.pa.us 114 :UNC 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 : :
60 tgl@sss.pgh.pa.us 120 [ + - + - ]:GNC 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 : : }
60 tgl@sss.pgh.pa.us 126 :UNC 0 : break;
127 : :
4911 rhaas@postgresql.org 128 :CBC 1 : default:
3249 peter_e@gmx.net 129 : 1 : fprintf(stderr, _("Try \"%s --help\" for more information.\n"),
130 : : progname);
4911 rhaas@postgresql.org 131 : 1 : exit(1);
132 : : break;
133 : : }
134 : : }
135 : :
4911 rhaas@postgresql.org 136 [ - + ]:GBC 1 : if (argc > optind)
137 : : {
4911 rhaas@postgresql.org 138 :UBC 0 : fprintf(stderr,
3249 peter_e@gmx.net 139 : 0 : _("%s: too many command-line arguments (first is \"%s\")\n"),
4911 rhaas@postgresql.org 140 : 0 : progname, argv[optind]);
3249 peter_e@gmx.net 141 : 0 : fprintf(stderr, _("Try \"%s --help\" for more information.\n"),
142 : : progname);
4911 rhaas@postgresql.org 143 : 0 : exit(1);
144 : : }
145 : :
1804 michael@paquier.xyz 146 :GBC 1 : printf(ngettext("Testing timing overhead for %u second.\n",
147 : : "Testing timing overhead for %u seconds.\n",
148 : : test_duration),
149 : : test_duration);
4911 rhaas@postgresql.org 150 : 1 : }
151 : :
152 : : static uint64
1804 michael@paquier.xyz 153 : 1 : test_timing(unsigned int duration)
154 : : {
155 : : uint64 total_time;
4836 bruce@momjian.us 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 : : */
59 tgl@sss.pgh.pa.us 169 :GNC 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 : :
60 174 [ + - ]: 1 : total_time = duration > 0 ? duration * INT64CONST(1000000000) : 0;
175 : :
4911 rhaas@postgresql.org 176 :GBC 1 : INSTR_TIME_SET_CURRENT(start_time);
60 tgl@sss.pgh.pa.us 177 :GNC 1 : cur = INSTR_TIME_GET_NANOSEC(start_time);
178 : :
4911 rhaas@postgresql.org 179 [ + + ]:GBC 15137630 : while (time_elapsed < total_time)
180 : : {
181 : : int32 diff,
182 : : bits;
183 : :
184 : 15137629 : prev = cur;
185 : 15137629 : INSTR_TIME_SET_CURRENT(temp);
60 tgl@sss.pgh.pa.us 186 :GNC 15137629 : cur = INSTR_TIME_GET_NANOSEC(temp);
4911 rhaas@postgresql.org 187 :GBC 15137629 : diff = cur - prev;
188 : :
189 : : /* Did time go backwards? */
59 tgl@sss.pgh.pa.us 190 [ - + ]:GNC 15137629 : if (unlikely(diff < 0))
191 : : {
3249 peter_e@gmx.net 192 :UBC 0 : fprintf(stderr, _("Detected clock going backwards in time.\n"));
193 : 0 : fprintf(stderr, _("Time warp: %d ms\n"), diff);
4911 rhaas@postgresql.org 194 : 0 : exit(1);
195 : : }
196 : :
197 : : /* What is the highest bit in the time diff? */
60 tgl@sss.pgh.pa.us 198 [ + - ]:GNC 15137629 : if (diff > 0)
199 : 15137629 : bits = pg_leftmost_one_pos32(diff) + 1;
200 : : else
60 tgl@sss.pgh.pa.us 201 :UNC 0 : bits = 0;
202 : :
203 : : /* Update appropriate duration bucket */
4911 rhaas@postgresql.org 204 :GBC 15137629 : histogram[bits]++;
205 : :
206 : : /* Update direct histogram of time diffs */
60 tgl@sss.pgh.pa.us 207 [ + + ]:GNC 15137629 : if (diff < NUM_DIRECT)
208 : 15136588 : direct_histogram[diff]++;
209 : :
210 : : /* Also track the largest observed duration, even if >= NUM_DIRECT */
211 [ + + ]: 15137629 : if (diff > largest_diff)
212 : : {
213 : 8 : largest_diff = diff;
214 : 8 : largest_diff_count = 1;
215 : : }
216 [ - + ]: 15137621 : else if (diff == largest_diff)
60 tgl@sss.pgh.pa.us 217 :UNC 0 : largest_diff_count++;
218 : :
4911 rhaas@postgresql.org 219 :GBC 15137629 : loop_count++;
220 : 15137629 : INSTR_TIME_SUBTRACT(temp, start_time);
60 tgl@sss.pgh.pa.us 221 :GNC 15137629 : time_elapsed = INSTR_TIME_GET_NANOSEC(temp);
222 : : }
223 : :
4911 rhaas@postgresql.org 224 :GBC 1 : INSTR_TIME_SET_CURRENT(end_time);
225 : :
226 : 1 : INSTR_TIME_SUBTRACT(end_time, start_time);
227 : :
59 tgl@sss.pgh.pa.us 228 :GNC 1 : printf(_("Average loop time including overhead: %0.2f ns\n"),
229 : : INSTR_TIME_GET_DOUBLE(end_time) * 1e9 / loop_count);
230 : :
4757 bruce@momjian.us 231 :GBC 1 : return loop_count;
232 : : }
233 : :
234 : : static void
235 : 1 : output(uint64 loop_count)
236 : : {
60 tgl@sss.pgh.pa.us 237 :GNC 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");
2933 peter_e@gmx.net 243 :GBC 1 : int len1 = strlen(header1);
244 : 1 : int len2 = strlen(header2);
245 : 1 : int len3 = strlen(header3);
60 tgl@sss.pgh.pa.us 246 :GNC 1 : int len4 = strlen(header4);
247 : : double rprct;
248 : 1 : bool stopped = false;
249 : :
250 : : /* find highest bit value */
4757 bruce@momjian.us 251 [ + - + + ]:GBC 8 : while (max_bit > 0 && histogram[max_bit] == 0)
252 : 7 : max_bit--;
253 : :
254 : : /* set minimum column widths */
60 tgl@sss.pgh.pa.us 255 :GNC 1 : len1 = Max(8, len1);
256 : 1 : len2 = Max(10, len2);
257 : 1 : len3 = Max(10, len3);
258 : 1 : len4 = Max(10, len4);
259 : :
3249 peter_e@gmx.net 260 :GBC 1 : printf(_("Histogram of timing durations:\n"));
60 tgl@sss.pgh.pa.us 261 :GNC 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 [ + + ]: 26 : for (int i = 0; i <= max_bit; i++)
269 : : {
270 : 25 : double prct = (double) histogram[i] * 100 / loop_count;
271 : :
272 : 25 : rprct += prct;
273 : 25 : 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 : 320 : double prct = (double) direct_histogram[i] * 100 / loop_count;
293 : 320 : bool print_it = !stopped;
294 : :
295 : 320 : rprct += prct;
296 : :
297 : : /* if largest diff is < NUM_DIRECT, be sure we print it */
298 [ - + ]: 320 : if (i == largest_diff)
299 : : {
60 tgl@sss.pgh.pa.us 300 [ # # ]:UNC 0 : if (stopped)
301 : 0 : printf("...\n");
302 : 0 : print_it = true;
303 : : }
304 : :
60 tgl@sss.pgh.pa.us 305 [ + + ]:GNC 320 : if (print_it)
306 : 75 : printf("%*d %*.4f %*.4f %*lld\n",
307 : : len1, i,
308 : : len2, prct,
309 : : len3, rprct,
310 : : len4, direct_histogram[i]);
311 [ + + ]: 320 : if (rprct >= max_rprct)
312 : 246 : 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 : : }
4911 rhaas@postgresql.org 328 :GBC 1 : }
|
