stat: change json+ output format so that instead of printing the raw clat data struct...
[fio.git] / stat.c
diff --git a/stat.c b/stat.c
index 146090e7f168d232fd055bb1a110229e35c0466a..8770ae28920e5a484cc04ec12579e8b54a777ec5 100644 (file)
--- a/stat.c
+++ b/stat.c
@@ -16,6 +16,9 @@
 #include "lib/pow2.h"
 #include "lib/output_buffer.h"
 #include "helper_thread.h"
+#include "smalloc.h"
+
+#define LOG_MSEC_SLACK 10
 
 struct fio_mutex *stat_mutex;
 
@@ -95,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;
 
@@ -254,13 +257,13 @@ out:
                free(ovals);
 }
 
-int calc_lat(struct io_stat *is, unsigned long *min, unsigned long *max,
-            double *mean, double *dev)
+bool calc_lat(struct io_stat *is, unsigned long *min, unsigned long *max,
+             double *mean, double *dev)
 {
        double n = (double) is->samples;
 
        if (n == 0)
-               return 0;
+               return false;
 
        *min = is->min_val;
        *max = is->max_val;
@@ -271,12 +274,13 @@ int calc_lat(struct io_stat *is, unsigned long *min, unsigned long *max,
        else
                *dev = 0;
 
-       return 1;
+       return true;
 }
 
 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;
 
@@ -288,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);
        }
 }
 
@@ -361,11 +371,11 @@ static void display_lat(const char *name, unsigned long min, unsigned long max,
        const char *base = "(usec)";
        char *minp, *maxp;
 
-       if (!usec_to_msec(&min, &max, &mean, &dev))
+       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);
@@ -377,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));
@@ -393,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))
@@ -423,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;
@@ -443,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);
        }
 }
 
@@ -654,6 +674,35 @@ static void show_block_infos(int nr_block_infos, uint32_t *block_infos,
                         i == BLOCK_STATE_COUNT - 1 ? '\n' : ',');
 }
 
+static void show_ss_normal(struct thread_stat *ts, struct buf_output *out)
+{
+       char *p1, *p1alt, *p2;
+       unsigned long long bw_mean, iops_mean;
+       const int i2p = is_power_of_2(ts->kb_base);
+
+       if (!ts->ss_dur)
+               return;
+
+       bw_mean = steadystate_bw_mean(ts);
+       iops_mean = steadystate_iops_mean(ts);
+
+       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",
+               ts->ss_state & __FIO_SS_ATTAINED ? "yes" : "no",
+               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);
+}
+
 static void show_thread_status_normal(struct thread_stat *ts,
                                      struct group_run_stats *rs,
                                      struct buf_output *out)
@@ -666,6 +715,8 @@ static void show_thread_status_normal(struct thread_stat *ts,
 
        if (!ddir_rw_sum(ts->io_bytes) && !ddir_rw_sum(ts->total_io_u))
                return;
+               
+       memset(time_buf, 0, sizeof(time_buf));
 
        time(&time_p);
        os_ctime_r((const time_t *) &time_p, time_buf, sizeof(time_buf));
@@ -729,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],
@@ -758,6 +809,9 @@ static void show_thread_status_normal(struct thread_stat *ts,
        if (ts->nr_block_infos)
                show_block_infos(ts->nr_block_infos, ts->block_infos,
                                  ts->percentile_list, out);
+
+       if (ts->ss_dur)
+               show_ss_normal(ts, out);
 }
 
 static void show_ddir_status_terse(struct thread_stat *ts,
@@ -777,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;
        }
 
@@ -861,7 +915,7 @@ 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;
        }
 
