Replace struct timeval with struct timespec in time measurements
This is required to implement more precise time measurements. * Makefile.am (strace_LDADD): Add $(clock_LIBS). * defs.h (struct tcb): Change the type of stime, dtime, and etime fields from struct timeval to struct timespec, all users updated. (syscall_exiting_decode, syscall_exiting_trace, count_syscall): Change the type of "struct timeval *" argument to "struct timespec *", all users updated. (tv_nz, tv_cmp, tv_float, tv_add, tv_sub, tv_div, tv_mul): Rename to ts_nz, ts_cmp, ts_float, ts_add, ts_sub, ts_div, and ts_mul. Change the type of all "struct timeval *" arguments to "struct timespec *", all users updated. * util.c (tv_nz, tv_cmp, tv_float, tv_add, tv_sub, tv_div, tv_mul): Rename to ts_nz, ts_cmp, ts_float, ts_add, ts_sub, ts_div, and ts_mul. Change the type of all "struct timeval *" arguments to "struct timespec *". * count.c (struct call_counts): Change the type of "time" field from struct timeval to struct timespec, all users updated. (overhead): Change type from struct timeval to struct timespec, all users updated. (count_syscall): Change the type of "struct timeval *" argument to "struct timespec *". * strace.c (printleader): Change the type of struct timeval variables to struct timespec, call clock_gettime instead of gettimeofday. (next_event, trace_syscall): Change the type of struct timeval variables to struct timespec. * syscall.c (syscall_entering_finish, syscall_exiting_decode): Call clock_gettime instead of gettimeofday.
This commit is contained in:
parent
dfccb60a75
commit
17935497e2
@ -64,7 +64,7 @@ include xlat/Makemodule.am
|
||||
strace_CPPFLAGS = $(AM_CPPFLAGS)
|
||||
strace_CFLAGS = $(AM_CFLAGS)
|
||||
strace_LDFLAGS =
|
||||
strace_LDADD = libstrace.a
|
||||
strace_LDADD = libstrace.a $(clock_LIBS)
|
||||
noinst_LIBRARIES = libstrace.a
|
||||
|
||||
libstrace_a_CPPFLAGS = $(strace_CPPFLAGS)
|
||||
|
||||
40
count.c
40
count.c
@ -39,17 +39,17 @@
|
||||
/* Per-syscall stats structure */
|
||||
struct call_counts {
|
||||
/* time may be total latency or system time */
|
||||
struct timeval time;
|
||||
struct timespec time;
|
||||
unsigned int calls, errors;
|
||||
};
|
||||
|
||||
static struct call_counts *countv[SUPPORTED_PERSONALITIES];
|
||||
#define counts (countv[current_personality])
|
||||
|
||||
static struct timeval overhead;
|
||||
static struct timespec overhead;
|
||||
|
||||
void
|
||||
count_syscall(struct tcb *tcp, const struct timeval *syscall_exiting_tv)
|
||||
count_syscall(struct tcb *tcp, const struct timespec *syscall_exiting_ts)
|
||||
{
|
||||
if (!scno_in_range(tcp->scno))
|
||||
return;
|
||||
@ -64,20 +64,20 @@ count_syscall(struct tcb *tcp, const struct timeval *syscall_exiting_tv)
|
||||
|
||||
if (count_wallclock) {
|
||||
/* wall clock time spent while in syscall */
|
||||
struct timeval wtv;
|
||||
tv_sub(&wtv, syscall_exiting_tv, &tcp->etime);
|
||||
struct timespec wts;
|
||||
ts_sub(&wts, syscall_exiting_ts, &tcp->etime);
|
||||
|
||||
tv_add(&cc->time, &cc->time, &wtv);
|
||||
ts_add(&cc->time, &cc->time, &wts);
|
||||
} else {
|
||||
/* system CPU time spent while in syscall */
|
||||
tv_add(&cc->time, &cc->time, &tcp->dtime);
|
||||
ts_add(&cc->time, &cc->time, &tcp->dtime);
|
||||
}
|
||||
}
|
||||
|
||||
static int
|
||||
time_cmp(void *a, void *b)
|
||||
{
|
||||
return -tv_cmp(&counts[*((int *) a)].time,
|
||||
return -ts_cmp(&counts[*((int *) a)].time,
|
||||
&counts[*((int *) b)].time);
|
||||
}
|
||||
|
||||
@ -119,7 +119,7 @@ set_sortby(const char *sortby)
|
||||
void set_overhead(int n)
|
||||
{
|
||||
overhead.tv_sec = n / 1000000;
|
||||
overhead.tv_usec = n % 1000000;
|
||||
overhead.tv_nsec = n % 1000000 * 1000;
|
||||
}
|
||||
|
||||
static void
|
||||
@ -132,7 +132,7 @@ call_summary_pers(FILE *outf)
|
||||
|
||||
unsigned int i;
|
||||
unsigned int call_cum, error_cum;
|
||||
struct timeval tv_cum, dtv;
|
||||
struct timespec tv_cum, dtv;
|
||||
double float_tv_cum;
|
||||
double percent;
|
||||
unsigned int *sorted_count;
|
||||
@ -143,20 +143,20 @@ call_summary_pers(FILE *outf)
|
||||
fprintf(outf, header, dashes, dashes, dashes, dashes, dashes, dashes);
|
||||
|
||||
sorted_count = xcalloc(sizeof(sorted_count[0]), nsyscalls);
|
||||
call_cum = error_cum = tv_cum.tv_sec = tv_cum.tv_usec = 0;
|
||||
call_cum = error_cum = tv_cum.tv_sec = tv_cum.tv_nsec = 0;
|
||||
for (i = 0; i < nsyscalls; i++) {
|
||||
sorted_count[i] = i;
|
||||
if (counts == NULL || counts[i].calls == 0)
|
||||
continue;
|
||||
tv_mul(&dtv, &overhead, counts[i].calls);
|
||||
tv_sub(&counts[i].time, &counts[i].time, &dtv);
|
||||
if (counts[i].time.tv_sec < 0 || counts[i].time.tv_usec < 0)
|
||||
counts[i].time.tv_sec = counts[i].time.tv_usec = 0;
|
||||
ts_mul(&dtv, &overhead, counts[i].calls);
|
||||
ts_sub(&counts[i].time, &counts[i].time, &dtv);
|
||||
if (counts[i].time.tv_sec < 0 || counts[i].time.tv_nsec < 0)
|
||||
counts[i].time.tv_sec = counts[i].time.tv_nsec = 0;
|
||||
call_cum += counts[i].calls;
|
||||
error_cum += counts[i].errors;
|
||||
tv_add(&tv_cum, &tv_cum, &counts[i].time);
|
||||
ts_add(&tv_cum, &tv_cum, &counts[i].time);
|
||||
}
|
||||
float_tv_cum = tv_float(&tv_cum);
|
||||
float_tv_cum = ts_float(&tv_cum);
|
||||
if (counts) {
|
||||
if (sortfun)
|
||||
qsort((void *) sorted_count, nsyscalls,
|
||||
@ -167,15 +167,15 @@ call_summary_pers(FILE *outf)
|
||||
struct call_counts *cc = &counts[idx];
|
||||
if (cc->calls == 0)
|
||||
continue;
|
||||
tv_div(&dtv, &cc->time, cc->calls);
|
||||
float_syscall_time = tv_float(&cc->time);
|
||||
ts_div(&dtv, &cc->time, cc->calls);
|
||||
float_syscall_time = ts_float(&cc->time);
|
||||
percent = (100.0 * float_syscall_time);
|
||||
if (percent != 0.0)
|
||||
percent /= float_tv_cum;
|
||||
/* else: float_tv_cum can be 0.0 too and we get 0/0 = NAN */
|
||||
fprintf(outf, data,
|
||||
percent, float_syscall_time,
|
||||
(long) (1000000 * dtv.tv_sec + dtv.tv_usec),
|
||||
(long) (1000000 * dtv.tv_sec + dtv.tv_nsec / 1000),
|
||||
cc->calls, cc->errors, sysent[idx].sys_name);
|
||||
}
|
||||
}
|
||||
|
||||
26
defs.h
26
defs.h
@ -210,9 +210,9 @@ struct tcb {
|
||||
const struct_sysent *s_ent; /* sysent[scno] or dummy struct for bad scno */
|
||||
const struct_sysent *s_prev_ent; /* for "resuming interrupted SYSCALL" msg */
|
||||
struct inject_opts *inject_vec[SUPPORTED_PERSONALITIES];
|
||||
struct timeval stime; /* System time usage as of last process wait */
|
||||
struct timeval dtime; /* Delta for system time usage */
|
||||
struct timeval etime; /* Syscall entry time */
|
||||
struct timespec stime; /* System time usage as of last process wait */
|
||||
struct timespec dtime; /* Delta for system time usage */
|
||||
struct timespec etime; /* Syscall entry time */
|
||||
|
||||
struct mmap_cache_t *mmap_cache;
|
||||
unsigned int mmap_cache_size;
|
||||
@ -393,11 +393,11 @@ extern int syscall_entering_decode(struct tcb *);
|
||||
extern int syscall_entering_trace(struct tcb *, unsigned int *);
|
||||
extern void syscall_entering_finish(struct tcb *, int);
|
||||
|
||||
extern int syscall_exiting_decode(struct tcb *, struct timeval *);
|
||||
extern int syscall_exiting_trace(struct tcb *, struct timeval, int);
|
||||
extern int syscall_exiting_decode(struct tcb *, struct timespec *);
|
||||
extern int syscall_exiting_trace(struct tcb *, struct timespec *, int);
|
||||
extern void syscall_exiting_finish(struct tcb *);
|
||||
|
||||
extern void count_syscall(struct tcb *, const struct timeval *);
|
||||
extern void count_syscall(struct tcb *, const struct timespec *);
|
||||
extern void call_summary(FILE *);
|
||||
|
||||
extern void clear_regs(struct tcb *tcp);
|
||||
@ -719,13 +719,13 @@ DECL_NETLINK(route);
|
||||
DECL_NETLINK(selinux);
|
||||
DECL_NETLINK(sock_diag);
|
||||
|
||||
extern int tv_nz(const struct timeval *);
|
||||
extern int tv_cmp(const struct timeval *, const struct timeval *);
|
||||
extern double tv_float(const struct timeval *);
|
||||
extern void tv_add(struct timeval *, const struct timeval *, const struct timeval *);
|
||||
extern void tv_sub(struct timeval *, const struct timeval *, const struct timeval *);
|
||||
extern void tv_mul(struct timeval *, const struct timeval *, int);
|
||||
extern void tv_div(struct timeval *, const struct timeval *, int);
|
||||
extern int ts_nz(const struct timespec *);
|
||||
extern int ts_cmp(const struct timespec *, const struct timespec *);
|
||||
extern double ts_float(const struct timespec *);
|
||||
extern void ts_add(struct timespec *, const struct timespec *, const struct timespec *);
|
||||
extern void ts_sub(struct timespec *, const struct timespec *, const struct timespec *);
|
||||
extern void ts_mul(struct timespec *, const struct timespec *, int);
|
||||
extern void ts_div(struct timespec *, const struct timespec *, int);
|
||||
|
||||
#ifdef USE_LIBUNWIND
|
||||
extern void unwind_init(void);
|
||||
|
||||
41
strace.c
41
strace.c
@ -641,30 +641,31 @@ printleader(struct tcb *tcp)
|
||||
tprintf("[pid %5u] ", tcp->pid);
|
||||
|
||||
if (tflag) {
|
||||
struct timeval tv;
|
||||
gettimeofday(&tv, NULL);
|
||||
struct timespec ts;
|
||||
clock_gettime(rflag ? CLOCK_MONOTONIC : CLOCK_REALTIME, &ts);
|
||||
|
||||
if (rflag) {
|
||||
static struct timeval otv;
|
||||
if (otv.tv_sec == 0)
|
||||
otv = tv;
|
||||
static struct timespec ots;
|
||||
if (ots.tv_sec == 0)
|
||||
ots = ts;
|
||||
|
||||
struct timeval dtv;
|
||||
tv_sub(&dtv, &tv, &otv);
|
||||
otv = tv;
|
||||
struct timespec dts;
|
||||
ts_sub(&dts, &ts, &ots);
|
||||
ots = ts;
|
||||
|
||||
tprintf("%6ld.%06ld ",
|
||||
(long) dtv.tv_sec, (long) dtv.tv_usec);
|
||||
(long) dts.tv_sec, (long) dts.tv_nsec / 1000);
|
||||
} else if (tflag > 2) {
|
||||
tprintf("%ld.%06ld ",
|
||||
(long) tv.tv_sec, (long) tv.tv_usec);
|
||||
tprintf("%lld.%06ld ",
|
||||
(long long) ts.tv_sec, (long) ts.tv_nsec / 1000);
|
||||
} else {
|
||||
time_t local = tv.tv_sec;
|
||||
time_t local = ts.tv_sec;
|
||||
char str[sizeof("HH:MM:SS")];
|
||||
|
||||
strftime(str, sizeof(str), "%T", localtime(&local));
|
||||
if (tflag > 1)
|
||||
tprintf("%s.%06ld ", str, (long) tv.tv_usec);
|
||||
tprintf("%s.%06ld ",
|
||||
str, (long) ts.tv_nsec / 1000);
|
||||
else
|
||||
tprintf("%s ", str);
|
||||
}
|
||||
@ -2299,8 +2300,12 @@ next_event(int *pstatus, siginfo_t *si)
|
||||
set_current_tcp(tcp);
|
||||
|
||||
if (cflag) {
|
||||
tv_sub(&tcp->dtime, &ru.ru_stime, &tcp->stime);
|
||||
tcp->stime = ru.ru_stime;
|
||||
struct timespec stime = {
|
||||
.tv_sec = ru.ru_stime.tv_sec,
|
||||
.tv_nsec = ru.ru_stime.tv_usec * 1000
|
||||
};
|
||||
ts_sub(&tcp->dtime, &stime, &tcp->stime);
|
||||
tcp->stime = stime;
|
||||
}
|
||||
|
||||
if (WIFSIGNALED(status))
|
||||
@ -2385,10 +2390,10 @@ trace_syscall(struct tcb *tcp, unsigned int *sig)
|
||||
syscall_entering_finish(tcp, res);
|
||||
return res;
|
||||
} else {
|
||||
struct timeval tv = {};
|
||||
int res = syscall_exiting_decode(tcp, &tv);
|
||||
struct timespec ts = {};
|
||||
int res = syscall_exiting_decode(tcp, &ts);
|
||||
if (res != 0) {
|
||||
res = syscall_exiting_trace(tcp, tv, res);
|
||||
res = syscall_exiting_trace(tcp, &ts, res);
|
||||
}
|
||||
syscall_exiting_finish(tcp);
|
||||
return res;
|
||||
|
||||
14
syscall.c
14
syscall.c
@ -711,7 +711,7 @@ syscall_entering_finish(struct tcb *tcp, int res)
|
||||
tcp->sys_func_rval = res;
|
||||
/* Measure the entrance time as late as possible to avoid errors. */
|
||||
if ((Tflag || cflag) && !filtered(tcp))
|
||||
gettimeofday(&tcp->etime, NULL);
|
||||
clock_gettime(CLOCK_MONOTONIC, &tcp->etime);
|
||||
}
|
||||
|
||||
/* Returns:
|
||||
@ -723,11 +723,11 @@ syscall_entering_finish(struct tcb *tcp, int res)
|
||||
* value. Anyway, call syscall_exiting_finish(tcp) then.
|
||||
*/
|
||||
int
|
||||
syscall_exiting_decode(struct tcb *tcp, struct timeval *ptv)
|
||||
syscall_exiting_decode(struct tcb *tcp, struct timespec *pts)
|
||||
{
|
||||
/* Measure the exit time as early as possible to avoid errors. */
|
||||
if ((Tflag || cflag) && !(filtered(tcp) || hide_log(tcp)))
|
||||
gettimeofday(ptv, NULL);
|
||||
clock_gettime(CLOCK_MONOTONIC, pts);
|
||||
|
||||
if (mmap_cache_is_enabled()) {
|
||||
if (tcp->s_ent->sys_flags & STACKTRACE_INVALIDATE_CACHE)
|
||||
@ -745,13 +745,13 @@ syscall_exiting_decode(struct tcb *tcp, struct timeval *ptv)
|
||||
}
|
||||
|
||||
int
|
||||
syscall_exiting_trace(struct tcb *tcp, struct timeval tv, int res)
|
||||
syscall_exiting_trace(struct tcb *tcp, struct timespec *ts, int res)
|
||||
{
|
||||
if (syscall_tampered(tcp))
|
||||
tamper_with_syscall_exiting(tcp);
|
||||
|
||||
if (cflag) {
|
||||
count_syscall(tcp, &tv);
|
||||
count_syscall(tcp, ts);
|
||||
if (cflag == CFLAG_ONLY_STATS) {
|
||||
return 0;
|
||||
}
|
||||
@ -942,9 +942,9 @@ syscall_exiting_trace(struct tcb *tcp, struct timeval tv, int res)
|
||||
tprints(" (INJECTED)");
|
||||
}
|
||||
if (Tflag) {
|
||||
tv_sub(&tv, &tv, &tcp->etime);
|
||||
ts_sub(ts, ts, &tcp->etime);
|
||||
tprintf(" <%ld.%06ld>",
|
||||
(long) tv.tv_sec, (long) tv.tv_usec);
|
||||
(long) ts->tv_sec, (long) ts->tv_nsec / 1000);
|
||||
}
|
||||
tprints("\n");
|
||||
dumpio(tcp);
|
||||
|
||||
46
util.c
46
util.c
@ -47,65 +47,65 @@
|
||||
#include "xstring.h"
|
||||
|
||||
int
|
||||
tv_nz(const struct timeval *a)
|
||||
ts_nz(const struct timespec *a)
|
||||
{
|
||||
return a->tv_sec || a->tv_usec;
|
||||
return a->tv_sec || a->tv_nsec;
|
||||
}
|
||||
|
||||
int
|
||||
tv_cmp(const struct timeval *a, const struct timeval *b)
|
||||
ts_cmp(const struct timespec *a, const struct timespec *b)
|
||||
{
|
||||
if (a->tv_sec < b->tv_sec
|
||||
|| (a->tv_sec == b->tv_sec && a->tv_usec < b->tv_usec))
|
||||
|| (a->tv_sec == b->tv_sec && a->tv_nsec < b->tv_nsec))
|
||||
return -1;
|
||||
if (a->tv_sec > b->tv_sec
|
||||
|| (a->tv_sec == b->tv_sec && a->tv_usec > b->tv_usec))
|
||||
|| (a->tv_sec == b->tv_sec && a->tv_nsec > b->tv_nsec))
|
||||
return 1;
|
||||
return 0;
|
||||
}
|
||||
|
||||
double
|
||||
tv_float(const struct timeval *tv)
|
||||
ts_float(const struct timespec *tv)
|
||||
{
|
||||
return tv->tv_sec + tv->tv_usec/1000000.0;
|
||||
return tv->tv_sec + tv->tv_nsec/1000000000.0;
|
||||
}
|
||||
|
||||
void
|
||||
tv_add(struct timeval *tv, const struct timeval *a, const struct timeval *b)
|
||||
ts_add(struct timespec *tv, const struct timespec *a, const struct timespec *b)
|
||||
{
|
||||
tv->tv_sec = a->tv_sec + b->tv_sec;
|
||||
tv->tv_usec = a->tv_usec + b->tv_usec;
|
||||
if (tv->tv_usec >= 1000000) {
|
||||
tv->tv_nsec = a->tv_nsec + b->tv_nsec;
|
||||
if (tv->tv_nsec >= 1000000000) {
|
||||
tv->tv_sec++;
|
||||
tv->tv_usec -= 1000000;
|
||||
tv->tv_nsec -= 1000000000;
|
||||
}
|
||||
}
|
||||
|
||||
void
|
||||
tv_sub(struct timeval *tv, const struct timeval *a, const struct timeval *b)
|
||||
ts_sub(struct timespec *tv, const struct timespec *a, const struct timespec *b)
|
||||
{
|
||||
tv->tv_sec = a->tv_sec - b->tv_sec;
|
||||
tv->tv_usec = a->tv_usec - b->tv_usec;
|
||||
if (((long) tv->tv_usec) < 0) {
|
||||
tv->tv_nsec = a->tv_nsec - b->tv_nsec;
|
||||
if (tv->tv_nsec < 0) {
|
||||
tv->tv_sec--;
|
||||
tv->tv_usec += 1000000;
|
||||
tv->tv_nsec += 1000000000;
|
||||
}
|
||||
}
|
||||
|
||||
void
|
||||
tv_div(struct timeval *tv, const struct timeval *a, int n)
|
||||
ts_div(struct timespec *tv, const struct timespec *a, int n)
|
||||
{
|
||||
tv->tv_usec = (a->tv_sec % n * 1000000 + a->tv_usec + n / 2) / n;
|
||||
tv->tv_sec = a->tv_sec / n + tv->tv_usec / 1000000;
|
||||
tv->tv_usec %= 1000000;
|
||||
long long nsec = (a->tv_sec % n * 1000000000LL + a->tv_nsec + n / 2) / n;
|
||||
tv->tv_sec = a->tv_sec / n + nsec / 1000000000;
|
||||
tv->tv_nsec = nsec % 1000000000;
|
||||
}
|
||||
|
||||
void
|
||||
tv_mul(struct timeval *tv, const struct timeval *a, int n)
|
||||
ts_mul(struct timespec *tv, const struct timespec *a, int n)
|
||||
{
|
||||
tv->tv_usec = a->tv_usec * n;
|
||||
tv->tv_sec = a->tv_sec * n + tv->tv_usec / 1000000;
|
||||
tv->tv_usec %= 1000000;
|
||||
long long nsec = a->tv_nsec * n;
|
||||
tv->tv_sec = a->tv_sec * n + nsec / 1000000000;
|
||||
tv->tv_nsec = nsec % 1000000000;
|
||||
}
|
||||
|
||||
#if !defined HAVE_STPCPY
|
||||
|
||||
Loading…
Reference in New Issue
Block a user