From 17935497e2f4e78b183026e1a49f4c279d0f276e Mon Sep 17 00:00:00 2001 From: "Dmitry V. Levin" Date: Fri, 16 Mar 2018 00:55:58 +0000 Subject: [PATCH] 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. --- Makefile.am | 2 +- count.c | 40 ++++++++++++++++++++-------------------- defs.h | 26 +++++++++++++------------- strace.c | 41 +++++++++++++++++++++++------------------ syscall.c | 14 +++++++------- util.c | 46 +++++++++++++++++++++++----------------------- 6 files changed, 87 insertions(+), 82 deletions(-) diff --git a/Makefile.am b/Makefile.am index 181a0f8e..ed1cda26 100644 --- a/Makefile.am +++ b/Makefile.am @@ -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) diff --git a/count.c b/count.c index 5d93371d..d667ec50 100644 --- a/count.c +++ b/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); } } diff --git a/defs.h b/defs.h index 266c8d6a..702c7514 100644 --- a/defs.h +++ b/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); diff --git a/strace.c b/strace.c index 80eb4dd1..9f2f4c68 100644 --- a/strace.c +++ b/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; diff --git a/syscall.c b/syscall.c index 24263b69..75e15b6e 100644 --- a/syscall.c +++ b/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); diff --git a/util.c b/util.c index 28124276..a69c9759 100644 --- a/util.c +++ b/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 -- 2.40.0