stat: correct json 'io_bytes' output
[fio.git] / stat.c
diff --git a/stat.c b/stat.c
index 3e57e544e1e421a3f4fd350b5b55d303371a46ce..fd3ad5aa248b2caf6e78c08e8ed330ac2cdf0eb3 100644 (file)
--- a/stat.c
+++ b/stat.c
@@ -98,7 +98,7 @@ static unsigned int plat_val_to_idx(unsigned int val)
  * Convert the given index of the bucket array to the value
  * represented by the bucket
  */
-static unsigned int plat_idx_to_val(unsigned int idx)
+static unsigned long long plat_idx_to_val(unsigned int idx)
 {
        unsigned int error_bits, k, base;
 
@@ -279,7 +279,8 @@ bool calc_lat(struct io_stat *is, unsigned long *min, unsigned long *max,
 
 void show_group_stats(struct group_run_stats *rs, struct buf_output *out)
 {
-       char *p1, *p2, *p3, *p4;
+       char *io, *agg, *min, *max;
+       char *ioalt, *aggalt, *minalt, *maxalt;
        const char *str[] = { "   READ", "  WRITE" , "   TRIM"};
        int i;
 
@@ -291,22 +292,28 @@ void show_group_stats(struct group_run_stats *rs, struct buf_output *out)
                if (!rs->max_run[i])
                        continue;
 
-               p1 = num2str(rs->io_kb[i], 6, rs->kb_base, i2p, 8);
-               p2 = num2str(rs->agg[i], 6, rs->kb_base, i2p, rs->unit_base);
-               p3 = num2str(rs->min_bw[i], 6, rs->kb_base, i2p, rs->unit_base);
-               p4 = num2str(rs->max_bw[i], 6, rs->kb_base, i2p, rs->unit_base);
-
-               log_buf(out, "%s: io=%s, aggrb=%s/s, minb=%s/s, maxb=%s/s,"
-                        " mint=%llumsec, maxt=%llumsec\n",
+               io = num2str(rs->iobytes[i], 4, 1, i2p, N2S_BYTE);
+               ioalt = num2str(rs->iobytes[i], 4, 1, !i2p, N2S_BYTE);
+               agg = num2str(rs->agg[i], 4, 1, i2p, rs->unit_base);
+               aggalt = num2str(rs->agg[i], 4, 1, !i2p, rs->unit_base);
+               min = num2str(rs->min_bw[i], 4, 1, i2p, rs->unit_base);
+               minalt = num2str(rs->min_bw[i], 4, 1, !i2p, rs->unit_base);
+               max = num2str(rs->max_bw[i], 4, 1, i2p, rs->unit_base);
+               maxalt = num2str(rs->max_bw[i], 4, 1, !i2p, rs->unit_base);
+               log_buf(out, "%s: bw=%s (%s), %s-%s (%s-%s), io=%s (%s), run=%llu-%llumsec\n",
                                rs->unified_rw_rep ? "  MIXED" : str[i],
-                               p1, p2, p3, p4,
+                               agg, aggalt, min, max, minalt, maxalt, io, ioalt,
                                (unsigned long long) rs->min_run[i],
                                (unsigned long long) rs->max_run[i]);
 
-               free(p1);
-               free(p2);
-               free(p3);
-               free(p4);
+               free(io);
+               free(agg);
+               free(min);
+               free(max);
+               free(ioalt);
+               free(aggalt);
+               free(minalt);
+               free(maxalt);
        }
 }
 
@@ -367,8 +374,8 @@ static void display_lat(const char *name, unsigned long min, unsigned long max,
        if (usec_to_msec(&min, &max, &mean, &dev))
                base = "(msec)";
 
-       minp = num2str(min, 6, 1, 0, 0);
-       maxp = num2str(max, 6, 1, 0, 0);
+       minp = num2str(min, 6, 1, 0, N2S_NONE);
+       maxp = num2str(max, 6, 1, 0, N2S_NONE);
 
        log_buf(out, "    %s %s: min=%s, max=%s, avg=%5.02f,"
                 " stdev=%5.02f\n", name, base, minp, maxp, mean, dev);
@@ -380,11 +387,11 @@ static void display_lat(const char *name, unsigned long min, unsigned long max,
 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" };
+       const char *str[] = { " read", "write", " trim" };
        unsigned long min, max, runt;
        unsigned long long bw, iops;
        double mean, dev;
-       char *io_p, *bw_p, *iops_p;
+       char *io_p, *bw_p, *bw_p_alt, *iops_p;
        int i2p;
 
        assert(ddir_rw(ddir));
@@ -396,19 +403,21 @@ static void show_ddir_status(struct group_run_stats *rs, struct thread_stat *ts,
        runt = ts->runtime[ddir];
 
        bw = (1000 * ts->io_bytes[ddir]) / runt;
-       io_p = num2str(ts->io_bytes[ddir], 6, 1, i2p, 8);
-       bw_p = num2str(bw, 6, 1, i2p, ts->unit_base);
+       io_p = num2str(ts->io_bytes[ddir], 4, 1, i2p, N2S_BYTE);
+       bw_p = num2str(bw, 4, 1, i2p, ts->unit_base);
+       bw_p_alt = num2str(bw, 4, 1, !i2p, ts->unit_base);
 
        iops = (1000 * (uint64_t)ts->total_io_u[ddir]) / runt;
-       iops_p = num2str(iops, 6, 1, 0, 0);
+       iops_p = num2str(iops, 4, 1, 0, N2S_NONE);
 
-       log_buf(out, "  %s: io=%s, bw=%s/s, iops=%s, runt=%6llumsec\n",
-                               rs->unified_rw_rep ? "mixed" : str[ddir],
-                               io_p, bw_p, iops_p,
-                               (unsigned long long) ts->runtime[ddir]);
+       log_buf(out, "  %s: IOPS=%s, BW=%s (%s)(%s/%llumsec)\n",
+                       rs->unified_rw_rep ? "mixed" : str[ddir],
+                       iops_p, bw_p, bw_p_alt, io_p,
+                       (unsigned long long) ts->runtime[ddir]);
 
        free(io_p);
        free(bw_p);
+       free(bw_p_alt);
        free(iops_p);
 
        if (calc_lat(&ts->slat_stat[ddir], &min, &max, &mean, &dev))
@@ -426,7 +435,16 @@ static void show_ddir_status(struct group_run_stats *rs, struct thread_stat *ts,
        }
        if (calc_lat(&ts->bw_stat[ddir], &min, &max, &mean, &dev)) {
                double p_of_agg = 100.0, fkb_base = (double)rs->kb_base;
-               const char *bw_str = (rs->unit_base == 1 ? "Kbit" : "KB");
+               const char *bw_str;
+
+               if ((rs->unit_base == 1) && i2p)
+                       bw_str = "Kibit";
+               else if (rs->unit_base == 1)
+                       bw_str = "kbit";
+               else if (i2p)
+                       bw_str = "KiB";
+               else
+                       bw_str = "kB";
 
                if (rs->unit_base == 1) {
                        min *= 8.0;
@@ -446,12 +464,11 @@ static void show_ddir_status(struct group_run_stats *rs, struct thread_stat *ts,
                        max /= fkb_base;
                        mean /= fkb_base;
                        dev /= fkb_base;
-                       bw_str = (rs->unit_base == 1 ? "Mbit" : "MB");
+                       bw_str = (rs->unit_base == 1 ? "Mibit" : "MiB");
                }
 
-               log_buf(out, "    bw (%-4s/s): min=%5lu, max=%5lu, per=%3.2f%%,"
-                        " avg=%5.02f, stdev=%5.02f\n", bw_str, min, max,
-                                                       p_of_agg, mean, dev);
+               log_buf(out, "   bw (%5s/s): min=%5lu, max=%5lu, per=%3.2f%%, avg=%5.02f, stdev=%5.02f\n",
+                       bw_str, min, max, p_of_agg, mean, dev);
        }
 }
 
@@ -659,7 +676,7 @@ static void show_block_infos(int nr_block_infos, uint32_t *block_infos,
 
 static void show_ss_normal(struct thread_stat *ts, struct buf_output *out)
 {
-       char *p1, *p2;
+       char *p1, *p1alt, *p2;
        unsigned long long bw_mean, iops_mean;
        const int i2p = is_power_of_2(ts->kb_base);
 
@@ -669,18 +686,20 @@ static void show_ss_normal(struct thread_stat *ts, struct buf_output *out)
        bw_mean = steadystate_bw_mean(ts);
        iops_mean = steadystate_iops_mean(ts);
 
-       p1 = num2str(bw_mean / ts->kb_base, 6, ts->kb_base, i2p, ts->unit_base);
-       p2 = num2str(iops_mean, 6, 1, 0, 0);
+       p1 = num2str(bw_mean / ts->kb_base, 4, ts->kb_base, i2p, ts->unit_base);
+       p1alt = num2str(bw_mean / ts->kb_base, 4, ts->kb_base, !i2p, ts->unit_base);
+       p2 = num2str(iops_mean, 4, 1, 0, N2S_NONE);
 
-       log_buf(out, "  steadystate  : attained=%s, bw=%s/s, iops=%s, %s%s=%.3f%s\n",
+       log_buf(out, "  steadystate  : attained=%s, bw=%s (%s), iops=%s, %s%s=%.3f%s\n",
                ts->ss_state & __FIO_SS_ATTAINED ? "yes" : "no",
-               p1, p2,
+               p1, p1alt, p2,
                ts->ss_state & __FIO_SS_IOPS ? "iops" : "bw",
                ts->ss_state & __FIO_SS_SLOPE ? " slope": " mean dev",
                ts->ss_criterion.u.f,
                ts->ss_state & __FIO_SS_PCT ? "%" : "");
 
        free(p1);
+       free(p1alt);
        free(p2);
 }
 
@@ -761,9 +780,9 @@ static void show_thread_status_normal(struct thread_stat *ts,
                                        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_buf(out, "     issued    : total=r=%llu/w=%llu/d=%llu,"
-                                " short=r=%llu/w=%llu/d=%llu,"
-                                " drop=r=%llu/w=%llu/d=%llu\n",
+       log_buf(out, "     issued rwt: total=%llu,%llu,%llu,"
+                                " short=%llu,%llu,%llu,"
+                                " dropped=%llu,%llu,%llu\n",
                                        (unsigned long long) ts->total_io_u[0],
                                        (unsigned long long) ts->total_io_u[1],
                                        (unsigned long long) ts->total_io_u[2],
@@ -812,7 +831,7 @@ static void show_ddir_status_terse(struct thread_stat *ts,
        if (ts->runtime[ddir]) {
                uint64_t runt = ts->runtime[ddir];
 
-               bw = ((1000 * ts->io_bytes[ddir]) / runt) / 1024;
+               bw = ((1000 * ts->io_bytes[ddir]) / runt) / 1024; /* KiB/s */
                iops = (1000 * (uint64_t) ts->total_io_u[ddir]) / runt;
        }
 
@@ -896,11 +915,12 @@ static void add_ddir_status_json(struct thread_stat *ts,
        if (ts->runtime[ddir]) {
                uint64_t runt = ts->runtime[ddir];
 
-               bw = ((1000 * ts->io_bytes[ddir]) / runt) / 1024;
+               bw = ((1000 * ts->io_bytes[ddir]) / runt) / 1024; /* KiB/s */
                iops = (1000.0 * (uint64_t) ts->total_io_u[ddir]) / runt;
        }
 
-       json_object_add_value_int(dir_object, "io_bytes", ts->io_bytes[ddir] >> 10);
+       json_object_add_value_int(dir_object, "io_bytes", ts->io_bytes[ddir]);
+       json_object_add_value_int(dir_object, "io_kbytes", ts->io_bytes[ddir] >> 10);
        json_object_add_value_int(dir_object, "bw", bw);
        json_object_add_value_float(dir_object, "iops", iops);
        json_object_add_value_int(dir_object, "runtime", ts->runtime[ddir]);
@@ -953,12 +973,11 @@ static void add_ddir_status_json(struct thread_stat *ts,
                clat_bins_object = json_create_object();
                json_object_add_value_object(tmp_object, "bins", clat_bins_object);
                for(i = 0; i < FIO_IO_U_PLAT_NR; i++) {
-                       snprintf(buf, sizeof(buf), "%d", i);
-                       json_object_add_value_int(clat_bins_object, (const char *)buf, ts->io_u_plat[ddir][i]);
+                       if (ts->io_u_plat[ddir][i]) {
+                               snprintf(buf, sizeof(buf), "%llu", plat_idx_to_val(i));
+                               json_object_add_value_int(clat_bins_object, (const char *)buf, ts->io_u_plat[ddir][i]);
+                       }
                }
-               json_object_add_value_int(clat_bins_object, "FIO_IO_U_PLAT_BITS", FIO_IO_U_PLAT_BITS);
-               json_object_add_value_int(clat_bins_object, "FIO_IO_U_PLAT_VAL", FIO_IO_U_PLAT_VAL);
-               json_object_add_value_int(clat_bins_object, "FIO_IO_U_PLAT_NR", FIO_IO_U_PLAT_NR);
        }
 
        if (!calc_lat(&ts->lat_stat[ddir], &min, &max, &mean, &dev)) {
@@ -1418,7 +1437,7 @@ void sum_group_stats(struct group_run_stats *dst, struct group_run_stats *src)
                if (dst->min_bw[i] && dst->min_bw[i] > src->min_bw[i])
                        dst->min_bw[i] = src->min_bw[i];
 
-               dst->io_kb[i] += src->io_kb[i];
+               dst->iobytes[i] += src->iobytes[i];
                dst->agg[i] += src->agg[i];
        }
 
@@ -1563,6 +1582,8 @@ void __show_run_stats(void)
                }
                if (last_ts == td->groupid)
                        continue;
+               if (!td->o.stats)
+                       continue;
 
                last_ts = td->groupid;
                nr_ts++;
@@ -1580,6 +1601,8 @@ void __show_run_stats(void)
        last_ts = -1;
        idx = 0;
        for_each_td(td, i) {
+               if (!td->o.stats)
+                       continue;
                if (idx && (!td->o.group_reporting ||
                    (td->o.group_reporting && last_ts != td->groupid))) {
                        idx = 0;
@@ -1696,19 +1719,14 @@ void __show_run_stats(void)
                                rs->max_run[j] = ts->runtime[j];
 
                        bw = 0;
-                       if (ts->runtime[j]) {
-                               unsigned long runt = ts->runtime[j];
-                               unsigned long long kb;
-
-                               kb = ts->io_bytes[j] / rs->kb_base;
-                               bw = kb * 1000 / runt;
-                       }
+                       if (ts->runtime[j])
+                               bw = ts->io_bytes[j] * 1000 / ts->runtime[j];
                        if (bw < rs->min_bw[j])
                                rs->min_bw[j] = bw;
                        if (bw > rs->max_bw[j])
                                rs->max_bw[j] = bw;
 
-                       rs->io_kb[j] += ts->io_bytes[j] / rs->kb_base;
+                       rs->iobytes[j] += ts->io_bytes[j];
                }
        }
 
@@ -1719,7 +1737,7 @@ void __show_run_stats(void)
 
                for (ddir = 0; ddir < DDIR_RWDIR_CNT; ddir++) {
                        if (rs->max_run[ddir])
-                               rs->agg[ddir] = (rs->io_kb[ddir] * 1000) /
+                               rs->agg[ddir] = (rs->iobytes[ddir] * 1000) /
                                                rs->max_run[ddir];
                }
        }
@@ -1808,8 +1826,10 @@ void __show_run_stats(void)
        }
 
        for (i = 0; i < FIO_OUTPUT_NR; i++) {
-               buf_output_flush(&output[i]);
-               buf_output_free(&output[i]);
+               struct buf_output *out = &output[i];
+
+               log_info_buf(out->buf, out->buflen);
+               buf_output_free(out);
        }
 
        log_info_flush();
@@ -2154,6 +2174,9 @@ void reset_io_stats(struct thread_data *td)
 
                ts->io_bytes[i] = 0;
                ts->runtime[i] = 0;
+               ts->total_io_u[i] = 0;
+               ts->short_io_u[i] = 0;
+               ts->drop_io_u[i] = 0;
 
                for (j = 0; j < FIO_IO_U_PLAT_NR; j++)
                        ts->io_u_plat[i][j] = 0;
@@ -2163,17 +2186,15 @@ void reset_io_stats(struct thread_data *td)
                ts->io_u_map[i] = 0;
                ts->io_u_submit[i] = 0;
                ts->io_u_complete[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++)
                ts->io_u_lat_m[i] = 0;
-               ts->total_submit = 0;
-               ts->total_complete = 0;
-       }
 
-       for (i = 0; i < 3; i++) {
-               ts->total_io_u[i] = 0;
-               ts->short_io_u[i] = 0;
-               ts->drop_io_u[i] = 0;
-       }
+       ts->total_submit = 0;
+       ts->total_complete = 0;
 }
 
 static void __add_stat_to_log(struct io_log *iolog, enum fio_ddir ddir,
@@ -2409,64 +2430,76 @@ void add_bw_sample(struct thread_data *td, struct io_u *io_u,
        td_io_u_unlock(td);
 }
 
-static int add_bw_samples(struct thread_data *td, struct timeval *t)
+static int __add_samples(struct thread_data *td, struct timeval *parent_tv,
+                        struct timeval *t, unsigned int avg_time,
+                        uint64_t *this_io_bytes, uint64_t *stat_io_bytes,
+                        struct io_stat *stat, struct io_log *log,
+                        bool is_kb)
 {
-       struct thread_stat *ts = &td->ts;
        unsigned long spent, rate;
        enum fio_ddir ddir;
        unsigned int next, next_log;
 
-       next_log = td->o.bw_avg_time;
+       next_log = avg_time;
 
-       spent = mtime_since(&td->bw_sample_time, t);
-       if (spent < td->o.bw_avg_time &&
-           td->o.bw_avg_time - spent >= LOG_MSEC_SLACK)
-               return td->o.bw_avg_time - spent;
+       spent = mtime_since(parent_tv, t);
+       if (spent < avg_time && avg_time - spent >= LOG_MSEC_SLACK)
+               return avg_time - spent;
 
        td_io_u_lock(td);
 
        /*
         * Compute both read and write rates for the interval.
         */
-       for (ddir = DDIR_READ; ddir < DDIR_RWDIR_CNT; ddir++) {
+       for (ddir = 0; ddir < DDIR_RWDIR_CNT; ddir++) {
                uint64_t delta;
 
-               delta = td->this_io_bytes[ddir] - td->stat_io_bytes[ddir];
+               delta = this_io_bytes[ddir] - stat_io_bytes[ddir];
                if (!delta)
                        continue; /* No entries for interval */
 
-               if (spent)
-                       rate = delta * 1000 / spent / 1024;
-               else
+               if (spent) {
+                       if (is_kb)
+                               rate = delta * 1000 / spent / 1024; /* KiB/s */
+                       else
+                               rate = (delta * 1000) / spent;
+               } else
                        rate = 0;
 
-               add_stat_sample(&ts->bw_stat[ddir], rate);
+               add_stat_sample(&stat[ddir], rate);
 
-               if (td->bw_log) {
+               if (log) {
                        unsigned int bs = 0;
 
                        if (td->o.min_bs[ddir] == td->o.max_bs[ddir])
                                bs = td->o.min_bs[ddir];
 
-                       next = add_log_sample(td, td->bw_log, sample_val(rate),
-                                             ddir, bs, 0);
+                       next = add_log_sample(td, log, sample_val(rate), ddir, bs, 0);
                        next_log = min(next_log, next);
                }
 
-               td->stat_io_bytes[ddir] = td->this_io_bytes[ddir];
+               stat_io_bytes[ddir] = this_io_bytes[ddir];
        }
 
-       timeval_add_msec(&td->bw_sample_time, td->o.bw_avg_time);
+       timeval_add_msec(parent_tv, avg_time);
 
        td_io_u_unlock(td);
 
-       if (spent <= td->o.bw_avg_time)
-               return min(next_log, td->o.bw_avg_time);
+       if (spent <= avg_time)
+               next = avg_time;
+       else
+               next = avg_time - (1 + spent - avg_time);
 
-       next = td->o.bw_avg_time - (1 + spent - td->o.bw_avg_time);
        return min(next, next_log);
 }
 
+static int add_bw_samples(struct thread_data *td, struct timeval *t)
+{
+       return __add_samples(td, &td->bw_sample_time, t, td->o.bw_avg_time,
+                               td->this_io_bytes, td->stat_io_bytes,
+                               td->ts.bw_stat, td->bw_log, true);
+}
+
 void add_iops_sample(struct thread_data *td, struct io_u *io_u,
                     unsigned int bytes)
 {
@@ -2486,60 +2519,9 @@ void add_iops_sample(struct thread_data *td, struct io_u *io_u,
 
 static int add_iops_samples(struct thread_data *td, struct timeval *t)
 {
-       struct thread_stat *ts = &td->ts;
-       unsigned long spent, iops;
-       enum fio_ddir ddir;
-       unsigned int next, next_log;
-
-       next_log = td->o.iops_avg_time;
-
-       spent = mtime_since(&td->iops_sample_time, t);
-       if (spent < td->o.iops_avg_time &&
-           td->o.iops_avg_time - spent >= LOG_MSEC_SLACK)
-               return td->o.iops_avg_time - spent;
-
-       td_io_u_lock(td);
-
-       /*
-        * Compute both read and write rates for the interval.
-        */
-       for (ddir = DDIR_READ; ddir < DDIR_RWDIR_CNT; ddir++) {
-               uint64_t delta;
-
-               delta = td->this_io_blocks[ddir] - td->stat_io_blocks[ddir];
-               if (!delta)
-                       continue; /* No entries for interval */
-
-               if (spent)
-                       iops = (delta * 1000) / spent;
-               else
-                       iops = 0;
-
-               add_stat_sample(&ts->iops_stat[ddir], iops);
-
-               if (td->iops_log) {
-                       unsigned int bs = 0;
-
-                       if (td->o.min_bs[ddir] == td->o.max_bs[ddir])
-                               bs = td->o.min_bs[ddir];
-
-                       next = add_log_sample(td, td->iops_log,
-                                             sample_val(iops), ddir, bs, 0);
-                       next_log = min(next_log, next);
-               }
-
-               td->stat_io_blocks[ddir] = td->this_io_blocks[ddir];
-       }
-
-       timeval_add_msec(&td->iops_sample_time, td->o.iops_avg_time);
-
-       td_io_u_unlock(td);
-
-       if (spent <= td->o.iops_avg_time)
-               return min(next_log, td->o.iops_avg_time);
-
-       next = td->o.iops_avg_time - (1 + spent - td->o.iops_avg_time);
-       return min(next, next_log);
+       return __add_samples(td, &td->iops_sample_time, t, td->o.iops_avg_time,
+                               td->this_io_blocks, td->stat_io_blocks,
+                               td->ts.iops_stat, td->iops_log, false);
 }
 
 /*
@@ -2555,17 +2537,21 @@ int calc_log_samples(void)
        fio_gettime(&now, NULL);
 
        for_each_td(td, i) {
+               if (!td->o.stats)
+                       continue;
                if (in_ramp_time(td) ||
                    !(td->runstate == TD_RUNNING || td->runstate == TD_VERIFYING)) {
                        next = min(td->o.iops_avg_time, td->o.bw_avg_time);
                        continue;
                }
-               if (td->bw_log && !per_unit_log(td->bw_log)) {
+               if (!td->bw_log ||
+                       (td->bw_log && !per_unit_log(td->bw_log))) {
                        tmp = add_bw_samples(td, &now);
                        if (tmp < next)
                                next = tmp;
                }
-               if (td->iops_log && !per_unit_log(td->iops_log)) {
+               if (!td->iops_log ||
+                       (td->iops_log && !per_unit_log(td->iops_log))) {
                        tmp = add_iops_samples(td, &now);
                        if (tmp < next)
                                next = tmp;