@@ -918,12 +972,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)) {
@@ -1087,8 +1140,8 @@ static void show_thread_status_terse_v3_v4(struct thread_stat *ts,
        log_buf(out, "\n");
 }
 
-void json_add_job_opts(struct json_object *root, const char *name,
-                      struct flist_head *opt_list, bool num_jobs)
+static void json_add_job_opts(struct json_object *root, const char *name,
+                             struct flist_head *opt_list, bool num_jobs)
 {
        struct json_object *dir_object;
        struct flist_head *entry;
@@ -1252,6 +1305,56 @@ static struct json_object *show_thread_status_json(struct thread_stat *ts,
                }
        }
 
+       if (ts->ss_dur) {
+               struct json_object *data;
+               struct json_array *iops, *bw;
+               int i, j, k;
+               char ss_buf[64];
+
+               snprintf(ss_buf, sizeof(ss_buf), "%s%s:%f%s",
+                       ts->ss_state & __FIO_SS_IOPS ? "iops" : "bw",
+                       ts->ss_state & __FIO_SS_SLOPE ? "_slope" : "",
+                       (float) ts->ss_limit.u.f,
+                       ts->ss_state & __FIO_SS_PCT ? "%" : "");
+
+               tmp = json_create_object();
+               json_object_add_value_object(root, "steadystate", tmp);
+               json_object_add_value_string(tmp, "ss", ss_buf);
+               json_object_add_value_int(tmp, "duration", (int)ts->ss_dur);
+               json_object_add_value_int(tmp, "attained", (ts->ss_state & __FIO_SS_ATTAINED) > 0);
+
+               snprintf(ss_buf, sizeof(ss_buf), "%f%s", (float) ts->ss_criterion.u.f,
+                       ts->ss_state & __FIO_SS_PCT ? "%" : "");
+               json_object_add_value_string(tmp, "criterion", ss_buf);
+               json_object_add_value_float(tmp, "max_deviation", ts->ss_deviation.u.f);
+               json_object_add_value_float(tmp, "slope", ts->ss_slope.u.f);
+
+               data = json_create_object();
+               json_object_add_value_object(tmp, "data", data);
+               bw = json_create_array();
+               iops = json_create_array();
+
+               /*
+               ** if ss was attained or the buffer is not full,
+               ** ss->head points to the first element in the list.
+               ** otherwise it actually points to the second element
+               ** in the list
+               */
+               if ((ts->ss_state & __FIO_SS_ATTAINED) || !(ts->ss_state & __FIO_SS_BUFFER_FULL))
+                       j = ts->ss_head;
+               else
+                       j = ts->ss_head == 0 ? ts->ss_dur - 1 : ts->ss_head - 1;
+               for (i = 0; i < ts->ss_dur; i++) {
+                       k = (j + i) % ts->ss_dur;
+                       json_array_add_value_int(bw, ts->ss_bw_data[k]);
+                       json_array_add_value_int(iops, ts->ss_iops_data[k]);
+               }
+               json_object_add_value_int(data, "bw_mean", steadystate_bw_mean(ts));
+               json_object_add_value_int(data, "iops_mean", steadystate_iops_mean(ts));
+               json_object_add_value_array(data, "iops", iops);
+               json_object_add_value_array(data, "bw", bw);
+       }
+
        return root;
 }
 
@@ -1333,7 +1436,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];
        }
 
@@ -1478,6 +1581,8 @@ void __show_run_stats(void)
                }
                if (last_ts == td->groupid)
                        continue;
+               if (!td->o.stats)
+                       continue;
 
                last_ts = td->groupid;
                nr_ts++;
@@ -1495,6 +1600,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;
@@ -1575,6 +1682,20 @@ void __show_run_stats(void)
                        ts->block_infos[k] = td->ts.block_infos[k];
 
                sum_thread_stats(ts, &td->ts, idx == 1);
+
+               if (td->o.ss_dur) {
+                       ts->ss_state = td->ss.state;
+                       ts->ss_dur = td->ss.dur;
+                       ts->ss_head = td->ss.head;
+                       ts->ss_bw_data = td->ss.bw_data;
+                       ts->ss_iops_data = td->ss.iops_data;
+                       ts->ss_limit.u.f = td->ss.limit;
+                       ts->ss_slope.u.f = td->ss.slope;
+                       ts->ss_deviation.u.f = td->ss.deviation;
+                       ts->ss_criterion.u.f = td->ss.criterion;
+               }
+               else
+                       ts->ss_dur = ts->ss_state = 0;
        }
 
        for (i = 0; i < nr_ts; i++) {
@@ -1597,19 +1718,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];
                }
        }
 
