stat: fix shifted windowed logging when using multiple directions

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>

diff --git a/iolog.h b/iolog.h
index d157fa281bd2828f93e050906f71a21cd5ae817f..bc3a0b5fea93770fa39309fb71526c751e803034 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 91c74abef420f8fb0e8453e5a9be1fecff1e6f56..63353cc0cd2bb496de27d6bda796ab130cb285d5 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;
 }