From: Jens Axboe Date: Mon, 18 Jun 2007 07:41:23 +0000 (+0200) Subject: Make completion and submission latency use appropriate time base X-Git-Tag: fio-1.16.5~6 X-Git-Url: https://git.kernel.dk/?p=fio.git;a=commitdiff_plain;h=d85f5118c41a112c3b8a58cc6908d00294bfb78d;hp=d2e268b09bc8ab95af81e5636608dcd93f40e4c1 Make completion and submission latency use appropriate time base It's hardcoded as msecs right now, switch the accounting to usecs and print out the appropriate base determined by the value range. Signed-off-by: Jens Axboe --- diff --git a/io_u.c b/io_u.c index 6290ebbc..53921e85 100644 --- a/io_u.c +++ b/io_u.c @@ -649,7 +649,7 @@ void io_u_log_error(struct thread_data *td, struct io_u *io_u) static void io_completed(struct thread_data *td, struct io_u *io_u, struct io_completion_data *icd) { - unsigned long msec; + unsigned long usec; assert(io_u->flags & IO_U_F_FLIGHT); io_u->flags &= ~IO_U_F_FLIGHT; @@ -673,11 +673,11 @@ static void io_completed(struct thread_data *td, struct io_u *io_u, io_u->file->last_completed_pos = io_u->endpos; - msec = mtime_since(&io_u->issue_time, &icd->time); + usec = utime_since(&io_u->issue_time, &icd->time); - add_clat_sample(td, idx, msec); + add_clat_sample(td, idx, usec); add_bw_sample(td, idx, &icd->time); - io_u_mark_latency(td, msec); + io_u_mark_latency(td, usec / 1000); if (td_write(td) && idx == DDIR_WRITE && td->o.verify != VERIFY_NONE) @@ -774,7 +774,7 @@ void io_u_queued(struct thread_data *td, struct io_u *io_u) { unsigned long slat_time; - slat_time = mtime_since(&io_u->start_time, &io_u->issue_time); + slat_time = utime_since(&io_u->start_time, &io_u->issue_time); add_slat_sample(td, io_u->ddir, slat_time); } diff --git a/stat.c b/stat.c index 0c2e01b4..1205bdd2 100644 --- a/stat.c +++ b/stat.c @@ -170,12 +170,30 @@ static void show_ddir_status(struct group_run_stats *rs, struct thread_stat *ts, free(bw_p); free(iops_p); - if (calc_lat(&ts->slat_stat[ddir], &min, &max, &mean, &dev)) - log_info(" slat (msec): min=%5lu, max=%5lu, avg=%5.02f, stdev=%5.02f\n", min, max, mean, dev); - - if (calc_lat(&ts->clat_stat[ddir], &min, &max, &mean, &dev)) - log_info(" clat (msec): min=%5lu, max=%5lu, avg=%5.02f, stdev=%5.02f\n", min, max, mean, dev); - + if (calc_lat(&ts->slat_stat[ddir], &min, &max, &mean, &dev)) { + const char *base = "(usec)"; + + if (min > 1000 && max > 1000 && mean > 1000.0 && dev > 1000.0) { + min /= 1000; + max /= 1000; + mean /= 1000.0; + dev /= 1000.0; + base = "(msec)"; + } + log_info(" slat %s: min=%5lu, max=%5lu, avg=%5.02f, stdev=%5.02f\n", base, min, max, mean, dev); + } + if (calc_lat(&ts->clat_stat[ddir], &min, &max, &mean, &dev)) { + const char *base = "(usec)"; + + if (min > 1000 && max > 1000 && mean > 1000.0 && dev > 1000.0) { + min /= 1000; + max /= 1000; + mean /= 1000.0; + dev /= 1000.0; + base = "(msec)"; + } + log_info(" clat %s: min=%5lu, max=%5lu, avg=%5.02f, stdev=%5.02f\n", base, min, max, mean, dev); + } if (calc_lat(&ts->bw_stat[ddir], &min, &max, &mean, &dev)) { double p_of_agg; @@ -227,8 +245,9 @@ static void show_thread_status(struct thread_stat *ts, log_info(" IO depths : 1=%3.1f%%, 2=%3.1f%%, 4=%3.1f%%, 8=%3.1f%%, 16=%3.1f%%, 32=%3.1f%%, >=64=%3.1f%%\n", io_u_dist[0], io_u_dist[1], io_u_dist[2], io_u_dist[3], io_u_dist[4], io_u_dist[5], io_u_dist[6]); log_info(" issued r/w: total=%lu/%lu, short=%lu/%lu\n", ts->total_io_u[0], ts->total_io_u[1], ts->short_io_u[0], ts->short_io_u[1]); - log_info(" lat (msec): 2=%3.2f%%, 4=%3.2f%%, 10=%3.2f%%, 20=%3.2f%%, 50=%3.2f%%, 100=%3.2f%%\n", io_u_lat[0], io_u_lat[1], io_u_lat[2], io_u_lat[3], io_u_lat[4], io_u_lat[5]); - log_info(" lat (msec): 250=%3.2f%%, 500=%3.2f%%, 750=%3.2f%%, 1000=%3.2f%%, >=2000=%3.2f%%\n", io_u_lat[6], io_u_lat[7], io_u_lat[8], io_u_lat[9], io_u_lat[10]); + log_info(" lat (msec): 2=%3.2f%%, 4=%3.2f%%, 10=%3.2f%%, 20=%3.2f%%, 50=%3.2f%%\n", io_u_lat[0], io_u_lat[1], io_u_lat[2], io_u_lat[3], io_u_lat[4]); + log_info(" lat (msec): 100=%3.2f%%, 250=%3.2f%%, 500=%3.2f%%, 750=%3.2f%%\n", io_u_lat[5], io_u_lat[6], io_u_lat[7], io_u_lat[8]); + log_info(" lat (msec): 1000=%3.2f%%, 2000=%3.2f%%, >=2000=%3.2f%%\n", io_u_lat[9], io_u_lat[10], io_u_lat[11]); } static void show_ddir_status_terse(struct thread_stat *ts, @@ -551,25 +570,25 @@ void add_agg_sample(unsigned long val, enum fio_ddir ddir) } void add_clat_sample(struct thread_data *td, enum fio_ddir ddir, - unsigned long msec) + unsigned long usec) { struct thread_stat *ts = &td->ts; - add_stat_sample(&ts->clat_stat[ddir], msec); + add_stat_sample(&ts->clat_stat[ddir], usec); if (ts->clat_log) - add_log_sample(td, ts->clat_log, msec, ddir); + add_log_sample(td, ts->clat_log, usec, ddir); } void add_slat_sample(struct thread_data *td, enum fio_ddir ddir, - unsigned long msec) + unsigned long usec) { struct thread_stat *ts = &td->ts; - add_stat_sample(&ts->slat_stat[ddir], msec); + add_stat_sample(&ts->slat_stat[ddir], usec); if (ts->slat_log) - add_log_sample(td, ts->slat_log, msec, ddir); + add_log_sample(td, ts->slat_log, usec, ddir); } void add_bw_sample(struct thread_data *td, enum fio_ddir ddir,