[PATCH] Improve time accounting for a job

We need to account loop time in usecs, or the null io engine can
get the timing wrong. For the system usage stats, don't use summed
up loop counts, but calculate end-start time instead.

Signed-off-by: Jens Axboe <jens.axboe@oracle.com>

diff --git a/fio.c b/fio.c
index a175be7a1f6bc07c13107d5f8be9152e14c67aea..28864bdf72ebf8c6f5d610e5e068c0d0cab5d506 100644 (file)
--- a/fio.c
+++ b/fio.c
@@ -605,6 +605,7 @@ static void clear_io_state(struct thread_data *td)
  */
 static void *thread_main(void *data)
 {
+       unsigned long long runtime[2];
        struct thread_data *td = data;
 
        if (!td->use_thread)
@@ -658,11 +659,12 @@ static void *thread_main(void *data)
        if (open_files(td))
                goto err;
 
-       fio_gettime(&td->epoch, NULL);
-
        if (td->exec_prerun)
                system(td->exec_prerun);
 
+       fio_gettime(&td->epoch, NULL);
+
+       runtime[0] = runtime[1] = 0;
        while (td->loops--) {
                getrusage(RUSAGE_SELF, &td->ru_start);
                fio_gettime(&td->start, NULL);
@@ -679,9 +681,9 @@ static void *thread_main(void *data)
                else
                        do_io(td);
 
-               td->runtime[td->ddir] += mtime_since_now(&td->start);
+               runtime[td->ddir] += utime_since_now(&td->start);
                if (td_rw(td) && td->io_bytes[td->ddir ^ 1])
-                       td->runtime[td->ddir ^ 1] = td->runtime[td->ddir];
+                       runtime[td->ddir ^ 1] = runtime[td->ddir];
 
                update_rusage_stat(td);
 
@@ -696,12 +698,16 @@ static void *thread_main(void *data)
 
                do_verify(td);
 
-               td->runtime[DDIR_READ] += mtime_since_now(&td->start);
+               runtime[DDIR_READ] += utime_since_now(&td->start);
 
                if (td->error || td->terminate)
                        break;
        }
 
+       fio_gettime(&td->end_time, NULL);
+       td->runtime[0] = runtime[0] / 1000;
+       td->runtime[1] = runtime[1] / 1000;
+
        if (td->bw_log)
                finish_log(td, td->bw_log, "bw");
        if (td->slat_log)

diff --git a/fio.h b/fio.h
index cb78f255822cc49367e3aba81f5bb1b9464be31f..791b005e49cf429cbaa99be3cadbdb64680c428a 100644 (file)
--- a/fio.h
+++ b/fio.h
@@ -308,6 +308,7 @@ struct thread_data {
 
        struct timeval start;   /* start of this loop */
        struct timeval epoch;   /* time job was started */
+       struct timeval end_time;/* time job ended */
 
        /*
         * fio system usage accounting
@@ -452,6 +453,7 @@ extern int setup_rate(struct thread_data *);
  * Time functions
  */
 extern unsigned long utime_since(struct timeval *, struct timeval *);
+extern unsigned long utime_since_now(struct timeval *);
 extern unsigned long mtime_since(struct timeval *, struct timeval *);
 extern unsigned long mtime_since_now(struct timeval *);
 extern unsigned long time_since_now(struct timeval *);

diff --git a/stat.c b/stat.c
index e6da4218ad9214f2741ca09142ce288c82101911..731b3036544de363e9db4a82084cce1316203d1e 100644 (file)
--- a/stat.c
+++ b/stat.c
@@ -258,9 +258,6 @@ void disk_util_timer_arm(void)
 
 void update_rusage_stat(struct thread_data *td)
 {
-       if (!(td->runtime[0] + td->runtime[1]))
-               return;
-
        getrusage(RUSAGE_SELF, &td->ru_end);
 
        td->usr_time += mtime_since(&td->ru_start.ru_utime, &td->ru_end.ru_utime);
@@ -362,6 +359,7 @@ static void show_thread_status(struct thread_data *td,
                               struct group_run_stats *rs)
 {
        double usr_cpu, sys_cpu;
+       unsigned long runtime;
 
        if (!(td->io_bytes[0] + td->io_bytes[1]) && !td->error)
                return;
@@ -372,8 +370,9 @@ static void show_thread_status(struct thread_data *td,
        if (td->io_bytes[td->ddir ^ 1])
                show_ddir_status(td, rs, td->ddir ^ 1);
 
-       if (td->runtime[0] + td->runtime[1]) {
-               double runt = td->runtime[0] + td->runtime[1];
+       runtime = mtime_since(&td->epoch, &td->end_time);
+       if (runtime) {
+               double runt = runtime;
 
                usr_cpu = (double) td->usr_time * 100 / runt;
                sys_cpu = (double) td->sys_time * 100 / runt;

diff --git a/time.c b/time.c
index cb44c209ec984a1d74ecc0b48054f999c0eed007..6c9eb0a894c951b08b09ad653594a8884fc13bbf 100644 (file)
--- a/time.c
+++ b/time.c
@@ -21,7 +21,7 @@ unsigned long utime_since(struct timeval *s, struct timeval *e)
        return sec + usec;
 }
 
-static unsigned long utime_since_now(struct timeval *s)
+unsigned long utime_since_now(struct timeval *s)
 {
        struct timeval t;