[PATCH] Improve time accounting for a job
authorJens Axboe <jens.axboe@oracle.com>
Fri, 24 Nov 2006 12:12:56 +0000 (13:12 +0100)
committerJens Axboe <jens.axboe@oracle.com>
Fri, 24 Nov 2006 12:12:56 +0000 (13:12 +0100)
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>
fio.c
fio.h
stat.c
time.c

diff --git a/fio.c b/fio.c
index a175be7..28864bd 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 cb78f25..791b005 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 e6da421..731b303 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 cb44c20..6c9eb0a 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;