githubmirror/strace

src/count.c
524 строки13 KB
Dmitry V. Levin
Update copyright headers
16 фев 2021, 11:00
16 фев 2021, 11:008fa8a88
/*
 * Copyright (c) 1991, 1992 Paul Kranenburg <pk@cs.few.eur.nl>
 * Copyright (c) 1993 Branko Lankester <branko@hacktic.nl>
 * Copyright (c) 1993, 1994, 1995, 1996 Rick Sladkey <jrs@world.std.com>
 * Copyright (c) 1996-1999 Wichert Akkerman <wichert@cistron.nl>
 * Copyright (c) 1999 IBM Deutschland Entwicklung GmbH, IBM Corporation
 *                     Linux for s390 port by D.J. Barrow
 *                    <barrow_dj@mail.yahoo.com,djbarrow@de.ibm.com>
 * Copyright (c) 2004 Roland McGrath <roland@redhat.com>
 * Copyright (c) 2006 Dmitry V. Levin <ldv@strace.io>
 * Copyright (c) 2006-2021 The strace developers.
 * All rights reserved.
 *
 * SPDX-License-Identifier: LGPL-2.1-or-later
 */

#include "defs.h"

#include <stdarg.h>

/* Per-syscall stats structure */
struct call_counts {
	/* time may be total latency or system time */
	struct timespec time;
	struct timespec time_min;
	struct timespec time_max;
	struct timespec time_avg;
	uint64_t calls, errors;
};

static struct call_counts *countv[SUPPORTED_PERSONALITIES];
#define counts (countv[current_personality])

static const struct timespec zero_ts;
static const struct timespec max_ts = {
	(time_t) (long long) (zero_extend_signed_to_ull((time_t) -1ULL) >> 1),
	999999999 };

static struct timespec overhead;


enum count_summary_columns {
	CSC_NONE,
	CSC_TIME_100S,
	CSC_TIME_TOTAL,
	CSC_TIME_MIN,
	CSC_TIME_MAX,
	CSC_TIME_AVG,
	CSC_CALLS,
	CSC_ERRORS,
	CSC_SC_NAME,

	CSC_MAX,
};

static uint8_t columns[CSC_MAX] = {
	CSC_TIME_100S,
	CSC_TIME_TOTAL,
	CSC_TIME_AVG,
	CSC_CALLS,
	CSC_ERRORS,
	CSC_SC_NAME,
};

static const struct {
	const char *name;
	uint8_t     column;
} column_aliases[] = {
	{ "time",         CSC_TIME_100S  },
	{ "time_percent", CSC_TIME_100S  },
	{ "time-percent", CSC_TIME_100S  },
	{ "time_total",   CSC_TIME_TOTAL },
	{ "time-total",   CSC_TIME_TOTAL },
	{ "total_time",   CSC_TIME_TOTAL },
	{ "total-time",   CSC_TIME_TOTAL },
	{ "min_time",     CSC_TIME_MIN   },
	{ "min-time",     CSC_TIME_MIN   },
	{ "shortest",     CSC_TIME_MIN   },
	{ "time_min",     CSC_TIME_MIN   },
	{ "time-min",     CSC_TIME_MIN   },
	{ "longest" ,     CSC_TIME_MAX   },
	{ "max_time",     CSC_TIME_MAX   },
	{ "max-time",     CSC_TIME_MAX   },
	{ "time_max",     CSC_TIME_MAX   },
	{ "time-max",     CSC_TIME_MAX   },
	{ "avg_time",     CSC_TIME_AVG   },
	{ "avg-time",     CSC_TIME_AVG   },
	{ "time_avg",     CSC_TIME_AVG   },
	{ "time-avg",     CSC_TIME_AVG   },
	{ "calls",        CSC_CALLS      },
	{ "count",        CSC_CALLS      },
	{ "error",        CSC_ERRORS     },
	{ "errors",       CSC_ERRORS     },
	{ "name",         CSC_SC_NAME    },
	{ "syscall",      CSC_SC_NAME    },
	{ "syscall_name", CSC_SC_NAME    },
	{ "syscall-name", CSC_SC_NAME    },
	{ "none",         CSC_NONE       },
	{ "nothing",      CSC_NONE       },
};

