From 690089990d051d86b4ef2b6fd5c1972c0dd4897b Mon Sep 17 00:00:00 2001 From: Jens Axboe Date: Fri, 24 Nov 2006 13:12:56 +0100 Subject: [PATCH 1/1] [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 --- fio.c | 16 +++++++++++----- fio.h | 2 ++ stat.c | 9 ++++----- time.c | 2 +- 4 files changed, 18 insertions(+), 11 deletions(-) diff --git a/fio.c b/fio.c index a175be7a..28864bdf 100644 --- 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 cb78f255..791b005e 100644 --- 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 e6da4218..731b3036 100644 --- 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 cb44c209..6c9eb0a8 100644 --- 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; -- 2.25.1