1 // SPDX-License-Identifier: GPL-2.0-or-later
2 /*
3 * Copyright (c) 2017 Cyril Hrubis <chrubis@suse.cz>
4 */
5
6 #include <sys/prctl.h>
7 #include <stdlib.h>
8 #include <stdio.h>
9 #include <limits.h>
10 #include <string.h>
11
12 #define TST_NO_DEFAULT_MAIN
13 #include "tst_test.h"
14 #include "tst_clocks.h"
15 #include "tst_timer_test.h"
16
17 #define MAX_SAMPLES 500
18
19 static const char *scall;
20 static void (*setup)(void);
21 static void (*cleanup)(void);
22 static int (*sample)(int clk_id, long long usec);
23 static struct tst_test *test;
24
25 static long long *samples;
26 static unsigned int cur_sample;
27 static unsigned int monotonic_resolution;
28 static unsigned int timerslack;
29 static int virt_env;
30
31 static char *print_frequency_plot;
32 static char *file_name;
33 static char *str_sleep_time;
34 static char *str_sample_cnt;
35 static int sleep_time = -1;
36 static int sample_cnt;
37
print_line(char c,int len)38 static void print_line(char c, int len)
39 {
40 while (len-- > 0)
41 fputc(c, stderr);
42 }
43
ceilu(float f)44 static unsigned int ceilu(float f)
45 {
46 if (f - (int)f > 0)
47 return (unsigned int)f + 1;
48
49 return (unsigned int)f;
50 }
51
flooru(float f)52 static unsigned int flooru(float f)
53 {
54 return (unsigned int)f;
55 }
56
bucket_len(unsigned int bucket,unsigned int max_bucket,unsigned int cols)57 static float bucket_len(unsigned int bucket, unsigned int max_bucket,
58 unsigned int cols)
59 {
60 return 1.00 * bucket * cols / max_bucket;
61 }
62
63 static const char *table_heading = " Time: us ";
64
65 /*
66 * Line Header: '10023 | '
67 */
header_len(long long max_sample)68 static unsigned int header_len(long long max_sample)
69 {
70 unsigned int l = 1;
71
72 while (max_sample/=10)
73 l++;
74
75 return MAX(strlen(table_heading) + 2, l + 3);
76 }
77
frequency_plot(void)78 static void frequency_plot(void)
79 {
80 unsigned int cols = 80;
81 unsigned int rows = 20;
82 unsigned int i, buckets[rows];
83 long long max_sample = samples[0];
84 long long min_sample = samples[cur_sample-1];
85 unsigned int line_header_len = header_len(max_sample);
86 unsigned int plot_line_len = cols - line_header_len;
87 unsigned int bucket_size;
88
89 memset(buckets, 0, sizeof(buckets));
90
91 /*
92 * We work with discrete data buckets smaller than 1 does not make
93 * sense as well as it's a good idea to keep buckets integer sized
94 * to avoid scaling artifacts.
95 */
96 bucket_size = MAX(1u, ceilu(1.00 * (max_sample - min_sample)/(rows-1)));
97
98 for (i = 0; i < cur_sample; i++) {
99 unsigned int bucket;
100 bucket = flooru(1.00 * (samples[i] - min_sample)/bucket_size);
101 buckets[bucket]++;
102 }
103
104 unsigned int max_bucket = buckets[0];
105 for (i = 1; i < rows; i++)
106 max_bucket = MAX(max_bucket, buckets[i]);
107
108 fprintf(stderr, "\n%*s| Frequency\n", line_header_len - 2, table_heading);
109
110 print_line('-', cols);
111 fputc('\n', stderr);
112
113 unsigned int l, r;
114
115 for (l = 0; l < rows; l++) {
116 if (buckets[l])
117 break;
118 }
119
120 for (r = rows-1; r > l; r--) {
121 if (buckets[r])
122 break;
123 }
124
125 for (i = l; i <= r; i++) {
126 float len = bucket_len(buckets[i], max_bucket, plot_line_len);
127
128 fprintf(stderr, "%*lli | ",
129 line_header_len - 3, min_sample + bucket_size*i);
130 print_line('*', len);
131
132 if ((len - (int)len) >= 0.5)
133 fputc('+', stderr);
134 else if ((len - (int)len) >= 0.25)
135 fputc('-', stderr);
136 else if (len < 0.25 && buckets[i])
137 fputc('.', stderr);
138
139 fputc('\n', stderr);
140 }
141
142 print_line('-', cols);
143 fputc('\n', stderr);
144
145 float scale = 1.00 * plot_line_len / max_bucket;
146
147 fprintf(stderr,
148 "%*uus | 1 sample = %.5f '*', %.5f '+', %.5f '-', non-zero '.'\n",
149 line_header_len - 5, bucket_size, scale, scale * 2, scale * 4);
150
151 fputc('\n', stderr);
152 }
153
tst_timer_sample(void)154 void tst_timer_sample(void)
155 {
156 samples[cur_sample++] = tst_timer_elapsed_us();
157 }
158
cmp(const void * a,const void * b)159 static int cmp(const void *a, const void *b)
160 {
161 const long long *aa = a, *bb = b;
162
163 return (*bb - *aa);
164 }
165
166 /*
167 * The threshold per one syscall is computed as a sum of:
168 *
169 * 400 us - accomodates for context switches, process
170 * migrations between CPUs on SMP, etc.
171 * 2*monotonic_resolution - accomodates for granurality of the CLOCK_MONOTONIC
172 * slack_per_scall - max of 0.1% of the sleep capped on 100ms or
173 * current->timer_slack_ns, which is slack allowed
174 * in kernel
175 *
176 * The formula for slack_per_scall applies to select() and *poll*() syscalls,
177 * the futex and *nanosleep() use only the timer_slack_ns, so we are a bit
178 * less strict here that we could be for these two for longer sleep times...
179 *
180 * We also allow for outliners, i.e. add some number to the threshold in case
181 * that the number of iteration is small. For large enoung number of iterations
182 * outliners are discarded and averaged out.
183 */
compute_threshold(long long requested_us,unsigned int nsamples)184 static long long compute_threshold(long long requested_us,
185 unsigned int nsamples)
186 {
187 unsigned int slack_per_scall = MIN(100000, requested_us / 1000);
188
189 slack_per_scall = MAX(slack_per_scall, timerslack);
190
191 return (400 + 2 * monotonic_resolution + slack_per_scall) * nsamples
192 + 3000/nsamples;
193 }
194
195 /*
196 * Returns number of samples to discard.
197 *
198 * We set it to either at least 1 if number of samples > 1 or 5%.
199 */
compute_discard(unsigned int nsamples)200 static unsigned int compute_discard(unsigned int nsamples)
201 {
202 if (nsamples == 1)
203 return 0;
204
205 return MAX(1u, nsamples / 20);
206 }
207
write_to_file(void)208 static void write_to_file(void)
209 {
210 unsigned int i;
211 FILE *f;
212
213 if (!file_name)
214 return;
215
216 f = fopen(file_name, "w");
217
218 if (!f) {
219 tst_res(TWARN | TERRNO,
220 "Failed to open '%s'", file_name);
221 return;
222 }
223
224 for (i = 0; i < cur_sample; i++)
225 fprintf(f, "%lli\n", samples[i]);
226
227 if (fclose(f)) {
228 tst_res(TWARN | TERRNO,
229 "Failed to close file '%s'", file_name);
230 }
231 }
232
233
234 /*
235 * Timer testing function.
236 *
237 * What we do here is:
238 *
239 * * Take nsamples measurements of the timer function, the function
240 * to be sampled is defined in the the actual test.
241 *
242 * * We sort the array of samples, then:
243 *
244 * - look for outliners which are samples where the sleep time has exceeded
245 * requested sleep time by an order of magnitude and, at the same time, are
246 * greater than clock resolution multiplied by three.
247 *
248 * - check for samples where the call has woken up too early which is a plain
249 * old bug
250 *
251 * - then we compute truncated mean and compare that with the requested sleep
252 * time increased by a threshold
253 */
do_timer_test(long long usec,unsigned int nsamples)254 void do_timer_test(long long usec, unsigned int nsamples)
255 {
256 long long trunc_mean, median;
257 unsigned int discard = compute_discard(nsamples);
258 unsigned int keep_samples = nsamples - discard;
259 long long threshold = compute_threshold(usec, keep_samples);
260 int i;
261 int failed = 0;
262
263 tst_res(TINFO,
264 "%s sleeping for %llius %u iterations, threshold %.2fus",
265 scall, usec, nsamples, 1.00 * threshold / (keep_samples));
266
267 cur_sample = 0;
268 for (i = 0; i < (int)nsamples; i++) {
269 if (sample(CLOCK_MONOTONIC, usec)) {
270 tst_res(TINFO, "sampling function failed, exitting");
271 return;
272 }
273 }
274
275 qsort(samples, nsamples, sizeof(samples[0]), cmp);
276
277 write_to_file();
278
279 for (i = 0; samples[i] > 10 * usec && i < (int)nsamples; i++) {
280 if (samples[i] <= 3 * monotonic_resolution)
281 break;
282 }
283
284 if (i > 0) {
285 tst_res(TINFO, "Found %i outliners in [%lli,%lli] range",
286 i, samples[0], samples[i-1]);
287 }
288
289 for (i = nsamples - 1; samples[i] < usec && i > -1; i--);
290
291 if (i < (int)nsamples - 1) {
292 tst_res(TFAIL, "%s woken up early %u times range: [%lli,%lli]",
293 scall, nsamples - 1 - i,
294 samples[i+1], samples[nsamples-1]);
295 failed = 1;
296 }
297
298 median = samples[nsamples/2];
299
300 trunc_mean = 0;
301
302 for (i = discard; i < (int)nsamples; i++)
303 trunc_mean += samples[i];
304
305 tst_res(TINFO,
306 "min %llius, max %llius, median %llius, trunc mean %.2fus (discarded %u)",
307 samples[nsamples-1], samples[0], median,
308 1.00 * trunc_mean / keep_samples, discard);
309
310 if (virt_env) {
311 tst_res(TINFO,
312 "Virtualisation detected, skipping oversleep checks");
313 } else if (trunc_mean > (nsamples - discard) * usec + threshold) {
314 tst_res(TFAIL, "%s slept for too long", scall);
315
316 if (!print_frequency_plot)
317 frequency_plot();
318
319 failed = 1;
320 }
321
322 if (print_frequency_plot)
323 frequency_plot();
324
325 if (!failed)
326 tst_res(TPASS, "Measured times are within thresholds");
327 }
328
329 static void parse_timer_opts(void);
330
set_latency(void)331 static int set_latency(void)
332 {
333 int fd, latency = 0;
334
335 fd = open("/dev/cpu_dma_latency", O_WRONLY);
336 if (fd < 0)
337 return fd;
338
339 return write(fd, &latency, sizeof(latency));
340 }
341
timer_setup(void)342 static void timer_setup(void)
343 {
344 struct timespec t;
345 int ret;
346
347 if (setup)
348 setup();
349
350 /*
351 * Running tests in VM may cause timing issues, disable upper bound
352 * checks if any hypervisor is detected.
353 */
354 virt_env = tst_is_virt(VIRT_ANY);
355 tst_clock_getres(CLOCK_MONOTONIC, &t);
356
357 tst_res(TINFO, "CLOCK_MONOTONIC resolution %lins", (long)t.tv_nsec);
358
359 monotonic_resolution = t.tv_nsec / 1000;
360 timerslack = 50;
361
362 #ifdef PR_GET_TIMERSLACK
363 ret = prctl(PR_GET_TIMERSLACK);
364 if (ret < 0) {
365 tst_res(TINFO, "prctl(PR_GET_TIMERSLACK) = -1, using %uus",
366 timerslack);
367 } else {
368 timerslack = ret / 1000;
369 tst_res(TINFO, "prctl(PR_GET_TIMERSLACK) = %ius", timerslack);
370 }
371 #else
372 tst_res(TINFO, "PR_GET_TIMERSLACK not defined, using %uus",
373 timerslack);
374 #endif /* PR_GET_TIMERSLACK */
375 parse_timer_opts();
376
377 samples = SAFE_MALLOC(sizeof(long long) * MAX(MAX_SAMPLES, sample_cnt));
378 if (set_latency() < 0)
379 tst_res(TINFO, "Failed to set zero latency constraint: %m");
380 }
381
timer_cleanup(void)382 static void timer_cleanup(void)
383 {
384 free(samples);
385
386 if (cleanup)
387 cleanup();
388 }
389
390 static struct tst_timer_tcase {
391 long long usec;
392 unsigned int samples;
393 } tcases[] = {
394 {1000, 500},
395 {2000, 500},
396 {5000, 300},
397 {10000, 100},
398 {25000, 50},
399 {100000, 10},
400 {1000000, 2},
401 };
402
timer_test_fn(unsigned int n)403 static void timer_test_fn(unsigned int n)
404 {
405 do_timer_test(tcases[n].usec, tcases[n].samples);
406 }
407
single_timer_test(void)408 static void single_timer_test(void)
409 {
410 do_timer_test(sleep_time, sample_cnt);
411 }
412
413 static struct tst_option options[] = {
414 {"p", &print_frequency_plot, "-p Print frequency plot"},
415 {"s:", &str_sleep_time, "-s us Sleep time"},
416 {"n:", &str_sample_cnt, "-n uint Number of samples to take"},
417 {"f:", &file_name, "-f fname Write measured samples into a file"},
418 {NULL, NULL, NULL}
419 };
420
parse_timer_opts(void)421 static void parse_timer_opts(void)
422 {
423 if (str_sleep_time) {
424 if (tst_parse_int(str_sleep_time, &sleep_time, 0, INT_MAX)) {
425 tst_brk(TBROK,
426 "Invalid sleep time '%s'", str_sleep_time);
427 }
428 }
429
430 if (str_sample_cnt) {
431 if (tst_parse_int(str_sample_cnt, &sample_cnt, 1, INT_MAX)) {
432 tst_brk(TBROK,
433 "Invalid sample count '%s'", str_sample_cnt);
434 }
435 }
436
437 if (str_sleep_time || str_sample_cnt) {
438 if (sleep_time < 0)
439 sleep_time = 10000;
440
441 if (!sample_cnt)
442 sample_cnt = 500;
443
444 long long timeout = sleep_time * sample_cnt / 1000000;
445
446 tst_set_timeout(timeout + timeout/10);
447
448 test->test_all = single_timer_test;
449 test->test = NULL;
450 test->tcnt = 0;
451 }
452 }
453
tst_timer_test_setup(struct tst_test * timer_test)454 struct tst_test *tst_timer_test_setup(struct tst_test *timer_test)
455 {
456 setup = timer_test->setup;
457 cleanup = timer_test->cleanup;
458 scall = timer_test->scall;
459 sample = timer_test->sample;
460
461 timer_test->scall = NULL;
462 timer_test->setup = timer_setup;
463 timer_test->cleanup = timer_cleanup;
464 timer_test->test = timer_test_fn;
465 timer_test->tcnt = ARRAY_SIZE(tcases);
466 timer_test->sample = NULL;
467 timer_test->options = options;
468
469 test = timer_test;
470
471 return timer_test;
472 }
473