void
count_syscall(struct tcb *tcp, const struct timespec *syscall_exiting_ts)
{
	if (!scno_in_range(tcp->scno))
		return;

	if (!counts) {
		counts = xcalloc(nsyscalls, sizeof(*counts));

		for (size_t i = 0; i < nsyscalls; i++)
			counts[i].time_min = max_ts;
	}
	struct call_counts *cc = &counts[tcp->scno];

	cc->calls++;
	if (syserror(tcp))
		cc->errors++;

	struct timespec wts;
	if (count_wallclock) {
		/* wall clock time spent while in syscall */
		ts_sub(&wts, syscall_exiting_ts, &tcp->etime);
	} else {
		/* system CPU time spent while in syscall */
		ts_sub(&wts, &tcp->stime, &tcp->ltime);
	}

	ts_sub(&wts, &wts, &overhead);

	const struct timespec *wts_nonneg = ts_max(&wts, &zero_ts);

	ts_add(&cc->time, &cc->time, wts_nonneg);
	cc->time_min = *ts_min(&cc->time_min, wts_nonneg);
	cc->time_max = *ts_max(&cc->time_max, wts_nonneg);
}

static int
time_cmp(const void *a, const void *b)
{
	const unsigned int *a_int = a;
	const unsigned int *b_int = b;
	return -ts_cmp(&counts[*a_int].time, &counts[*b_int].time);
}

static int
min_time_cmp(const void *a, const void *b)
{
	return -ts_cmp(&counts[*((unsigned int *) a)].time_min,
		       &counts[*((unsigned int *) b)].time_min);
}

static int
max_time_cmp(const void *a, const void *b)
{
	return -ts_cmp(&counts[*((unsigned int *) a)].time_max,
		       &counts[*((unsigned int *) b)].time_max);
}

static int
avg_time_cmp(const void *a, const void *b)
{
	return -ts_cmp(&counts[*((unsigned int *) a)].time_avg,
		       &counts[*((unsigned int *) b)].time_avg);
}

static int
syscall_cmp(const void *a, const void *b)
{
	const unsigned int *a_int = a;
	const unsigned int *b_int = b;
	const char *a_name = sysent[*a_int].sys_name;
	const char *b_name = sysent[*b_int].sys_name;
	return strcmp(a_name ? a_name : "", b_name ? b_name : "");
}

static int
count_cmp(const void *a, const void *b)
{
	const unsigned int *a_int = a;
	const unsigned int *b_int = b;
	unsigned int m = counts[*a_int].calls;
	unsigned int n = counts[*b_int].calls;

	return (m < n) ? 1 : (m > n) ? -1 : 0;
}

static int
error_cmp(const void *a, const void *b)
{
	const unsigned int *a_int = a;
	const unsigned int *b_int = b;
	unsigned int m = counts[*a_int].errors;
	unsigned int n = counts[*b_int].errors;

	return (m < n) ? 1 : (m > n) ? -1 : 0;
}

typedef int (*sort_func)(const void *, const void *);
static sort_func sortfun;

void
set_sortby(const char *sortby)
{
	static const sort_func sort_fns[CSC_MAX] = {
		[CSC_TIME_100S]  = time_cmp,
		[CSC_TIME_TOTAL] = time_cmp,
		[CSC_TIME_MIN]   = min_time_cmp,
		[CSC_TIME_MAX]   = max_time_cmp,
		[CSC_TIME_AVG]   = avg_time_cmp,
		[CSC_CALLS]      = count_cmp,
		[CSC_ERRORS]     = error_cmp,
		[CSC_SC_NAME]    = syscall_cmp,
	};

	for (size_t i = 0; i < ARRAY_SIZE(column_aliases); ++i) {
		if (!strcmp(column_aliases[i].name, sortby)) {
			sortfun = sort_fns[column_aliases[i].column];
			return;
		}
	}

	error_msg_and_help("invalid sortby: '%s'", sortby);
}

void
set_count_summary_columns(const char *s)
{
	uint8_t visible[CSC_MAX] = { 0 };
	const char *prev = s;
	size_t cur = 0;

	memset(columns, 0, sizeof(columns));

	for (;;) {
		bool found = false;
		const char *pos = strchr(prev, ',');
		size_t len = pos ? (size_t) (pos - prev) : strlen(prev);

		for (size_t i = 0; i < ARRAY_SIZE(column_aliases); i++) {
			if (strncmp(column_aliases[i].name, prev, len) ||
			    column_aliases[i].name[len])
				continue;
			if (column_aliases[i].column == CSC_NONE ||
			    column_aliases[i].column >= CSC_MAX)
				continue;

			if (visible[column_aliases[i].column])
				error_msg_and_help("call summary column "
						   "has been provided more "
						   "than once: '%s' (-U option "
						   "residual: '%s')",
						   column_aliases[i].name,
						   prev);

			columns[cur++] = column_aliases[i].column;
			visible[column_aliases[i].column] = 1;
			found = true;

			break;
		}

		if (!found)
			error_msg_and_help("unknown column name: '%.*s'",
					   (int) MIN(len, INT_MAX), prev);

		if (!pos)
			break;

		prev = pos + 1;
	}

	/*
	 * Always enable syscall name column, as without it table is meaningless
	 */
	if (!visible[CSC_SC_NAME])
		columns[cur++] = CSC_SC_NAME;
}

