Log and dump short ios
Signed-off-by: Jens Axboe <jens.axboe@oracle.com>
diff --git a/HOWTO b/HOWTO
index 08a2b68..aeb87dd 100644
--- a/HOWTO
+++ b/HOWTO
@@ -684,6 +684,7 @@
bw (KiB/s) : min= 0, max= 1196, per=51.00%, avg=664.02, stdev=681.68
cpu : usr=1.49%, sys=0.25%, ctx=7969
IO depths : 1=0.1%, 2=0.3%, 4=0.5%, 8=99.0%, 16=0.0%, 32=0.0%, >32=0.0%
+ issued r/w: total=0/32768, short=0/0
lat (msec): 2=1.6%, 4=0.0%, 10=3.2%, 20=12.8%, 50=38.4%, 100=24.8%,
lat (msec): 250=15.2%, 500=0.0%, 750=0.0%, 1000=0.0%, >=2048=0.0%
@@ -715,6 +716,8 @@
16= entries includes depths up to that value but higher
than the previous entry. In other words, it covers the
range from 16 to 31.
+IO issued= The number of read/write requests issued, and how many
+ of them were short.
IO latencies= The distribution of IO completion latencies. This is the
time from when IO leaves fio and when it gets completed.
The numbers follow the same pattern as the IO depths,
diff --git a/fio.c b/fio.c
index 296ac34..60a2a1b 100644
--- a/fio.c
+++ b/fio.c
@@ -348,6 +348,8 @@
io_u->offset += bytes;
f->last_completed_pos = io_u->offset;
+ td->ts.short_io_u[io_u->ddir]++;
+
if (io_u->offset == f->real_file_size)
goto sync_done;
@@ -464,6 +466,8 @@
io_u->offset += bytes;
f->last_completed_pos = io_u->offset;
+ td->ts.short_io_u[io_u->ddir]++;
+
if (io_u->offset == f->real_file_size)
goto sync_done;
diff --git a/fio.h b/fio.h
index 9c398a2..0893a20 100644
--- a/fio.h
+++ b/fio.h
@@ -333,6 +333,7 @@
unsigned int io_u_map[FIO_IO_U_MAP_NR];
unsigned int io_u_lat[FIO_IO_U_LAT_NR];
unsigned long total_io_u[2];
+ unsigned long short_io_u[2];
unsigned long long io_bytes[2];
unsigned long runtime[2];
diff --git a/stat.c b/stat.c
index 3a785ee..0c2e01b 100644
--- a/stat.c
+++ b/stat.c
@@ -225,6 +225,7 @@
stat_calc_lat(ts, io_u_lat);
log_info(" IO depths : 1=%3.1f%%, 2=%3.1f%%, 4=%3.1f%%, 8=%3.1f%%, 16=%3.1f%%, 32=%3.1f%%, >=64=%3.1f%%\n", io_u_dist[0], 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_info(" issued r/w: total=%lu/%lu, short=%lu/%lu\n", ts->total_io_u[0], ts->total_io_u[1], ts->short_io_u[0], ts->short_io_u[1]);
log_info(" lat (msec): 2=%3.2f%%, 4=%3.2f%%, 10=%3.2f%%, 20=%3.2f%%, 50=%3.2f%%, 100=%3.2f%%\n", io_u_lat[0], io_u_lat[1], io_u_lat[2], io_u_lat[3], io_u_lat[4], io_u_lat[5]);
log_info(" lat (msec): 250=%3.2f%%, 500=%3.2f%%, 750=%3.2f%%, 1000=%3.2f%%, >=2000=%3.2f%%\n", io_u_lat[6], io_u_lat[7], io_u_lat[8], io_u_lat[9], io_u_lat[10]);
@@ -431,8 +432,10 @@
for (k = 0; k < FIO_IO_U_LAT_NR; k++)
ts->io_u_lat[k] += td->ts.io_u_lat[k];
- for (k = 0; k <= DDIR_WRITE; k++)
+ for (k = 0; k <= DDIR_WRITE; k++) {
ts->total_io_u[k] += td->ts.total_io_u[k];
+ ts->short_io_u[k] += td->ts.short_io_u[k];
+ }
ts->total_run_time += td->ts.total_run_time;
}