@@ -1620,7 +1736,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];
                }
        }
@@ -1636,16 +1752,22 @@ void __show_run_stats(void)
        if (output_format & FIO_OUTPUT_JSON) {
                struct thread_data *global;
                char time_buf[32];
-               time_t time_p;
+               struct timeval now;
+               unsigned long long ms_since_epoch;
 
-               time(&time_p);
-               os_ctime_r((const time_t *) &time_p, time_buf,
+               gettimeofday(&now, NULL);
+               ms_since_epoch = (unsigned long long)(now.tv_sec) * 1000 +
+                                (unsigned long long)(now.tv_usec) / 1000;
+
+               os_ctime_r((const time_t *) &now.tv_sec, time_buf,
                                sizeof(time_buf));
-               time_buf[strlen(time_buf) - 1] = '\0';
+               if (time_buf[strlen(time_buf) - 1] == '\n')
+                       time_buf[strlen(time_buf) - 1] = '\0';
 
                root = json_create_object();
                json_object_add_value_string(root, "fio version", fio_version_string);
-               json_object_add_value_int(root, "timestamp", time_p);
+               json_object_add_value_int(root, "timestamp", now.tv_sec);
+               json_object_add_value_int(root, "timestamp_ms", ms_since_epoch);
                json_object_add_value_string(root, "time", time_buf);
                global = get_global_options();
                json_add_job_opts(root, "global options", &global->opt_list, false);
@@ -1872,7 +1994,7 @@ static struct io_logs *get_new_log(struct io_log *iolog)
 
        new_size = new_samples * log_entry_sz(iolog);
 
-       cur_log = malloc(sizeof(*cur_log));
+       cur_log = smalloc(sizeof(*cur_log));
        if (cur_log) {
                INIT_FLIST_HEAD(&cur_log->list);
                cur_log->log = malloc(new_size);
@@ -1883,7 +2005,7 @@ static struct io_logs *get_new_log(struct io_log *iolog)
                        iolog->cur_log_max = new_samples;
                        return cur_log;
                }
-               free(cur_log);
+               sfree(cur_log);
        }
 
        return NULL;
@@ -1898,7 +2020,7 @@ static struct io_logs *regrow_log(struct io_log *iolog)
        int i;
 
        if (!iolog || iolog->disabled)
-               return NULL;
+               goto disable;
 
        cur_log = iolog_cur_log(iolog);
        if (!cur_log) {
@@ -1943,24 +2065,24 @@ static struct io_logs *regrow_log(struct io_log *iolog)
                dst = get_sample(iolog, cur_log, i);
                memcpy(dst, src, log_entry_sz(iolog));
        }
+       cur_log->nr_samples = iolog->pending->nr_samples;
 
        iolog->pending->nr_samples = 0;
        return cur_log;
+disable:
+       if (iolog)
+               iolog->disabled = true;
+       return NULL;
 }
 
 void regrow_logs(struct thread_data *td)
 {
-       if (!regrow_log(td->slat_log))
-               td->slat_log->disabled = true;
-       if (!regrow_log(td->clat_log))
-               td->clat_log->disabled = true;
-       if (!regrow_log(td->lat_log))
-               td->lat_log->disabled = true;
-       if (!regrow_log(td->bw_log))
-               td->bw_log->disabled = true;
-       if (!regrow_log(td->iops_log))
-               td->iops_log->disabled = true;
-
+       regrow_log(td->slat_log);
+       regrow_log(td->clat_log);
+       regrow_log(td->clat_hist_log);
+       regrow_log(td->lat_log);
+       regrow_log(td->bw_log);
+       regrow_log(td->iops_log);
        td->flags &= ~TD_F_REGROW_LOGS;
 }
 
