syscall: track syscall system time a bit more explicitly

Before, it relied on implicit assumptions that syscall-exit event is
right the next one after syscall-enter.  Also, there's some additional
debugging output that might help someone someday.

* count.c (count_syscall): Calculate system time as difference of tcp's
stime and ltime.
* defs.h (struct tcb): Add ltime, atime fields, remove dtime.
* strace.c (droptcb): Print total system time spent by a tcb.
(startup_tcb): Store initial system time in atime.
(next_event): Update stime directly.
* syscall.c (syscall_entering_finish): Store current system time in
tcb's ltime field.
(syscall_exiting_finish): Likewise.

diff --git a/count.c b/count.c
index e66b85e530322535a6d2cfae99cc92be838e78d2..3adde7a3623eb0fb511000ff693aaf26319cc82e 100644 (file)
--- a/count.c
+++ b/count.c
@@ -48,12 +48,12 @@ count_syscall(struct tcb *tcp, const struct timespec *syscall_exiting_ts)
        if (count_wallclock) {
                /* wall clock time spent while in syscall */
                ts_sub(&wts, syscall_exiting_ts, &tcp->etime);
-               ts_sub(&wts, &wts, &overhead);
        } else {
                /* system CPU time spent while in syscall */
-               ts_sub(&wts, &tcp->dtime, &overhead);
+               ts_sub(&wts, &tcp->stime, &tcp->ltime);
        }
 
+       ts_sub(&wts, &wts, &overhead);
        ts_add(&cc->time, &cc->time, ts_max(&wts, &zero_ts));
 }
 

diff --git a/defs.h b/defs.h
index cd71d9988a32bb4b9bc538b732609d15276747e1..003cc2283f8cf7d454a69e336920bd17c41a62f7 100644 (file)
--- a/defs.h
+++ b/defs.h
@@ -215,8 +215,9 @@ struct tcb {
        const struct_sysent *s_prev_ent; /* for "resuming interrupted SYSCALL" msg */
        struct inject_opts *inject_vec[SUPPORTED_PERSONALITIES];
        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 timespec ltime;  /* System time usage as of last syscall entry */
+       struct timespec atime;  /* System time right after attach */
+       struct timespec etime;  /* Syscall entry time (CLOCK_MONOTONIC) */
        struct timespec delay_expiration_time; /* When does the delay end */
 
        struct mmap_cache_t *mmap_cache;

diff --git a/strace.c b/strace.c
index 6821f397951bd9714ed6a541dad51af3f3035b7f..59097e1408f56189e81bec34ad876e622b5aa463 100644 (file)
--- a/strace.c
+++ b/strace.c
@@ -801,6 +801,14 @@ droptcb(struct tcb *tcp)
        if (tcp->pid == 0)
                return;
 
+       if (cflag && debug_flag) {
+               struct timespec dt;
+
+               ts_sub(&dt, &tcp->stime, &tcp->atime);
+               debug_func_msg("pid %d: %.9f seconds of system time spent "
+                              "since attach", tcp->pid, ts_float(&dt));
+       }
+
        int p;
        for (p = 0; p < SUPPORTED_PERSONALITIES; ++p)
                free(tcp->inject_vec[p]);
@@ -2226,6 +2234,10 @@ startup_tcb(struct tcb *tcp)
 
        if ((tcp->flags & TCB_GRABBED) && (get_scno(tcp) == 1))
                tcp->s_prev_ent = tcp->s_ent;
+
+       if (cflag) {
+               tcp->atime = tcp->stime;
+       }
 }
 
 static void
@@ -2442,12 +2454,8 @@ next_event(void)
                }
 
                if (cflag) {
-                       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;
+                       tcp->stime.tv_sec = ru.ru_stime.tv_sec;
+                       tcp->stime.tv_nsec = ru.ru_stime.tv_usec * 1000;
                }
 
                tcb_wait_tab_check_size(wait_tab_pos);

diff --git a/syscall.c b/syscall.c
index 20d04d0d6ff52bd95ed88762c5be4d273ae26670..16c603bc382c004d7a5610ad4efe00dd3fddab9e 100644 (file)
--- a/syscall.c
+++ b/syscall.c
@@ -665,9 +665,27 @@ syscall_entering_finish(struct tcb *tcp, int res)
 {
        tcp->flags |= TCB_INSYSCALL;
        tcp->sys_func_rval = res;
+
        /* Measure the entrance time as late as possible to avoid errors. */
        if ((Tflag || cflag) && !filtered(tcp))
                clock_gettime(CLOCK_MONOTONIC, &tcp->etime);
+
+       /* Start tracking system time */
+       if (cflag) {
+               if (debug_flag) {
+                       struct timespec dt;
+
+                       ts_sub(&dt, &tcp->stime, &tcp->ltime);
+
+                       if (ts_nz(&dt))
+                               debug_func_msg("pid %d: %.9f seconds of system "
+                                              "time spent since the last "
+                                              "syscall exit",
+                                              tcp->pid, ts_float(&dt));
+               }
+
+               tcp->ltime = tcp->stime;
+       }
 }
 
 /* Returns:
@@ -921,6 +939,9 @@ syscall_exiting_finish(struct tcb *tcp)
        tcp->flags &= ~(TCB_INSYSCALL | TCB_TAMPERED | TCB_INJECT_DELAY_EXIT);
        tcp->sys_func_rval = 0;
        free_tcb_priv_data(tcp);
+
+       if (cflag)
+               tcp->ltime = tcp->stime;
 }
 
 bool