stat: fix shifted windowed logging when using multiple directions
authorSitsofe Wheeler <sitsofe@yahoo.com>
Wed, 30 Aug 2017 19:08:00 +0000 (20:08 +0100)
committerSitsofe Wheeler <sitsofe@yahoo.com>
Fri, 1 Sep 2017 21:31:42 +0000 (22:31 +0100)
When using log_avg_msec and multiple I/O directions, the results
recorded for the directions other than the first are attributed to the
wrong time. This is demonstrated by the following:

sudo modprobe null_blk completion_nsec=100000000 irqmode=2
sudo ./fio --bs=4k --direct=1 --ioengine=libaio --log_avg_msec=1000 \
 --runtime=2s --disable_lat=1 --disable_bw_measurement=1 \
 --filename=/dev/nullb0 --write_iops_log=shiftedlog --rw=rw \
 --name=shiftedlog

results in this:
cat shiftedlog_iops.1.log
1000, 5, 0, 0
2000, 6, 0, 0
2000, 4, 1, 0
2256, 4, 1, 0

shiftedlog_iops.1.log is missing an entry at 1000ms for for the write
direction (1) because the sample has been misattributed to 2000ms (the
third row) due to iolog->avg_last being shared by all directions.

Fix the shifting by turning iolog->avg_last into an array indexed by
direction and only update the windowed stats for the current direction
from add_log_sample().

Fixes https://github.com/axboe/fio/issues/410 .

Reported-by: Kris Davis <shimrot@gmail.com>
Signed-off-by: Sitsofe Wheeler <sitsofe@yahoo.com>
iolog.h
stat.c

diff --git a/iolog.h b/iolog.h
index d157fa2..bc3a0b5 100644 (file)
--- a/iolog.h
+++ b/iolog.h
@@ -117,7 +117,7 @@ struct io_log {
         */
        struct io_stat avg_window[DDIR_RWDIR_CNT];
        unsigned long avg_msec;
-       unsigned long avg_last;
+       unsigned long avg_last[DDIR_RWDIR_CNT];
 
        /*
         * Windowed latency histograms, for keeping track of when we need to
diff --git a/stat.c b/stat.c
index 91c74ab..63353cc 100644 (file)
--- a/stat.c
+++ b/stat.c
@@ -2159,7 +2159,7 @@ static void __add_log_sample(struct io_log *iolog, union io_sample_data data,
        if (iolog->disabled)
                return;
        if (flist_empty(&iolog->io_logs))
-               iolog->avg_last = t;
+               iolog->avg_last[ddir] = t;
 
        cur_log = get_cur_log(iolog);
        if (cur_log) {
@@ -2290,9 +2290,9 @@ static long add_log_sample(struct thread_data *td, struct io_log *iolog,
         * If period hasn't passed, adding the above sample is all we
         * need to do.
         */
-       this_window = elapsed - iolog->avg_last;
-       if (elapsed < iolog->avg_last)
-               return iolog->avg_last - elapsed;
+       this_window = elapsed - iolog->avg_last[ddir];
+       if (elapsed < iolog->avg_last[ddir])
+               return iolog->avg_last[ddir] - elapsed;
        else if (this_window < iolog->avg_msec) {
                int diff = iolog->avg_msec - this_window;
 
@@ -2300,9 +2300,9 @@ static long add_log_sample(struct thread_data *td, struct io_log *iolog,
                        return diff;
        }
 
-       _add_stat_to_log(iolog, elapsed, td->o.log_max != 0);
+       __add_stat_to_log(iolog, ddir, elapsed, td->o.log_max != 0);
 
-       iolog->avg_last = elapsed - (this_window - iolog->avg_msec);
+       iolog->avg_last[ddir] = elapsed - (this_window - iolog->avg_msec);
        return iolog->avg_msec;
 }