nanosecond: update completion latency recording and normal, json output to use nanose...

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

diff --git a/client.c b/client.c
index 42ccbef0e42271196e1acabffe1c9ed2cc32909c..81119c2eee19a298efc1b9d62d21678500f019fd 100644 (file)
--- 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 3a5848e7a1da06c5260db3c35d8e08c68ce560a0..f4eac793f4fb3311dbd77069fc5a392477f33fef 100644 (file)
--- 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 a4ee20df73b122c9a63cf7cd243e98e5186c1180..6ced2f1d7f3fdebf17a834dc9c3cec6c1b2d2e33 100644 (file)
--- 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 51d6e9583556efd33a5fd77569171e718196e31d..375413f4b6d230e38432484179327736ae2de060 100644 (file)
--- 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 017ab130f57d08e562a9cb2a4b495f499f8b6784..b0a6e876a465c6cd82582ede3f45a525aeba3c69 100644 (file)
--- 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 6ffcad930a3cb11b64b272a14528c31a44ea2bdc..28acf103c7ef02d3951f932eacb6ce18a11504a8 100644 (file)
--- 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 d8a08034a5faf94c5097ad1f33623fed86a08ddb..ea45c00c2857c4479843d9ab66b0ce6d2508bd1a 100644 (file)
--- 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
  */