@@ -1979,11 +2101,14 @@ static struct io_logs *get_cur_log(struct io_log *iolog)
                return cur_log;
 
        /*
-        * Out of space. If we're in IO offload mode, add a new log chunk
-        * inline. If we're doing inline submissions, flag 'td' as needing
-        * a log regrow and we'll take care of it on the submission side.
+        * Out of space. If we're in IO offload mode, or we're not doing
+        * per unit logging (hence logging happens outside of the IO thread
+        * as well), add a new log chunk inline. If we're doing inline
+        * submissions, flag 'td' as needing a log regrow and we'll take
+        * care of it on the submission side.
         */
-       if (iolog->td->o.io_submit_mode == IO_MODE_OFFLOAD)
+       if (iolog->td->o.io_submit_mode == IO_MODE_OFFLOAD ||
+           !per_unit_log(iolog))
                return regrow_log(iolog);
 
        iolog->td->flags |= TD_F_REGROW_LOGS;
@@ -1991,7 +2116,7 @@ static struct io_logs *get_cur_log(struct io_log *iolog)
        return iolog->pending;
 }
 
-static void __add_log_sample(struct io_log *iolog, unsigned long val,
+static void __add_log_sample(struct io_log *iolog, union io_sample_data data,
                             enum fio_ddir ddir, unsigned int bs,
                             unsigned long t, uint64_t offset)
 {
@@ -2008,8 +2133,8 @@ static void __add_log_sample(struct io_log *iolog, unsigned long val,
 
                s = get_sample(iolog, cur_log, cur_log->nr_samples);
 
-               s->val = val;
-               s->time = t;
+               s->data = data;
+               s->time = t + (iolog->td ? iolog->td->unix_epoch : 0);
                io_sample_set_ddir(iolog, s, ddir);
                s->bs = bs;
 
@@ -2077,14 +2202,14 @@ static void __add_stat_to_log(struct io_log *iolog, enum fio_ddir ddir,
         * had actual samples done.
         */
        if (iolog->avg_window[ddir].samples) {
-               unsigned long val;
+               union io_sample_data data;
 
                if (log_max)
-                       val = iolog->avg_window[ddir].max_val;
+                       data.val = iolog->avg_window[ddir].max_val;
                else
-                       val = iolog->avg_window[ddir].mean.u.f + 0.50;
+                       data.val = iolog->avg_window[ddir].mean.u.f + 0.50;
 
-               __add_log_sample(iolog, val, ddir, 0, elapsed, 0);
+               __add_log_sample(iolog, data, ddir, 0, elapsed, 0);
        }
 
        reset_io_stat(&iolog->avg_window[ddir]);
@@ -2099,14 +2224,14 @@ static void _add_stat_to_log(struct io_log *iolog, unsigned long elapsed,
                __add_stat_to_log(iolog, ddir, elapsed, log_max);
 }
 
-static void add_log_sample(struct thread_data *td, struct io_log *iolog,
-                          unsigned long val, enum fio_ddir ddir,
+static long add_log_sample(struct thread_data *td, struct io_log *iolog,
+                          union io_sample_data data, enum fio_ddir ddir,
                           unsigned int bs, uint64_t offset)
 {
        unsigned long elapsed, this_window;
 
        if (!ddir_rw(ddir))
-               return;
+               return 0;
 
        elapsed = mtime_since_now(&td->epoch);
 
@@ -2114,27 +2239,34 @@ static void add_log_sample(struct thread_data *td, struct io_log *iolog,
         * If no time averaging, just add the log sample.
         */
        if (!iolog->avg_msec) {
-               __add_log_sample(iolog, val, ddir, bs, elapsed, offset);
-               return;
+               __add_log_sample(iolog, data, ddir, bs, elapsed, offset);
+               return 0;
        }
 
        /*
         * Add the sample. If the time period has passed, then
         * add that entry to the log and clear.
         */
-       add_stat_sample(&iolog->avg_window[ddir], val);
+       add_stat_sample(&iolog->avg_window[ddir], data.val);
 
        /*
         * If period hasn't passed, adding the above sample is all we
         * need to do.
         */
        this_window = elapsed - iolog->avg_last;
-       if (this_window < iolog->avg_msec)
-               return;
+       if (elapsed < iolog->avg_last)
+               return iolog->avg_last - elapsed;
+       else if (this_window < iolog->avg_msec) {
+               int diff = iolog->avg_msec - this_window;
+
+               if (inline_log(iolog) || diff > LOG_MSEC_SLACK)
+                       return diff;
+       }
 
        _add_stat_to_log(iolog, elapsed, td->o.log_max != 0);
 
-       iolog->avg_last = elapsed;
+       iolog->avg_last = elapsed - (this_window - iolog->avg_msec);
+       return iolog->avg_msec;
 }
 
 void finalize_logs(struct thread_data *td, bool unit_logs)
@@ -2155,7 +2287,7 @@ void finalize_logs(struct thread_data *td, bool unit_logs)
                _add_stat_to_log(td->iops_log, elapsed, td->o.log_max != 0);
 }
 
-void add_agg_sample(unsigned long val, enum fio_ddir ddir, unsigned int bs)
+void add_agg_sample(union io_sample_data data, enum fio_ddir ddir, unsigned int bs)
 {
        struct io_log *iolog;
 
@@ -2163,7 +2295,7 @@ void add_agg_sample(unsigned long val, enum fio_ddir ddir, unsigned int bs)
                return;
 
        iolog = agg_io_log[ddir];
-       __add_log_sample(iolog, val, ddir, bs, mtime_since_genesis(), 0);
+       __add_log_sample(iolog, data, ddir, bs, mtime_since_genesis(), 0);
 }
 
 static void add_clat_percentile_sample(struct thread_stat *ts,
@@ -2178,18 +2310,59 @@ static void add_clat_percentile_sample(struct thread_stat *ts,
 void add_clat_sample(struct thread_data *td, enum fio_ddir ddir,
                     unsigned long usec, unsigned int bs, uint64_t offset)
 {
+       unsigned long elapsed, this_window;
        struct thread_stat *ts = &td->ts;
+       struct io_log *iolog = td->clat_hist_log;
 
        td_io_u_lock(td);
 
        add_stat_sample(&ts->clat_stat[ddir], usec);
 
        if (td->clat_log)
-               add_log_sample(td, td->clat_log, usec, ddir, bs, offset);
+               add_log_sample(td, td->clat_log, sample_val(usec), ddir, bs,
+                              offset);
 
        if (ts->clat_percentiles)
                add_clat_percentile_sample(ts, usec, ddir);
 
+       if (iolog && iolog->hist_msec) {
+               struct io_hist *hw = &iolog->hist_window[ddir];
+
+               hw->samples++;
+               elapsed = mtime_since_now(&td->epoch);
+               if (!hw->hist_last)
+                       hw->hist_last = elapsed;
+               this_window = elapsed - hw->hist_last;
+               
+               if (this_window >= iolog->hist_msec) {
+                       unsigned int *io_u_plat;
+                       struct io_u_plat_entry *dst;
+
+                       /*
+                        * Make a byte-for-byte copy of the latency histogram
+                        * stored in td->ts.io_u_plat[ddir], recording it in a
+                        * log sample. Note that the matching call to free() is
+                        * located in iolog.c after printing this sample to the
+                        * log file.
+                        */
+                       io_u_plat = (unsigned int *) td->ts.io_u_plat[ddir];
+                       dst = malloc(sizeof(struct io_u_plat_entry));
+                       memcpy(&(dst->io_u_plat), io_u_plat,
+                               FIO_IO_U_PLAT_NR * sizeof(unsigned int));
+                       flist_add(&dst->list, &hw->list);
+                       __add_log_sample(iolog, sample_plat(dst), ddir, bs,
+                                               elapsed, offset);
+
+                       /*
+                        * Update the last time we recorded as being now, minus
+                        * any drift in time we encountered before actually
+                        * making the record.
+                        */
+                       hw->hist_last = elapsed - (this_window - iolog->hist_msec);
+                       hw->samples = 0;
+               }
+       }
+
        td_io_u_unlock(td);
 }
 
@@ -2206,7 +2379,7 @@ void add_slat_sample(struct thread_data *td, enum fio_ddir ddir,
        add_stat_sample(&ts->slat_stat[ddir], usec);
 
        if (td->slat_log)
-               add_log_sample(td, td->slat_log, usec, ddir, bs, offset);
+               add_log_sample(td, td->slat_log, sample_val(usec), ddir, bs, offset);
 
        td_io_u_unlock(td);
 }
@@ -2224,7 +2397,8 @@ void add_lat_sample(struct thread_data *td, enum fio_ddir ddir,
        add_stat_sample(&ts->lat_stat[ddir], usec);
 
        if (td->lat_log)
-               add_log_sample(td, td->lat_log, usec, ddir, bs, offset);
+               add_log_sample(td, td->lat_log, sample_val(usec), ddir, bs,
+                              offset);
 
        td_io_u_unlock(td);
 }
@@ -2245,44 +2419,50 @@ void add_bw_sample(struct thread_data *td, struct io_u *io_u,
        add_stat_sample(&ts->bw_stat[io_u->ddir], rate);
 
        if (td->bw_log)
-               add_log_sample(td, td->bw_log, rate, io_u->ddir, bytes, io_u->offset);
+               add_log_sample(td, td->bw_log, sample_val(rate), io_u->ddir,
+                              bytes, io_u->offset);
 
        td->stat_io_bytes[io_u->ddir] = td->this_io_bytes[io_u->ddir];
        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;
 
-       if (per_unit_log(td->bw_log))
-               return 0;
+       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 >= 10)
-               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) {
                        unsigned int bs = 0;
@@ -2290,20 +2470,30 @@ static int add_bw_samples(struct thread_data *td, struct timeval *t)
                        if (td->o.min_bs[ddir] == td->o.max_bs[ddir])
                                bs = td->o.min_bs[ddir];
 
-                       add_log_sample(td, td->bw_log, 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 td->o.bw_avg_time;
+       if (spent <= avg_time)
+               next = avg_time;
+       else
+               next = avg_time - (1 + spent - avg_time);
 
-       return 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,
@@ -2316,7 +2506,8 @@ void add_iops_sample(struct thread_data *td, struct io_u *io_u,
        add_stat_sample(&ts->iops_stat[io_u->ddir], 1);
 
        if (td->iops_log)
-               add_log_sample(td, td->iops_log, 1, io_u->ddir, bytes, io_u->offset);
+               add_log_sample(td, td->iops_log, sample_val(1), io_u->ddir,
+                              bytes, io_u->offset);
 
        td->stat_io_blocks[io_u->ddir] = td->this_io_blocks[io_u->ddir];
        td_io_u_unlock(td);
@@ -2324,57 +2515,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;
-
-       if (per_unit_log(td->iops_log))
-               return 0;
-
-       spent = mtime_since(&td->iops_sample_time, t);
-       if (spent < td->o.iops_avg_time &&
-           td->o.iops_avg_time - spent >= 10)
-               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];
-
-                       add_log_sample(td, td->iops_log, iops, ddir, bs, 0);
-               }
-
-               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 td->o.iops_avg_time;
-
-       return td->o.iops_avg_time - (1 + spent - td->o.iops_avg_time);
+       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);
 }
 
 /*
@@ -2390,17 +2533,19 @@ int calc_log_samples(void)
        fio_gettime(&now, NULL);
 
        for_each_td(td, i) {
-               if (!ramp_time_over(td) ||
+               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 (!per_unit_log(td->bw_log)) {
+               if (td->bw_log && !per_unit_log(td->bw_log)) {
                        tmp = add_bw_samples(td, &now);
                        if (tmp < next)
                                next = tmp;
                }
-               if (!per_unit_log(td->iops_log)) {
+               if (td->iops_log && !per_unit_log(td->iops_log)) {
                        tmp = add_iops_samples(td, &now);
                        if (tmp < next)
                                next = tmp;