1 /*
2 * Copyright (c) 1991, 1992 Paul Kranenburg <pk@cs.few.eur.nl>
3 * Copyright (c) 1993 Branko Lankester <branko@hacktic.nl>
4 * Copyright (c) 1993, 1994, 1995, 1996 Rick Sladkey <jrs@world.std.com>
5 * Copyright (c) 1996-1999 Wichert Akkerman <wichert@cistron.nl>
6 * Copyright (c) 1999 IBM Deutschland Entwicklung GmbH, IBM Corporation
7 * Linux for s390 port by D.J. Barrow
8 * <barrow_dj@mail.yahoo.com,djbarrow@de.ibm.com>
9 * Copyright (c) 2004 Roland McGrath <roland@redhat.com>
10 * Copyright (c) 2006 Dmitry V. Levin <ldv@strace.io>
11 * Copyright (c) 2006-2021 The strace developers.
12 * All rights reserved.
13 *
14 * SPDX-License-Identifier: LGPL-2.1-or-later
15 */
16
17 #include "defs.h"
18
19 #include <stdarg.h>
20
21 /* Per-syscall stats structure */
22 struct call_counts {
23 /* time may be total latency or system time */
24 struct timespec time;
25 struct timespec time_min;
26 struct timespec time_max;
27 struct timespec time_avg;
28 uint64_t calls, errors;
29 };
30
31 static struct call_counts *countv[SUPPORTED_PERSONALITIES];
32 #define counts (countv[current_personality])
33
34 static const struct timespec zero_ts;
35 static const struct timespec max_ts = {
36 (time_t) (long long) (zero_extend_signed_to_ull((time_t) -1ULL) >> 1),
37 999999999 };
38
39 static struct timespec overhead;
40
41
42 enum count_summary_columns {
43 CSC_NONE,
44 CSC_TIME_100S,
45 CSC_TIME_TOTAL,
46 CSC_TIME_MIN,
47 CSC_TIME_MAX,
48 CSC_TIME_AVG,
49 CSC_CALLS,
50 CSC_ERRORS,
51 CSC_SC_NAME,
52
53 CSC_MAX,
54 };
55
56 static uint8_t columns[CSC_MAX] = {
57 CSC_TIME_100S,
58 CSC_TIME_TOTAL,
59 CSC_TIME_AVG,
60 CSC_CALLS,
61 CSC_ERRORS,
62 CSC_SC_NAME,
63 };
64
65 static const struct {
66 const char *name;
67 uint8_t column;
68 } column_aliases[] = {
69 { "time", CSC_TIME_100S },
70 { "time_percent", CSC_TIME_100S },
71 { "time-percent", CSC_TIME_100S },
72 { "time_total", CSC_TIME_TOTAL },
73 { "time-total", CSC_TIME_TOTAL },
74 { "total_time", CSC_TIME_TOTAL },
75 { "total-time", CSC_TIME_TOTAL },
76 { "min_time", CSC_TIME_MIN },
77 { "min-time", CSC_TIME_MIN },
78 { "shortest", CSC_TIME_MIN },
79 { "time_min", CSC_TIME_MIN },
80 { "time-min", CSC_TIME_MIN },
81 { "longest" , CSC_TIME_MAX },
82 { "max_time", CSC_TIME_MAX },
83 { "max-time", CSC_TIME_MAX },
84 { "time_max", CSC_TIME_MAX },
85 { "time-max", CSC_TIME_MAX },
86 { "avg_time", CSC_TIME_AVG },
87 { "avg-time", CSC_TIME_AVG },
88 { "time_avg", CSC_TIME_AVG },
89 { "time-avg", CSC_TIME_AVG },
90 { "calls", CSC_CALLS },
91 { "count", CSC_CALLS },
92 { "error", CSC_ERRORS },
93 { "errors", CSC_ERRORS },
94 { "name", CSC_SC_NAME },
95 { "syscall", CSC_SC_NAME },
96 { "syscall_name", CSC_SC_NAME },
97 { "syscall-name", CSC_SC_NAME },
98 { "none", CSC_NONE },
99 { "nothing", CSC_NONE },
100 };
101
102 void
103 count_syscall(struct tcb *tcp, const struct timespec *syscall_exiting_ts)
104 {
105 if (!scno_in_range(tcp->scno))
106 return;
107
108 if (!counts) {
109 counts = xcalloc(nsyscalls, sizeof(*counts));
110
111 for (size_t i = 0; i < nsyscalls; i++)
112 counts[i].time_min = max_ts;
113 }
114 struct call_counts *cc = &counts[tcp->scno];
115
116 cc->calls++;
117 if (syserror(tcp))
118 cc->errors++;
119
120 struct timespec wts;
121 if (count_wallclock) {
122 /* wall clock time spent while in syscall */
123 ts_sub(&wts, syscall_exiting_ts, &tcp->etime);
124 } else {
125 /* system CPU time spent while in syscall */
126 ts_sub(&wts, &tcp->stime, &tcp->ltime);
127 }
128
129 ts_sub(&wts, &wts, &overhead);
130
131 const struct timespec *wts_nonneg = ts_max(&wts, &zero_ts);
132
133 ts_add(&cc->time, &cc->time, wts_nonneg);
134 cc->time_min = *ts_min(&cc->time_min, wts_nonneg);
135 cc->time_max = *ts_max(&cc->time_max, wts_nonneg);
136 }
137
138 static int
139 time_cmp(const void *a, const void *b)
140 {
141 const unsigned int *a_int = a;
142 const unsigned int *b_int = b;
143 return -ts_cmp(&counts[*a_int].time, &counts[*b_int].time);
144 }
145
146 static int
147 min_time_cmp(const void *a, const void *b)
148 {
149 return -ts_cmp(&counts[*((unsigned int *) a)].time_min,
150 &counts[*((unsigned int *) b)].time_min);
151 }
152
153 static int
154 max_time_cmp(const void *a, const void *b)
155 {
156 return -ts_cmp(&counts[*((unsigned int *) a)].time_max,
157 &counts[*((unsigned int *) b)].time_max);
158 }
159
160 static int
161 avg_time_cmp(const void *a, const void *b)
162 {
163 return -ts_cmp(&counts[*((unsigned int *) a)].time_avg,
164 &counts[*((unsigned int *) b)].time_avg);
165 }
166
167 static int
168 syscall_cmp(const void *a, const void *b)
169 {
170 const unsigned int *a_int = a;
171 const unsigned int *b_int = b;
172 const char *a_name = sysent[*a_int].sys_name;
173 const char *b_name = sysent[*b_int].sys_name;
174 return strcmp(a_name ? a_name : "", b_name ? b_name : "");
175 }
176
177 static int
178 count_cmp(const void *a, const void *b)
179 {
180 const unsigned int *a_int = a;
181 const unsigned int *b_int = b;
182 unsigned int m = counts[*a_int].calls;
183 unsigned int n = counts[*b_int].calls;
184
185 return (m < n) ? 1 : (m > n) ? -1 : 0;
186 }
187
188 static int
189 error_cmp(const void *a, const void *b)
190 {
191 const unsigned int *a_int = a;
192 const unsigned int *b_int = b;
193 unsigned int m = counts[*a_int].errors;
194 unsigned int n = counts[*b_int].errors;
195
196 return (m < n) ? 1 : (m > n) ? -1 : 0;
197 }
198
199 typedef int (*sort_func)(const void *, const void *);
200 static sort_func sortfun;
201
202 void
203 set_sortby(const char *sortby)
204 {
205 static const sort_func sort_fns[CSC_MAX] = {
206 [CSC_TIME_100S] = time_cmp,
207 [CSC_TIME_TOTAL] = time_cmp,
208 [CSC_TIME_MIN] = min_time_cmp,
209 [CSC_TIME_MAX] = max_time_cmp,
210 [CSC_TIME_AVG] = avg_time_cmp,
211 [CSC_CALLS] = count_cmp,
212 [CSC_ERRORS] = error_cmp,
213 [CSC_SC_NAME] = syscall_cmp,
214 };
215
216 for (size_t i = 0; i < ARRAY_SIZE(column_aliases); ++i) {
217 if (!strcmp(column_aliases[i].name, sortby)) {
218 sortfun = sort_fns[column_aliases[i].column];
219 return;
220 }
221 }
222
223 error_msg_and_help("invalid sortby: '%s'", sortby);
224 }
225
226 void
227 set_count_summary_columns(const char *s)
228 {
229 uint8_t visible[CSC_MAX] = { 0 };
230 const char *prev = s;
231 size_t cur = 0;
232
233 memset(columns, 0, sizeof(columns));
234
235 for (;;) {
236 bool found = false;
237 const char *pos = strchr(prev, ',');
238 size_t len = pos ? (size_t) (pos - prev) : strlen(prev);
239
240 for (size_t i = 0; i < ARRAY_SIZE(column_aliases); i++) {
241 if (strncmp(column_aliases[i].name, prev, len) ||
242 column_aliases[i].name[len])
243 continue;
244 if (column_aliases[i].column == CSC_NONE ||
245 column_aliases[i].column >= CSC_MAX)
246 continue;
247
248 if (visible[column_aliases[i].column])
249 error_msg_and_help("call summary column "
250 "has been provided more "
251 "than once: '%s' (-U option "
252 "residual: '%s')",
253 column_aliases[i].name,
254 prev);
255
256 columns[cur++] = column_aliases[i].column;
257 visible[column_aliases[i].column] = 1;
258 found = true;
259
260 break;
261 }
262
263 if (!found)
264 error_msg_and_help("unknown column name: '%.*s'",
265 (int) MIN(len, INT_MAX), prev);
266
267 if (!pos)
268 break;
269
270 prev = pos + 1;
271 }
272
273 /*
274 * Always enable syscall name column, as without it table is meaningless
275 */
276 if (!visible[CSC_SC_NAME])
277 columns[cur++] = CSC_SC_NAME;
278 }
279
280 int
281 set_overhead(const char *str)
282 {
283 return parse_ts(str, &overhead);
284 }
285
286 static size_t ATTRIBUTE_FORMAT((printf, 1, 2))
287 num_chars(const char *fmt, ...)
288 {
289 va_list ap;
290
291 va_start(ap, fmt);
292 int ret = vsnprintf(NULL, 0, fmt, ap);
293 va_end(ap);
294
295 return (unsigned int) MAX(ret, 0);
296 }
297
298 static void
299 call_summary_pers(FILE *outf)
300 {
301 unsigned int *indices;
302 size_t last_column = 0;
303
304 struct timespec tv_cum = zero_ts;
305 const struct timespec *tv_min = &max_ts;
306 const struct timespec *tv_min_max = &zero_ts;
307 const struct timespec *tv_max = &zero_ts;
308 const struct timespec *tv_avg_max = &zero_ts;
309 uint64_t call_cum = 0;
310 uint64_t error_cum = 0;
311
312 double float_tv_cum;
313 double percent;
314
315 size_t sc_name_max = 0;
316
317
318 /* sort, calculate statistics */
319 indices = xcalloc(sizeof(indices[0]), nsyscalls);
320 for (size_t i = 0; i < nsyscalls; ++i) {
321 indices[i] = i;
322 if (counts[i].calls == 0)
323 continue;
324
325 ts_add(&tv_cum, &tv_cum, &counts[i].time);
326 tv_min = ts_min(tv_min, &counts[i].time_min);
327 tv_min_max = ts_max(tv_min_max, &counts[i].time_min);
328 tv_max = ts_max(tv_max, &counts[i].time_max);
329 call_cum += counts[i].calls;
330 error_cum += counts[i].errors;
331
332 ts_div(&counts[i].time_avg, &counts[i].time, counts[i].calls);
333 tv_avg_max = ts_max(tv_avg_max, &counts[i].time_avg);
334
335 sc_name_max = MAX(sc_name_max, strlen(sysent[i].sys_name));
336 }
337 float_tv_cum = ts_float(&tv_cum);
338
339 if (sortfun)
340 qsort((void *) indices, nsyscalls, sizeof(indices[0]), sortfun);
341
342 enum column_flags {
343 CF_L = 1 << 0, /* Left-aligned column */
344 };
345 static const struct {
346 const char *s;
347 size_t sz;
348 const char *fmt;
349 const char *last_fmt;
350 uint32_t flags;
351 } cdesc[] = {
352 [CSC_TIME_100S] = { ARRSZ_PAIR("% time") - 1, "%1$*2$.2f" },
353 [CSC_TIME_MIN] = { ARRSZ_PAIR("shortest") - 1, "%1$*2$.6f" },
354 [CSC_TIME_MAX] = { ARRSZ_PAIR("longest") - 1, "%1$*2$.6f" },
355 /* Historical field sizes are preserved */
356 [CSC_TIME_TOTAL] = { "seconds", 11, "%1$*2$.6f" },
357 [CSC_TIME_AVG] = { "usecs/call", 11, "%1$*2$" PRIu64 },
358 [CSC_CALLS] = { "calls", 9, "%1$*2$" PRIu64 },
359 [CSC_ERRORS] = { "errors", 9, "%1$*2$.0" PRIu64 },
360 [CSC_SC_NAME] = { "syscall", 16, "%1$-*2$s", "%1$s", CF_L },
361 };
362
363 /* calculate column widths */
364 #define W_(c_, v_) [c_] = MAX(cdesc[c_].sz, (v_))
365 unsigned int cwidths[CSC_MAX] = {
366 W_(CSC_TIME_100S, sizeof("100.00") - 1),
367 W_(CSC_TIME_TOTAL, num_chars("%.6f", float_tv_cum)),
368 W_(CSC_TIME_MIN, num_chars("%" PRId64 ".000000",
369 (int64_t) tv_min_max->tv_sec)),
370 W_(CSC_TIME_MAX, num_chars("%" PRId64 ".000000",
371 (int64_t) tv_max->tv_sec)),
372 W_(CSC_TIME_AVG, num_chars("%" PRId64 ,
373 (uint64_t) (ts_float(tv_avg_max)
374 * 1e6))),
375 W_(CSC_CALLS, num_chars("%" PRIu64, call_cum)),
376 W_(CSC_ERRORS, num_chars("%" PRIu64, error_cum)),
377 W_(CSC_SC_NAME, sc_name_max + 1),
378 };
379 #undef W_
380
381 /* find the last column */
382 for (size_t i = 0; i < ARRAY_SIZE(columns) && columns[i]; ++i)
383 last_column = i;
384
385 /* header */
386 for (size_t i = 0; i <= last_column; ++i) {
387 const char *fmt = cdesc[columns[i]].flags & CF_L
388 ? (i == last_column ? "%1$s" : "%1$-*2$s")
389 : "%1$*2$s";
390 if (i)
391 fputc(' ', outf);
392 fprintf(outf, fmt, cdesc[columns[i]].s, cwidths[columns[i]]);
393 }
394 fputc('\n', outf);
395
396 /* divider */
397 for (size_t i = 0; i <= last_column; ++i) {
398 if (i)
399 fputc(' ', outf);
400
401 for (size_t j = 0; j < cwidths[columns[i]]; ++j)
402 fputc('-', outf);
403 }
404 fputc('\n', outf);
405
406 /* cache column formats */
407 #define FC_(c_) \
408 case (c_): \
409 column_fmts[i] = (i == last_column) && cdesc[c].last_fmt \
410 ? cdesc[c].last_fmt : cdesc[c].fmt; \
411 break
412 #define PC_(c_, val_) \
413 case (c_): \
414 fprintf(outf, column_fmts[i], (val_), cwidths[c]); \
415 break
416
417 const char *column_fmts[last_column + 1];
418 for (size_t i = 0; i <= last_column; ++i) {
419 const size_t c = columns[i];
420
421 switch (c) {
422 FC_(CSC_TIME_100S);
423 FC_(CSC_TIME_TOTAL);
424 FC_(CSC_TIME_MIN);
425 FC_(CSC_TIME_MAX);
426 FC_(CSC_TIME_AVG);
427 FC_(CSC_CALLS);
428 FC_(CSC_ERRORS);
429 FC_(CSC_SC_NAME);
430 }
431 }
432
433 /* data output */
434 for (size_t j = 0; j < nsyscalls; ++j) {
435 unsigned int idx = indices[j];
436 struct call_counts *cc = &counts[idx];
437 double float_syscall_time;
438
439 if (cc->calls == 0)
440 continue;
441
442 float_syscall_time = ts_float(&cc->time);
443 percent = (100.0 * float_syscall_time);
444 /* else: float_tv_cum can be 0.0 too and we get 0/0 = NAN */
445 if (percent != 0.0)
446 percent /= float_tv_cum;
447
448 for (size_t i = 0; i <= last_column; ++i) {
449 const size_t c = columns[i];
450 if (i)
451 fputc(' ', outf);
452
453 switch (c) {
454 PC_(CSC_TIME_100S, percent);
455 PC_(CSC_TIME_TOTAL, float_syscall_time);
456 PC_(CSC_TIME_MIN, ts_float(&cc->time_min));
457 PC_(CSC_TIME_MAX, ts_float(&cc->time_max));
458 PC_(CSC_TIME_AVG,
459 (uint64_t) (ts_float(&cc->time_avg) * 1e6));
460 PC_(CSC_CALLS, cc->calls);
461 PC_(CSC_ERRORS, cc->errors);
462 PC_(CSC_SC_NAME, sysent[idx].sys_name);
463 }
464 }
465
466 fputc('\n', outf);
467 }
468
469 free(indices);
470
471 /* footer */
472 for (size_t i = 0; i <= last_column; ++i) {
473 if (i)
474 fputc(' ', outf);
475
476 for (size_t j = 0; j < cwidths[columns[i]]; ++j)
477 fputc('-', outf);
478 }
479 fputc('\n', outf);
480
481 /* totals */
482 for (size_t i = 0; i <= last_column; ++i) {
483 const size_t c = columns[i];
484 if (i)
485 fputc(' ', outf);
486
487 switch (c) {
488 PC_(CSC_TIME_100S, 100.0);
489 PC_(CSC_TIME_TOTAL, float_tv_cum);
490 PC_(CSC_TIME_MIN, ts_float(tv_min));
491 PC_(CSC_TIME_MAX, ts_float(tv_max));
492 PC_(CSC_TIME_AVG, (uint64_t) (float_tv_cum / call_cum * 1e6));
493 PC_(CSC_CALLS, call_cum);
494 PC_(CSC_ERRORS, error_cum);
495 PC_(CSC_SC_NAME, "total");
496 }
497 }
498 fputc('\n', outf);
499
500 #undef PC_
501 #undef FC_
502 }
503
504 void
505 call_summary(FILE *outf)
506 {
507 const unsigned int old_pers = current_personality;
508
509 for (unsigned int i = 0; i < SUPPORTED_PERSONALITIES; ++i) {
510 if (!countv[i])
511 continue;
512
513 if (current_personality != i)
514 set_personality(i);
515 if (i)
516 fprintf(outf,
517 "System call usage summary for %s mode:\n",
518 personality_names[i]);
519 call_summary_pers(outf);
520 }
521
522 if (old_pers != current_personality)
523 set_personality(old_pers);
524 }