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