Age Owner 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 "portability/instr_time.h"
13 :
14 : static const char *progname;
15 :
16 : static unsigned int test_duration = 3;
17 :
18 : static void handle_args(int argc, char *argv[]);
19 : static uint64 test_timing(unsigned int duration);
20 : static void output(uint64 loop_count);
21 :
22 : /* record duration in powers of 2 microseconds */
23 : long long int histogram[32];
24 :
25 : int
4030 rhaas 26 CBC 5 : main(int argc, char *argv[])
27 : {
28 : uint64 loop_count;
29 :
2368 peter_e 30 5 : set_pglocale_pgservice(argv[0], PG_TEXTDOMAIN("pg_test_timing"));
4030 rhaas 31 5 : progname = get_progname(argv[0]);
32 :
33 5 : handle_args(argc, argv);
34 :
3876 bruce 35 UBC 0 : loop_count = test_timing(test_duration);
36 :
37 0 : output(loop_count);
38 :
4030 rhaas 39 0 : return 0;
40 : }
41 :
42 : static void
4030 rhaas 43 CBC 5 : handle_args(int argc, char *argv[])
44 : {
45 : static struct option long_options[] = {
46 : {"duration", required_argument, NULL, 'd'},
47 : {NULL, 0, NULL, 0}
48 : };
49 :
50 : int option; /* Command line option */
3955 bruce 51 5 : int optindex = 0; /* used by getopt_long */
52 : unsigned long optval; /* used for option parsing */
53 : char *endptr;
54 :
4030 rhaas 55 5 : if (argc > 1)
56 : {
3569 bruce 57 5 : if (strcmp(argv[1], "--help") == 0 || strcmp(argv[1], "-?") == 0)
58 : {
2368 peter_e 59 1 : printf(_("Usage: %s [-d DURATION]\n"), progname);
4030 rhaas 60 1 : exit(0);
61 : }
62 4 : if (strcmp(argv[1], "--version") == 0 || strcmp(argv[1], "-V") == 0)
63 : {
64 1 : puts("pg_test_timing (PostgreSQL) " PG_VERSION);
65 1 : exit(0);
66 : }
67 : }
68 :
69 3 : while ((option = getopt_long(argc, argv, "d:",
70 3 : long_options, &optindex)) != -1)
71 : {
72 3 : switch (option)
73 : {
74 2 : case 'd':
923 michael 75 2 : errno = 0;
76 2 : optval = strtoul(optarg, &endptr, 10);
77 :
78 2 : if (endptr == optarg || *endptr != '\0' ||
79 1 : errno != 0 || optval != (unsigned int) optval)
80 : {
81 1 : fprintf(stderr, _("%s: invalid argument for option %s\n"),
82 : progname, "--duration");
83 1 : fprintf(stderr, _("Try \"%s --help\" for more information.\n"), progname);
84 1 : exit(1);
85 : }
86 :
87 1 : test_duration = (unsigned int) optval;
88 1 : if (test_duration == 0)
89 : {
90 1 : fprintf(stderr, _("%s: %s must be in range %u..%u\n"),
91 : progname, "--duration", 1, UINT_MAX);
92 1 : exit(1);
93 : }
4030 rhaas 94 UBC 0 : break;
95 :
4030 rhaas 96 CBC 1 : default:
2368 peter_e 97 1 : fprintf(stderr, _("Try \"%s --help\" for more information.\n"),
98 : progname);
4030 rhaas 99 1 : exit(1);
100 : break;
101 : }
102 : }
103 :
4030 rhaas 104 UBC 0 : if (argc > optind)
105 : {
106 0 : fprintf(stderr,
2368 peter_e 107 0 : _("%s: too many command-line arguments (first is \"%s\")\n"),
4030 rhaas 108 0 : progname, argv[optind]);
2368 peter_e 109 0 : fprintf(stderr, _("Try \"%s --help\" for more information.\n"),
110 : progname);
4030 rhaas 111 0 : exit(1);
112 : }
113 :
114 :
923 michael 115 0 : printf(ngettext("Testing timing overhead for %u second.\n",
116 : "Testing timing overhead for %u seconds.\n",
117 : test_duration),
118 : test_duration);
4030 rhaas 119 0 : }
120 :
121 : static uint64
923 michael 122 0 : test_timing(unsigned int duration)
123 : {
124 : uint64 total_time;
3955 bruce 125 0 : int64 time_elapsed = 0;
126 0 : uint64 loop_count = 0;
127 : uint64 prev,
128 : cur;
129 : instr_time start_time,
130 : end_time,
131 : temp;
132 :
3017 andres 133 0 : total_time = duration > 0 ? duration * INT64CONST(1000000) : 0;
134 :
4030 rhaas 135 0 : INSTR_TIME_SET_CURRENT(start_time);
136 0 : cur = INSTR_TIME_GET_MICROSEC(start_time);
137 :
138 0 : while (time_elapsed < total_time)
139 : {
140 : int32 diff,
3602 bruce 141 0 : bits = 0;
142 :
4030 rhaas 143 0 : prev = cur;
144 0 : INSTR_TIME_SET_CURRENT(temp);
145 0 : cur = INSTR_TIME_GET_MICROSEC(temp);
146 0 : diff = cur - prev;
147 :
148 : /* Did time go backwards? */
149 0 : if (diff < 0)
150 : {
2368 peter_e 151 0 : fprintf(stderr, _("Detected clock going backwards in time.\n"));
152 0 : fprintf(stderr, _("Time warp: %d ms\n"), diff);
4030 rhaas 153 0 : exit(1);
154 : }
155 :
156 : /* What is the highest bit in the time diff? */
157 0 : while (diff)
158 : {
159 0 : diff >>= 1;
160 0 : bits++;
161 : }
162 :
163 : /* Update appropriate duration bucket */
164 0 : histogram[bits]++;
165 :
166 0 : loop_count++;
167 0 : INSTR_TIME_SUBTRACT(temp, start_time);
168 0 : time_elapsed = INSTR_TIME_GET_MICROSEC(temp);
169 : }
170 :
171 0 : INSTR_TIME_SET_CURRENT(end_time);
172 :
173 0 : INSTR_TIME_SUBTRACT(end_time, start_time);
174 :
2368 peter_e 175 0 : printf(_("Per loop time including overhead: %0.2f ns\n"),
176 : INSTR_TIME_GET_DOUBLE(end_time) * 1e9 / loop_count);
177 :
3876 bruce 178 0 : return loop_count;
179 : }
180 :
181 : static void
182 0 : output(uint64 loop_count)
183 : {
3602 184 0 : int64 max_bit = 31,
185 : i;
2052 peter_e 186 0 : char *header1 = _("< us");
187 0 : char *header2 = /* xgettext:no-c-format */ _("% of total");
188 0 : char *header3 = _("count");
189 0 : int len1 = strlen(header1);
190 0 : int len2 = strlen(header2);
191 0 : int len3 = strlen(header3);
192 :
193 : /* find highest bit value */
3876 bruce 194 0 : while (max_bit > 0 && histogram[max_bit] == 0)
195 0 : max_bit--;
196 :
2368 peter_e 197 0 : printf(_("Histogram of timing durations:\n"));
2052 198 0 : printf("%*s %*s %*s\n",
199 : Max(6, len1), header1,
200 : Max(10, len2), header2,
201 : Max(10, len3), header3);
202 :
3876 bruce 203 0 : for (i = 0; i <= max_bit; i++)
1403 peter 204 0 : printf("%*ld %*.5f %*lld\n",
205 : Max(6, len1), 1l << i,
206 : Max(10, len2) - 1, (double) histogram[i] * 100 / loop_count,
207 : Max(10, len3), histogram[i]);
4030 rhaas 208 0 : }
|
