From d6bb626ef37d3905221ade2887b422717a07af09 Mon Sep 17 00:00:00 2001 From: Vincent Fu Date: Thu, 16 Mar 2017 12:11:46 -0400 Subject: [PATCH] nanosecond: update completion latency recording and normal, json output to use nanoseconds A new set of nsec bins (0-1, 2-3, 4-9, 10-19, ...) is created for tracking latencies. The number of io_u_plat[] latency bins is increased by about 50% to accommodate the greater resolution while retaining the same max latency value of ~9 seconds. Example output test: (g=0): rw=read, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=null, iodepth=1 fio-2.20-39-g83b3 Starting 1 process Jobs: 1 (f=1): [R(1)][100.0%][r=14.6GiB/s,w=0KiB/s][r=3832k,w=0 IOPS][eta 00m:00s] test: (groupid=0, jobs=1): err= 0: pid=17621: Thu Jun 1 15:09:38 2017 read: IOPS=3784k, BW=14.4GiB/s (15.5GB/s)(144GiB/10000msec) clat (nsec): min=15, max=1685.2k, avg=26.92, stdev=433.62 lat (nsec): min=46, max=5989.9k, avg=67.31, stdev=1659.58 clat percentiles (nsec): | 1.00th=[ 18], 5.00th=[ 18], 10.00th=[ 19], 20.00th=[ 19], | 30.00th=[ 22], 40.00th=[ 22], 50.00th=[ 25], 60.00th=[ 26], | 70.00th=[ 26], 80.00th=[ 27], 90.00th=[ 36], 95.00th=[ 41], | 99.00th=[ 46], 99.50th=[ 50], 99.90th=[ 104], 99.95th=[ 139], | 99.99th=[ 7840] bw ( MiB/s): min=13393, max=15647, per=0.10%, avg=14784.86, stdev=558.40 lat (nsec) : 20=20.87%, 50=78.57%, 100=0.43%, 250=0.10%, 500=0.01% lat (nsec) : 750=0.01%, 1000=0.01% lat (usec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01% lat (usec) : 100=0.01%, 250=0.01%, 500=0.01%, 1000=0.01% lat (msec) : 2=0.01% cpu : usr=99.72%, sys=0.12%, ctx=321, majf=0, minf=8 IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued rwt: total=37840231,0,0, short=0,0,0, dropped=0,0,0 latency : target=0, window=0, percentile=100.00%, depth=1 Run status group 0 (all jobs): READ: bw=14.4GiB/s (15.5GB/s), 14.4GiB/s-14.4GiB/s (15.5GB/s-15.5GB/s), io=144GiB (155GB), run=10000-10000msec --- client.c | 2 + fio_time.h | 3 +- gettime.c | 20 +++++++ io_u.c | 87 +++++++++++++++++++++------- server.c | 2 + stat.c | 164 ++++++++++++++++++++++++++++++++--------------------- stat.h | 32 ++++++++--- 7 files changed, 215 insertions(+), 95 deletions(-) diff --git a/client.c b/client.c index 42ccbef0..81119c2e 100644 --- a/client.c +++ b/client.c @@ -908,6 +908,8 @@ static void convert_ts(struct thread_stat *dst, struct thread_stat *src) dst->io_u_complete[i] = le32_to_cpu(src->io_u_complete[i]); } + for (i = 0; i < FIO_IO_U_LAT_N_NR; i++) + dst->io_u_lat_n[i] = le32_to_cpu(src->io_u_lat_n[i]); for (i = 0; i < FIO_IO_U_LAT_U_NR; i++) dst->io_u_lat_u[i] = le32_to_cpu(src->io_u_lat_u[i]); for (i = 0; i < FIO_IO_U_LAT_M_NR; i++) diff --git a/fio_time.h b/fio_time.h index 3a5848e7..f4eac793 100644 --- a/fio_time.h +++ b/fio_time.h @@ -4,7 +4,8 @@ #include "lib/types.h" struct thread_data; -extern uint64_t utime_since(const struct timespec *,const struct timespec *); +extern uint64_t ntime_since(const struct timespec *, const struct timespec *); +extern uint64_t utime_since(const struct timespec *, const struct timespec *); extern uint64_t utime_since_now(const struct timespec *); extern uint64_t mtime_since(const struct timespec *, const struct timespec *); extern uint64_t mtime_since_now(const struct timespec *); diff --git a/gettime.c b/gettime.c index a4ee20df..6ced2f1d 100644 --- a/gettime.c +++ b/gettime.c @@ -380,6 +380,26 @@ void fio_clock_init(void) log_info("fio: clocksource=cpu may not be reliable\n"); } +uint64_t ntime_since(const struct timespec *s, const struct timespec *e) +{ + int64_t sec, nsec; + + sec = e->tv_sec - s->tv_sec; + nsec = e->tv_nsec - s->tv_nsec; + if (sec > 0 && nsec < 0) { + sec--; + nsec += 1000000000LL; + } + + /* + * time warp bug on some kernels? + */ + if (sec < 0 || (sec == 0 && nsec < 0)) + return 0; + + return nsec + (sec * 1000000000LL); +} + uint64_t utime_since(const struct timespec *s, const struct timespec *e) { int64_t sec, usec; diff --git a/io_u.c b/io_u.c index 51d6e958..375413f4 100644 --- a/io_u.c +++ b/io_u.c @@ -989,11 +989,52 @@ void io_u_mark_depth(struct thread_data *td, unsigned int nr) td->ts.io_u_map[idx] += nr; } -static void io_u_mark_lat_usec(struct thread_data *td, unsigned long usec) +static void io_u_mark_lat_nsec(struct thread_data *td, unsigned long long nsec) { int idx = 0; - assert(usec < 1000); + assert(nsec < 1000); + + switch (nsec) { + case 750 ... 999: + idx = 9; + break; + case 500 ... 749: + idx = 8; + break; + case 250 ... 499: + idx = 7; + break; + case 100 ... 249: + idx = 6; + break; + case 50 ... 99: + idx = 5; + break; + case 20 ... 49: + idx = 4; + break; + case 10 ... 19: + idx = 3; + break; + case 4 ... 9: + idx = 2; + break; + case 2 ... 3: + idx = 1; + case 0 ... 1: + break; + } + + assert(idx < FIO_IO_U_LAT_N_NR); + td->ts.io_u_lat_n[idx]++; +} + +static void io_u_mark_lat_usec(struct thread_data *td, unsigned long long usec) +{ + int idx = 0; + + assert(usec < 1000 && usec >= 1); switch (usec) { case 750 ... 999: @@ -1030,10 +1071,12 @@ static void io_u_mark_lat_usec(struct thread_data *td, unsigned long usec) td->ts.io_u_lat_u[idx]++; } -static void io_u_mark_lat_msec(struct thread_data *td, unsigned long msec) +static void io_u_mark_lat_msec(struct thread_data *td, unsigned long long msec) { int idx = 0; + assert(msec >= 1); + switch (msec) { default: idx = 11; @@ -1075,12 +1118,14 @@ static void io_u_mark_lat_msec(struct thread_data *td, unsigned long msec) td->ts.io_u_lat_m[idx]++; } -static void io_u_mark_latency(struct thread_data *td, unsigned long usec) +static void io_u_mark_latency(struct thread_data *td, unsigned long long nsec) { - if (usec < 1000) - io_u_mark_lat_usec(td, usec); + if (nsec < 1000) + io_u_mark_lat_nsec(td, nsec); + else if (nsec < 1000000) + io_u_mark_lat_usec(td, nsec / 1000); else - io_u_mark_lat_msec(td, usec / 1000); + io_u_mark_lat_msec(td, nsec / 1000000); } static unsigned int __get_next_fileno_rand(struct thread_data *td) @@ -1729,7 +1774,7 @@ static void account_io_completion(struct thread_data *td, struct io_u *io_u, const enum fio_ddir idx, unsigned int bytes) { const int no_reduce = !gtod_reduce(td); - unsigned long lusec = 0; + unsigned long long llnsec = 0; if (td->parent) td = td->parent; @@ -1738,37 +1783,37 @@ static void account_io_completion(struct thread_data *td, struct io_u *io_u, return; if (no_reduce) - lusec = utime_since(&io_u->issue_time, &icd->time); + llnsec = ntime_since(&io_u->issue_time, &icd->time); if (!td->o.disable_lat) { - unsigned long tusec; + unsigned long long tnsec; - tusec = utime_since(&io_u->start_time, &icd->time); - add_lat_sample(td, idx, tusec, bytes, io_u->offset); + tnsec = ntime_since(&io_u->start_time, &icd->time); + add_lat_sample(td, idx, tnsec, bytes, io_u->offset); if (td->flags & TD_F_PROFILE_OPS) { struct prof_io_ops *ops = &td->prof_io_ops; if (ops->io_u_lat) - icd->error = ops->io_u_lat(td, tusec); + icd->error = ops->io_u_lat(td, tnsec/1000); } - if (td->o.max_latency && tusec > td->o.max_latency) - lat_fatal(td, icd, tusec, td->o.max_latency); - if (td->o.latency_target && tusec > td->o.latency_target) { + if (td->o.max_latency && tnsec/1000 > td->o.max_latency) + lat_fatal(td, icd, tnsec/1000, td->o.max_latency); + if (td->o.latency_target && tnsec/1000 > td->o.latency_target) { if (lat_target_failed(td)) - lat_fatal(td, icd, tusec, td->o.latency_target); + lat_fatal(td, icd, tnsec/1000, td->o.latency_target); } } if (ddir_rw(idx)) { if (!td->o.disable_clat) { - add_clat_sample(td, idx, lusec, bytes, io_u->offset); - io_u_mark_latency(td, lusec); + add_clat_sample(td, idx, llnsec, bytes, io_u->offset); + io_u_mark_latency(td, llnsec); } if (!td->o.disable_bw && per_unit_log(td->bw_log)) - add_bw_sample(td, io_u, bytes, lusec); + add_bw_sample(td, io_u, bytes, llnsec); if (no_reduce && per_unit_log(td->iops_log)) add_iops_sample(td, io_u, bytes); @@ -2000,7 +2045,7 @@ void io_u_queued(struct thread_data *td, struct io_u *io_u) if (!td->o.disable_slat && ramp_time_over(td) && td->o.stats) { unsigned long slat_time; - slat_time = utime_since(&io_u->start_time, &io_u->issue_time); + slat_time = ntime_since(&io_u->start_time, &io_u->issue_time); if (td->parent) td = td->parent; diff --git a/server.c b/server.c index 017ab130..b0a6e876 100644 --- a/server.c +++ b/server.c @@ -1497,6 +1497,8 @@ void fio_server_send_ts(struct thread_stat *ts, struct group_run_stats *rs) p.ts.io_u_complete[i] = cpu_to_le32(ts->io_u_complete[i]); } + for (i = 0; i < FIO_IO_U_LAT_N_NR; i++) + p.ts.io_u_lat_n[i] = cpu_to_le32(ts->io_u_lat_n[i]); for (i = 0; i < FIO_IO_U_LAT_U_NR; i++) p.ts.io_u_lat_u[i] = cpu_to_le32(ts->io_u_lat_u[i]); for (i = 0; i < FIO_IO_U_LAT_M_NR; i++) diff --git a/stat.c b/stat.c index 6ffcad93..28acf103 100644 --- a/stat.c +++ b/stat.c @@ -58,7 +58,7 @@ void update_rusage_stat(struct thread_data *td) * group by looking at the index bits. * */ -static unsigned int plat_val_to_idx(unsigned int val) +static unsigned int plat_val_to_idx(unsigned long long val) { unsigned int msb, error_bits, base, offset, idx; @@ -66,7 +66,7 @@ static unsigned int plat_val_to_idx(unsigned int val) if (val == 0) msb = 0; else - msb = (sizeof(val)*8) - __builtin_clz(val) - 1; + msb = (sizeof(val)*8) - __builtin_clzll(val) - 1; /* * MSB <= (FIO_IO_U_PLAT_BITS-1), cannot be rounded off. Use @@ -135,16 +135,16 @@ static int double_cmp(const void *a, const void *b) } unsigned int calc_clat_percentiles(unsigned int *io_u_plat, unsigned long nr, - fio_fp64_t *plist, unsigned int **output, - unsigned int *maxv, unsigned int *minv) + fio_fp64_t *plist, unsigned long long **output, + unsigned long long *maxv, unsigned long long *minv) { unsigned long sum = 0; unsigned int len, i, j = 0; unsigned int oval_len = 0; - unsigned int *ovals = NULL; + unsigned long long *ovals = NULL; int is_last; - *minv = -1U; + *minv = -1ULL; *maxv = 0; len = 0; @@ -173,7 +173,7 @@ unsigned int calc_clat_percentiles(unsigned int *io_u_plat, unsigned long nr, if (j == oval_len) { oval_len += 100; - ovals = realloc(ovals, oval_len * sizeof(unsigned int)); + ovals = realloc(ovals, oval_len * sizeof(*ovals)); } ovals[j] = plat_idx_to_val(i); @@ -201,9 +201,10 @@ static void show_clat_percentiles(unsigned int *io_u_plat, unsigned long nr, fio_fp64_t *plist, unsigned int precision, struct buf_output *out) { - unsigned int len, j = 0, minv, maxv; - unsigned int *ovals; - int is_last, per_line, scale_down; + unsigned int divisor, len, i, j = 0; + unsigned long long minv, maxv; + unsigned long long *ovals; + int is_last, per_line, scale_down, time_width; char fmt[32]; len = calc_clat_percentiles(io_u_plat, nr, plist, &ovals, &maxv, &minv); @@ -211,23 +212,30 @@ static void show_clat_percentiles(unsigned int *io_u_plat, unsigned long nr, goto out; /* - * We default to usecs, but if the value range is such that we - * should scale down to msecs, do that. + * We default to nsecs, but if the value range is such that we + * should scale down to usecs or msecs, do that. */ - if (minv > 2000 && maxv > 99999) { - scale_down = 1; + if (minv > 2000000 && maxv > 99999999ULL) { + scale_down = 2; + divisor = 1000000; log_buf(out, " clat percentiles (msec):\n |"); + } else if (minv > 2000 && maxv > 99999) { + scale_down = 1; + divisor = 1000; + log_buf(out, " clat percentiles (usec):\n |"); } else { scale_down = 0; - log_buf(out, " clat percentiles (usec):\n |"); + divisor = 1; + log_buf(out, " clat percentiles (nsec):\n |"); } - snprintf(fmt, sizeof(fmt), "%%1.%uf", precision); - per_line = (80 - 7) / (precision + 14); - for (j = 0; j < len; j++) { - char fbuf[16], *ptr = fbuf; + time_width = max(5, (int) (log10(maxv / divisor) + 1)); + snprintf(fmt, sizeof(fmt), " %%%u.%ufth=[%%%dllu]%%c", precision+3, precision, time_width); + // fmt will be something like " %5.2fth=[%4llu]%c" + per_line = (80 - 7) / (precision + 10 + time_width); + for (j = 0; j < len; j++) { /* for formatting */ if (j != 0 && (j % per_line) == 0) log_buf(out, " |"); @@ -235,15 +243,10 @@ static void show_clat_percentiles(unsigned int *io_u_plat, unsigned long nr, /* end of the list */ is_last = (j == len - 1); - if (plist[j].u.f < 10.0) - ptr += sprintf(fbuf, " "); - - snprintf(ptr, sizeof(fbuf), fmt, plist[j].u.f); - - if (scale_down) + for (i = 0; i < scale_down; i++) ovals[j] = (ovals[j] + 999) / 1000; - log_buf(out, " %sth=[%5u]%c", fbuf, ovals[j], is_last ? '\n' : ','); + log_buf(out, fmt, plist[j].u.f, ovals[j], is_last ? '\n' : ','); if (is_last) break; @@ -257,7 +260,7 @@ out: free(ovals); } -bool calc_lat(struct io_stat *is, unsigned long *min, unsigned long *max, +bool calc_lat(struct io_stat *is, unsigned long long *min, unsigned long long *max, double *mean, double *dev) { double n = (double) is->samples; @@ -355,6 +358,11 @@ static void stat_calc_lat(struct thread_stat *ts, double *dst, } } +void stat_calc_lat_n(struct thread_stat *ts, double *io_u_lat) +{ + stat_calc_lat(ts, io_u_lat, ts->io_u_lat_n, FIO_IO_U_LAT_N_NR); +} + void stat_calc_lat_u(struct thread_stat *ts, double *io_u_lat) { stat_calc_lat(ts, io_u_lat, ts->io_u_lat_u, FIO_IO_U_LAT_U_NR); @@ -365,14 +373,16 @@ void stat_calc_lat_m(struct thread_stat *ts, double *io_u_lat) stat_calc_lat(ts, io_u_lat, ts->io_u_lat_m, FIO_IO_U_LAT_M_NR); } -static void display_lat(const char *name, unsigned long min, unsigned long max, +static void display_lat(const char *name, unsigned long long min, unsigned long long max, double mean, double dev, struct buf_output *out) { - const char *base = "(usec)"; + const char *base = "(nsec)"; char *minp, *maxp; - if (usec_to_msec(&min, &max, &mean, &dev)) + if (nsec_to_msec(&min, &max, &mean, &dev)) base = "(msec)"; + else if (nsec_to_usec(&min, &max, &mean, &dev)) + base = "(usec)"; minp = num2str(min, 6, 1, 0, N2S_NONE); maxp = num2str(max, 6, 1, 0, N2S_NONE); @@ -388,8 +398,8 @@ static void show_ddir_status(struct group_run_stats *rs, struct thread_stat *ts, int ddir, struct buf_output *out) { const char *str[] = { " read", "write", " trim" }; - unsigned long min, max, runt; - unsigned long long bw, iops; + unsigned long runt; + unsigned long long min, max, bw, iops; double mean, dev; char *io_p, *bw_p, *bw_p_alt, *iops_p; int i2p; @@ -467,7 +477,7 @@ static void show_ddir_status(struct group_run_stats *rs, struct thread_stat *ts, bw_str = (rs->unit_base == 1 ? "Mibit" : "MiB"); } - log_buf(out, " bw (%5s/s): min=%5lu, max=%5lu, per=%3.2f%%, avg=%5.02f, stdev=%5.02f\n", + log_buf(out, " bw (%5s/s): min=%5llu, max=%5llu, per=%3.2f%%, avg=%5.02f, stdev=%5.02f\n", bw_str, min, max, p_of_agg, mean, dev); } } @@ -502,6 +512,14 @@ static int show_lat(double *io_u_lat, int nr, const char **ranges, return shown; } +static void show_lat_n(double *io_u_lat_n, struct buf_output *out) +{ + const char *ranges[] = { "2=", "4=", "10=", "20=", "50=", "100=", + "250=", "500=", "750=", "1000=", }; + + show_lat(io_u_lat_n, FIO_IO_U_LAT_N_NR, ranges, "nsec", out); +} + static void show_lat_u(double *io_u_lat_u, struct buf_output *out) { const char *ranges[] = { "2=", "4=", "10=", "20=", "50=", "100=", @@ -521,12 +539,15 @@ static void show_lat_m(double *io_u_lat_m, struct buf_output *out) static void show_latencies(struct thread_stat *ts, struct buf_output *out) { + double io_u_lat_n[FIO_IO_U_LAT_N_NR]; double io_u_lat_u[FIO_IO_U_LAT_U_NR]; double io_u_lat_m[FIO_IO_U_LAT_M_NR]; + stat_calc_lat_n(ts, io_u_lat_n); stat_calc_lat_u(ts, io_u_lat_u); stat_calc_lat_m(ts, io_u_lat_m); + show_lat_n(io_u_lat_n, out); show_lat_u(io_u_lat_u, out); show_lat_m(io_u_lat_m, out); } @@ -818,11 +839,10 @@ static void show_ddir_status_terse(struct thread_stat *ts, struct group_run_stats *rs, int ddir, struct buf_output *out) { - unsigned long min, max; - unsigned long long bw, iops; - unsigned int *ovals = NULL; + unsigned long long min, max, minv, maxv, bw, iops; + unsigned long long *ovals = NULL; double mean, dev; - unsigned int len, minv, maxv; + unsigned int len; int i; assert(ddir_rw(ddir)); @@ -840,14 +860,14 @@ static void show_ddir_status_terse(struct thread_stat *ts, (unsigned long long) ts->runtime[ddir]); if (calc_lat(&ts->slat_stat[ddir], &min, &max, &mean, &dev)) - log_buf(out, ";%lu;%lu;%f;%f", min, max, mean, dev); + log_buf(out, ";%llu;%llu;%f;%f", min, max, mean, dev); else - log_buf(out, ";%lu;%lu;%f;%f", 0UL, 0UL, 0.0, 0.0); + log_buf(out, ";%llu;%llu;%f;%f", 0ULL, 0ULL, 0.0, 0.0); if (calc_lat(&ts->clat_stat[ddir], &min, &max, &mean, &dev)) - log_buf(out, ";%lu;%lu;%f;%f", min, max, mean, dev); + log_buf(out, ";%llu;%llu;%f;%f", min, max, mean, dev); else - log_buf(out, ";%lu;%lu;%f;%f", 0UL, 0UL, 0.0, 0.0); + log_buf(out, ";%llu;%llu;%f;%f", 0ULL, 0ULL, 0.0, 0.0); if (ts->clat_percentiles) { len = calc_clat_percentiles(ts->io_u_plat[ddir], @@ -862,13 +882,13 @@ static void show_ddir_status_terse(struct thread_stat *ts, log_buf(out, ";0%%=0"); continue; } - log_buf(out, ";%f%%=%u", ts->percentile_list[i].u.f, ovals[i]); + log_buf(out, ";%f%%=%llu", ts->percentile_list[i].u.f, ovals[i]); } if (calc_lat(&ts->lat_stat[ddir], &min, &max, &mean, &dev)) - log_buf(out, ";%lu;%lu;%f;%f", min, max, mean, dev); + log_buf(out, ";%llu;%llu;%f;%f", min, max, mean, dev); else - log_buf(out, ";%lu;%lu;%f;%f", 0UL, 0UL, 0.0, 0.0); + log_buf(out, ";%llu;%llu;%f;%f", 0ULL, 0ULL, 0.0, 0.0); if (ovals) free(ovals); @@ -882,19 +902,19 @@ static void show_ddir_status_terse(struct thread_stat *ts, p_of_agg = 100.0; } - log_buf(out, ";%lu;%lu;%f%%;%f;%f", min, max, p_of_agg, mean, dev); + log_buf(out, ";%llu;%llu;%f%%;%f;%f", min, max, p_of_agg, mean, dev); } else - log_buf(out, ";%lu;%lu;%f%%;%f;%f", 0UL, 0UL, 0.0, 0.0, 0.0); + log_buf(out, ";%llu;%llu;%f%%;%f;%f", 0ULL, 0ULL, 0.0, 0.0, 0.0); } static void add_ddir_status_json(struct thread_stat *ts, struct group_run_stats *rs, int ddir, struct json_object *parent) { - unsigned long min, max; + unsigned long long min, max, minv, maxv; unsigned long long bw; - unsigned int *ovals = NULL; + unsigned long long *ovals = NULL; double mean, dev, iops; - unsigned int len, minv, maxv; + unsigned int len; int i; const char *ddirname[] = {"read", "write", "trim"}; struct json_object *dir_object, *tmp_object, *percentile_object, *clat_bins_object; @@ -933,7 +953,7 @@ static void add_ddir_status_json(struct thread_stat *ts, mean = dev = 0.0; } tmp_object = json_create_object(); - json_object_add_value_object(dir_object, "slat", tmp_object); + json_object_add_value_object(dir_object, "slat_ns", tmp_object); json_object_add_value_int(tmp_object, "min", min); json_object_add_value_int(tmp_object, "max", max); json_object_add_value_float(tmp_object, "mean", mean); @@ -944,7 +964,7 @@ static void add_ddir_status_json(struct thread_stat *ts, mean = dev = 0.0; } tmp_object = json_create_object(); - json_object_add_value_object(dir_object, "clat", tmp_object); + json_object_add_value_object(dir_object, "clat_ns", tmp_object); json_object_add_value_int(tmp_object, "min", min); json_object_add_value_int(tmp_object, "max", max); json_object_add_value_float(tmp_object, "mean", mean); @@ -985,7 +1005,7 @@ static void add_ddir_status_json(struct thread_stat *ts, mean = dev = 0.0; } tmp_object = json_create_object(); - json_object_add_value_object(dir_object, "lat", tmp_object); + json_object_add_value_object(dir_object, "lat_ns", tmp_object); json_object_add_value_int(tmp_object, "min", min); json_object_add_value_int(tmp_object, "max", max); json_object_add_value_float(tmp_object, "mean", mean); @@ -1173,6 +1193,7 @@ static struct json_object *show_thread_status_json(struct thread_stat *ts, struct json_object *root, *tmp; struct jobs_eta *je; double io_u_dist[FIO_IO_U_MAP_NR]; + double io_u_lat_n[FIO_IO_U_LAT_N_NR]; double io_u_lat_u[FIO_IO_U_LAT_U_NR]; double io_u_lat_m[FIO_IO_U_LAT_M_NR]; double usr_cpu, sys_cpu; @@ -1217,6 +1238,7 @@ static struct json_object *show_thread_status_json(struct thread_stat *ts, /* Calc % distribution of IO depths, usecond, msecond latency */ stat_calc_dist(ts->io_u_map, ddir_rw_sum(ts->total_io_u), io_u_dist); + stat_calc_lat_n(ts, io_u_lat_n); stat_calc_lat_u(ts, io_u_lat_u); stat_calc_lat_m(ts, io_u_lat_m); @@ -1232,9 +1254,17 @@ static struct json_object *show_thread_status_json(struct thread_stat *ts, json_object_add_value_float(tmp, (const char *)name, io_u_dist[i]); } + /* Nanosecond latency */ tmp = json_create_object(); - json_object_add_value_object(root, "latency_us", tmp); + json_object_add_value_object(root, "latency_ns", tmp); + for (i = 0; i < FIO_IO_U_LAT_N_NR; i++) { + const char *ranges[] = { "2", "4", "10", "20", "50", "100", + "250", "500", "750", "1000", }; + json_object_add_value_float(tmp, ranges[i], io_u_lat_n[i]); + } /* Microsecond latency */ + tmp = json_create_object(); + json_object_add_value_object(root, "latency_us", tmp); for (i = 0; i < FIO_IO_U_LAT_U_NR; i++) { const char *ranges[] = { "2", "4", "10", "20", "50", "100", "250", "500", "750", "1000", }; @@ -1494,6 +1524,8 @@ void sum_thread_stats(struct thread_stat *dst, struct thread_stat *src, dst->io_u_submit[k] += src->io_u_submit[k]; for (k = 0; k < FIO_IO_U_MAP_NR; k++) dst->io_u_complete[k] += src->io_u_complete[k]; + for (k = 0; k < FIO_IO_U_LAT_N_NR; k++) + dst->io_u_lat_n[k] += src->io_u_lat_n[k]; for (k = 0; k < FIO_IO_U_LAT_U_NR; k++) dst->io_u_lat_u[k] += src->io_u_lat_u[k]; for (k = 0; k < FIO_IO_U_LAT_M_NR; k++) @@ -1955,7 +1987,7 @@ void check_for_running_stats(void) } } -static inline void add_stat_sample(struct io_stat *is, unsigned long data) +static inline void add_stat_sample(struct io_stat *is, unsigned long long data) { double val = data; double delta; @@ -2188,6 +2220,8 @@ void reset_io_stats(struct thread_data *td) ts->io_u_complete[i] = 0; } + for (i = 0; i < FIO_IO_U_LAT_N_NR; i++) + ts->io_u_lat_n[i] = 0; for (i = 0; i < FIO_IO_U_LAT_U_NR; i++) ts->io_u_lat_u[i] = 0; for (i = 0; i < FIO_IO_U_LAT_M_NR; i++) @@ -2303,16 +2337,16 @@ void add_agg_sample(union io_sample_data data, enum fio_ddir ddir, unsigned int } static void add_clat_percentile_sample(struct thread_stat *ts, - unsigned long usec, enum fio_ddir ddir) + unsigned long long nsec, enum fio_ddir ddir) { - unsigned int idx = plat_val_to_idx(usec); + unsigned int idx = plat_val_to_idx(nsec); assert(idx < FIO_IO_U_PLAT_NR); ts->io_u_plat[ddir][idx]++; } void add_clat_sample(struct thread_data *td, enum fio_ddir ddir, - unsigned long usec, unsigned int bs, uint64_t offset) + unsigned long long nsec, unsigned int bs, uint64_t offset) { unsigned long elapsed, this_window; struct thread_stat *ts = &td->ts; @@ -2320,14 +2354,14 @@ void add_clat_sample(struct thread_data *td, enum fio_ddir ddir, td_io_u_lock(td); - add_stat_sample(&ts->clat_stat[ddir], usec); + add_stat_sample(&ts->clat_stat[ddir], nsec); if (td->clat_log) - add_log_sample(td, td->clat_log, sample_val(usec), ddir, bs, + add_log_sample(td, td->clat_log, sample_val(nsec), ddir, bs, offset); if (ts->clat_percentiles) - add_clat_percentile_sample(ts, usec, ddir); + add_clat_percentile_sample(ts, nsec, ddir); if (iolog && iolog->hist_msec) { struct io_hist *hw = &iolog->hist_window[ddir]; @@ -2389,7 +2423,7 @@ void add_slat_sample(struct thread_data *td, enum fio_ddir ddir, } void add_lat_sample(struct thread_data *td, enum fio_ddir ddir, - unsigned long usec, unsigned int bs, uint64_t offset) + unsigned long long nsec, unsigned int bs, uint64_t offset) { struct thread_stat *ts = &td->ts; @@ -2398,23 +2432,23 @@ void add_lat_sample(struct thread_data *td, enum fio_ddir ddir, td_io_u_lock(td); - add_stat_sample(&ts->lat_stat[ddir], usec); + add_stat_sample(&ts->lat_stat[ddir], nsec); if (td->lat_log) - add_log_sample(td, td->lat_log, sample_val(usec), ddir, bs, + add_log_sample(td, td->lat_log, sample_val(nsec), ddir, bs, offset); td_io_u_unlock(td); } void add_bw_sample(struct thread_data *td, struct io_u *io_u, - unsigned int bytes, unsigned long spent) + unsigned int bytes, unsigned long long spent) { struct thread_stat *ts = &td->ts; unsigned long rate; if (spent) - rate = bytes * 1000 / spent; + rate = (unsigned long) (bytes * 1000000ULL / spent); else rate = 0; diff --git a/stat.h b/stat.h index d8a08034..ea45c00c 100644 --- a/stat.h +++ b/stat.h @@ -19,6 +19,7 @@ struct group_run_stats { * How many depth levels to log */ #define FIO_IO_U_MAP_NR 7 +#define FIO_IO_U_LAT_N_NR 10 #define FIO_IO_U_LAT_U_NR 10 #define FIO_IO_U_LAT_M_NR 12 @@ -108,7 +109,7 @@ struct group_run_stats { #define FIO_IO_U_PLAT_BITS 6 #define FIO_IO_U_PLAT_VAL (1 << FIO_IO_U_PLAT_BITS) -#define FIO_IO_U_PLAT_GROUP_NR 19 +#define FIO_IO_U_PLAT_GROUP_NR 29 #define FIO_IO_U_PLAT_NR (FIO_IO_U_PLAT_GROUP_NR * FIO_IO_U_PLAT_VAL) #define FIO_IO_U_LIST_MAX_LEN 20 /* The size of the default and user-specified list of percentiles */ @@ -178,6 +179,7 @@ struct thread_stat { uint32_t io_u_map[FIO_IO_U_MAP_NR]; uint32_t io_u_submit[FIO_IO_U_MAP_NR]; uint32_t io_u_complete[FIO_IO_U_MAP_NR]; + uint32_t io_u_lat_n[FIO_IO_U_LAT_N_NR]; uint32_t io_u_lat_u[FIO_IO_U_LAT_U_NR]; uint32_t io_u_lat_m[FIO_IO_U_LAT_M_NR]; uint32_t io_u_plat[DDIR_RWDIR_CNT][FIO_IO_U_PLAT_NR]; @@ -286,8 +288,8 @@ extern void sum_group_stats(struct group_run_stats *dst, struct group_run_stats extern void init_thread_stat(struct thread_stat *ts); extern void init_group_run_stat(struct group_run_stats *gs); extern void eta_to_str(char *str, unsigned long eta_sec); -extern bool calc_lat(struct io_stat *is, unsigned long *min, unsigned long *max, double *mean, double *dev); -extern unsigned int calc_clat_percentiles(unsigned int *io_u_plat, unsigned long nr, fio_fp64_t *plist, unsigned int **output, unsigned int *maxv, unsigned int *minv); +extern bool calc_lat(struct io_stat *is, unsigned long long *min, unsigned long long *max, double *mean, double *dev); +extern unsigned int calc_clat_percentiles(unsigned int *io_u_plat, unsigned long nr, fio_fp64_t *plist, unsigned long long **output, unsigned long long *maxv, unsigned long long *minv); extern void stat_calc_lat_m(struct thread_stat *ts, double *io_u_lat); extern void stat_calc_lat_u(struct thread_stat *ts, double *io_u_lat); extern void stat_calc_dist(unsigned int *map, unsigned long total, double *io_u_dist); @@ -295,9 +297,9 @@ extern void reset_io_stats(struct thread_data *); extern void update_rusage_stat(struct thread_data *); extern void clear_rusage_stat(struct thread_data *); -extern void add_lat_sample(struct thread_data *, enum fio_ddir, unsigned long, +extern void add_lat_sample(struct thread_data *, enum fio_ddir, unsigned long long, unsigned int, uint64_t); -extern void add_clat_sample(struct thread_data *, enum fio_ddir, unsigned long, +extern void add_clat_sample(struct thread_data *, enum fio_ddir, unsigned long long, unsigned int, uint64_t); extern void add_slat_sample(struct thread_data *, enum fio_ddir, unsigned long, unsigned int, uint64_t); @@ -305,16 +307,16 @@ extern void add_agg_sample(union io_sample_data, enum fio_ddir, unsigned int); extern void add_iops_sample(struct thread_data *, struct io_u *, unsigned int); extern void add_bw_sample(struct thread_data *, struct io_u *, - unsigned int, unsigned long); + unsigned int, unsigned long long); extern int calc_log_samples(void); extern struct io_log *agg_io_log[DDIR_RWDIR_CNT]; extern int write_bw_log; -static inline bool usec_to_msec(unsigned long *min, unsigned long *max, +static inline bool nsec_to_usec(unsigned long long *min, unsigned long long *max, double *mean, double *dev) { - if (*min > 1000 && *max > 1000 && *mean > 1000.0 && *dev > 1000.0) { + if (*min > 2000 && *max > 99999 && *dev > 1000.0) { *min /= 1000; *max /= 1000; *mean /= 1000.0; @@ -324,6 +326,20 @@ static inline bool usec_to_msec(unsigned long *min, unsigned long *max, return false; } + +static inline bool nsec_to_msec(unsigned long long *min, unsigned long long *max, + double *mean, double *dev) +{ + if (*min > 2000000 && *max > 99999999ULL && *dev > 1000000.0) { + *min /= 1000000; + *max /= 1000000; + *mean /= 1000000.0; + *dev /= 1000000.0; + return true; + } + + return false; +} /* * Worst level condensing would be 1:5, so allow enough room for that */ -- 2.25.1