int
set_overhead(const char *str)
{
	return parse_ts(str, &overhead);
}

static size_t ATTRIBUTE_FORMAT((printf, 1, 2))
num_chars(const char *fmt, ...)
{
	va_list ap;

	va_start(ap, fmt);
	int ret = vsnprintf(NULL, 0, fmt, ap);
	va_end(ap);

	return (unsigned int) MAX(ret, 0);
}

static void
call_summary_pers(FILE *outf)
{
	unsigned int *indices;
	size_t last_column = 0;

	struct timespec tv_cum = zero_ts;
	const struct timespec *tv_min = &max_ts;
	const struct timespec *tv_min_max = &zero_ts;
	const struct timespec *tv_max = &zero_ts;
	const struct timespec *tv_avg_max = &zero_ts;
	uint64_t call_cum = 0;
	uint64_t error_cum = 0;

	double float_tv_cum;
	double percent;

	size_t sc_name_max = 0;


	/* sort, calculate statistics */
	indices = xcalloc(sizeof(indices[0]), nsyscalls);
	for (size_t i = 0; i < nsyscalls; ++i) {
		indices[i] = i;
		if (counts[i].calls == 0)
			continue;

		ts_add(&tv_cum, &tv_cum, &counts[i].time);
		tv_min = ts_min(tv_min, &counts[i].time_min);
		tv_min_max = ts_max(tv_min_max, &counts[i].time_min);
		tv_max = ts_max(tv_max, &counts[i].time_max);
		call_cum += counts[i].calls;
		error_cum += counts[i].errors;

		ts_div(&counts[i].time_avg, &counts[i].time, counts[i].calls);
		tv_avg_max = ts_max(tv_avg_max, &counts[i].time_avg);

		sc_name_max = MAX(sc_name_max, strlen(sysent[i].sys_name));
	}
	float_tv_cum = ts_float(&tv_cum);

	if (sortfun)
		qsort((void *) indices, nsyscalls, sizeof(indices[0]), sortfun);

	enum column_flags {
		CF_L = 1 << 0, /* Left-aligned column */
	};
	static const struct {
		const char *s;
		size_t sz;
		const char *fmt;
		const char *last_fmt;
		uint32_t flags;
	} cdesc[] = {
		[CSC_TIME_100S]  = { ARRSZ_PAIR("% time") - 1,   "%1$*2$.2f" },
		[CSC_TIME_MIN]   = { ARRSZ_PAIR("shortest") - 1, "%1$*2$.6f" },
		[CSC_TIME_MAX]   = { ARRSZ_PAIR("longest") - 1,  "%1$*2$.6f" },
		/* Historical field sizes are preserved */
		[CSC_TIME_TOTAL] = { "seconds",    11, "%1$*2$.6f" },
		[CSC_TIME_AVG]   = { "usecs/call", 11, "%1$*2$" PRIu64 },
		[CSC_CALLS]      = { "calls",       9, "%1$*2$" PRIu64 },
		[CSC_ERRORS]     = { "errors",      9, "%1$*2$.0" PRIu64 },
		[CSC_SC_NAME]    = { "syscall",    16, "%1$-*2$s", "%1$s", CF_L },
	};

	/* calculate column widths */
#define W_(c_, v_) [c_] = MAX(cdesc[c_].sz, (v_))
	unsigned int cwidths[CSC_MAX] = {
		W_(CSC_TIME_100S,  sizeof("100.00") - 1),
		W_(CSC_TIME_TOTAL, num_chars("%.6f", float_tv_cum)),
		W_(CSC_TIME_MIN,   num_chars("%" PRId64 ".000000",
					     (int64_t) tv_min_max->tv_sec)),
		W_(CSC_TIME_MAX,   num_chars("%" PRId64 ".000000",
					     (int64_t) tv_max->tv_sec)),
		W_(CSC_TIME_AVG,   num_chars("%" PRId64 ,
					     (uint64_t) (ts_float(tv_avg_max)
							 * 1e6))),
		W_(CSC_CALLS,      num_chars("%" PRIu64, call_cum)),
		W_(CSC_ERRORS,     num_chars("%" PRIu64, error_cum)),
		W_(CSC_SC_NAME,    sc_name_max + 1),
	};
#undef W_

	/* find the last column */
	for (size_t i = 0; i < ARRAY_SIZE(columns) && columns[i]; ++i)
		last_column = i;

	/* header */
	for (size_t i = 0; i <= last_column; ++i) {
		const char *fmt = cdesc[columns[i]].flags & CF_L
				  ? (i == last_column ? "%1$s" : "%1$-*2$s")
				  : "%1$*2$s";
		if (i)
			fputc(' ', outf);
		fprintf(outf, fmt, cdesc[columns[i]].s, cwidths[columns[i]]);
	}
	fputc('\n', outf);

	/* divider */
	for (size_t i = 0; i <= last_column; ++i) {
		if (i)
			fputc(' ', outf);

		for (size_t j = 0; j < cwidths[columns[i]]; ++j)
			fputc('-', outf);
	}
	fputc('\n', outf);

	/* cache column formats */
#define FC_(c_) \
	case (c_): \
		column_fmts[i] = (i == last_column) && cdesc[c].last_fmt \
				 ? cdesc[c].last_fmt : cdesc[c].fmt; \
		break
#define PC_(c_, val_) \
	case (c_): \
		fprintf(outf, column_fmts[i], (val_), cwidths[c]); \
		break

	const char *column_fmts[last_column + 1];
	for (size_t i = 0; i <= last_column; ++i) {
		const size_t c = columns[i];

		switch (c) {
		FC_(CSC_TIME_100S);
		FC_(CSC_TIME_TOTAL);
		FC_(CSC_TIME_MIN);
		FC_(CSC_TIME_MAX);
		FC_(CSC_TIME_AVG);
		FC_(CSC_CALLS);
		FC_(CSC_ERRORS);
		FC_(CSC_SC_NAME);
		}
	}

	/* data output */
	for (size_t j = 0; j < nsyscalls; ++j) {
		unsigned int idx = indices[j];
		struct call_counts *cc = &counts[idx];
		double float_syscall_time;

		if (cc->calls == 0)
			continue;

		float_syscall_time = ts_float(&cc->time);
		percent = (100.0 * float_syscall_time);
		/* else: float_tv_cum can be 0.0 too and we get 0/0 = NAN */
		if (percent != 0.0)
			   percent /= float_tv_cum;

		for (size_t i = 0; i <= last_column; ++i) {
			const size_t c = columns[i];
			if (i)
				fputc(' ', outf);

			switch (c) {
			PC_(CSC_TIME_100S,  percent);
			PC_(CSC_TIME_TOTAL, float_syscall_time);
			PC_(CSC_TIME_MIN,   ts_float(&cc->time_min));
			PC_(CSC_TIME_MAX,   ts_float(&cc->time_max));
			PC_(CSC_TIME_AVG,
			    (uint64_t) (ts_float(&cc->time_avg) * 1e6));
			PC_(CSC_CALLS,      cc->calls);
			PC_(CSC_ERRORS,     cc->errors);
			PC_(CSC_SC_NAME,    sysent[idx].sys_name);
			}
		}

		fputc('\n', outf);
	}

	free(indices);

	/* footer */
	for (size_t i = 0; i <= last_column; ++i) {
		if (i)
			fputc(' ', outf);

		for (size_t j = 0; j < cwidths[columns[i]]; ++j)
			fputc('-', outf);
	}
	fputc('\n', outf);

	/* totals */
	for (size_t i = 0; i <= last_column; ++i) {
		const size_t c = columns[i];
		if (i)
			fputc(' ', outf);

		switch (c) {
		PC_(CSC_TIME_100S, 100.0);
		PC_(CSC_TIME_TOTAL, float_tv_cum);
		PC_(CSC_TIME_MIN, ts_float(tv_min));
		PC_(CSC_TIME_MAX, ts_float(tv_max));
		PC_(CSC_TIME_AVG, (uint64_t) (float_tv_cum / call_cum * 1e6));
		PC_(CSC_CALLS, call_cum);
		PC_(CSC_ERRORS, error_cum);
		PC_(CSC_SC_NAME, "total");
		}
	}
	fputc('\n', outf);

#undef PC_
#undef FC_
}

void
call_summary(FILE *outf)
{
	unsigned int i, old_pers = current_personality;

	for (i = 0; i < SUPPORTED_PERSONALITIES; ++i) {
		if (!countv[i])
			continue;

		if (current_personality != i)
			set_personality(i);
		if (i)
			fprintf(outf,
				"System call usage summary for %s mode:\n",
				personality_names[i]);
		call_summary_pers(outf);
	}

	if (old_pers != current_personality)
		set_personality(old_pers);
}