HOWTO: modernize output examples and descriptions
authorSitsofe Wheeler <sitsofe@yahoo.com>
Fri, 23 Jun 2017 06:01:50 +0000 (07:01 +0100)
committerSitsofe Wheeler <sitsofe@yahoo.com>
Mon, 26 Jun 2017 22:51:29 +0000 (23:51 +0100)
- Update output examples to reflect what is produced by the current fio
- Add hidden comments saying how to generate output for fio examples.
- Update output descriptions to match examples.
- Add missing thread lifecycle states.

HOWTO

diff --git a/HOWTO b/HOWTO
index 09ac5cee4c1ad7222cb8ea796d56bfa74b026fbc..a098a771189f34b2354cad1ccf6616fc4bcf1a96 100644 (file)
--- a/HOWTO
+++ b/HOWTO
@@ -2979,13 +2979,20 @@ Tiobench profile options
 Interpreting the output
 -----------------------
 
 Interpreting the output
 -----------------------
 
+..
+       Example output was based on the following:
+       TZ=UTC fio --iodepth=8 --ioengine=null --size=100M --time_based \
+               --rate=1256k --bs=14K --name=quick --runtime=1s --name=mixed \
+               --runtime=2m --rw=rw
+
 Fio spits out a lot of output. While running, fio will display the status of the
 jobs created. An example of that would be::
 
     Jobs: 1 (f=1): [_(1),M(1)][24.8%][r=20.5MiB/s,w=23.5MiB/s][r=82,w=94 IOPS][eta 01m:31s]
 
 Fio spits out a lot of output. While running, fio will display the status of the
 jobs created. An example of that would be::
 
     Jobs: 1 (f=1): [_(1),M(1)][24.8%][r=20.5MiB/s,w=23.5MiB/s][r=82,w=94 IOPS][eta 01m:31s]
 
-The characters inside the square brackets denote the current status of each
-thread. The possible values (in typical life cycle order) are:
+The characters inside the first set of square brackets denote the current status of
+each thread.  The first character is the first job defined in the job file, and so
+forth.  The possible values (in typical life cycle order) are:
 
 +------+-----+-----------------------------------------------------------+
 | Idle | Run |                                                           |
 
 +------+-----+-----------------------------------------------------------+
 | Idle | Run |                                                           |
@@ -2998,6 +3005,8 @@ thread. The possible values (in typical life cycle order) are:
 +------+-----+-----------------------------------------------------------+
 |      |  p  | Thread running pre-reading file(s).                       |
 +------+-----+-----------------------------------------------------------+
 +------+-----+-----------------------------------------------------------+
 |      |  p  | Thread running pre-reading file(s).                       |
 +------+-----+-----------------------------------------------------------+
+|      |  /  | Thread is in ramp period.                                 |
++------+-----+-----------------------------------------------------------+
 |      |  R  | Running, doing sequential reads.                          |
 +------+-----+-----------------------------------------------------------+
 |      |  r  | Running, doing random reads.                              |
 |      |  R  | Running, doing sequential reads.                          |
 +------+-----+-----------------------------------------------------------+
 |      |  r  | Running, doing random reads.                              |
@@ -3010,77 +3019,103 @@ thread. The possible values (in typical life cycle order) are:
 +------+-----+-----------------------------------------------------------+
 |      |  m  | Running, doing mixed random reads/writes.                 |
 +------+-----+-----------------------------------------------------------+
 +------+-----+-----------------------------------------------------------+
 |      |  m  | Running, doing mixed random reads/writes.                 |
 +------+-----+-----------------------------------------------------------+
-|      |  F  | Running, currently waiting for :manpage:`fsync(2)`        |
+|      |  D  | Running, doing sequential trims.                          |
++------+-----+-----------------------------------------------------------+
+|      |  d  | Running, doing random trims.                              |
++------+-----+-----------------------------------------------------------+
+|      |  F  | Running, currently waiting for :manpage:`fsync(2)`.       |
 +------+-----+-----------------------------------------------------------+
 |      |  V  | Running, doing verification of written data.              |
 +------+-----+-----------------------------------------------------------+
 +------+-----+-----------------------------------------------------------+
 |      |  V  | Running, doing verification of written data.              |
 +------+-----+-----------------------------------------------------------+
+| f    |     | Thread finishing.                                         |
++------+-----+-----------------------------------------------------------+
 | E    |     | Thread exited, not reaped by main thread yet.             |
 +------+-----+-----------------------------------------------------------+
 | E    |     | Thread exited, not reaped by main thread yet.             |
 +------+-----+-----------------------------------------------------------+
-| _    |     | Thread reaped, or                                         |
+| _    |     | Thread reaped.                                            |
 +------+-----+-----------------------------------------------------------+
 | X    |     | Thread reaped, exited with an error.                      |
 +------+-----+-----------------------------------------------------------+
 | K    |     | Thread reaped, exited due to signal.                      |
 +------+-----+-----------------------------------------------------------+
 
 +------+-----+-----------------------------------------------------------+
 | X    |     | Thread reaped, exited with an error.                      |
 +------+-----+-----------------------------------------------------------+
 | K    |     | Thread reaped, exited due to signal.                      |
 +------+-----+-----------------------------------------------------------+
 
+..
+       Example output was based on the following:
+       TZ=UTC fio --iodepth=8 --ioengine=null --size=100M --runtime=58m \
+               --time_based --rate=2512k --bs=256K --numjobs=10 \
+               --name=readers --rw=read --name=writers --rw=write
+
 Fio will condense the thread string as not to take up more space on the command
 Fio will condense the thread string as not to take up more space on the command
-line as is needed. For instance, if you have 10 readers and 10 writers running,
+line than needed. For instance, if you have 10 readers and 10 writers running,
 the output would look like this::
 
     Jobs: 20 (f=20): [R(10),W(10)][4.0%][r=20.5MiB/s,w=23.5MiB/s][r=82,w=94 IOPS][eta 57m:36s]
 
 the output would look like this::
 
     Jobs: 20 (f=20): [R(10),W(10)][4.0%][r=20.5MiB/s,w=23.5MiB/s][r=82,w=94 IOPS][eta 57m:36s]
 
-Fio will still maintain the ordering, though. So the above means that jobs 1..10
-are readers, and 11..20 are writers.
+Note that the status string is displayed in order, so it's possible to tell which of
+the jobs are currently doing what.  In the example above this means that jobs 1--10
+are readers and 11--20 are writers.
 
 The other values are fairly self explanatory -- number of threads currently
 
 The other values are fairly self explanatory -- number of threads currently
-running and doing I/O, the number of currently open files (f=), the rate of I/O
-since last check (read speed listed first, then write speed and optionally trim
-speed), and the estimated completion percentage and time for the current
+running and doing I/O, the number of currently open files (f=), the estimated
+completion percentage, the rate of I/O since last check (read speed listed first,
+then write speed and optionally trim speed) in terms of bandwidth and IOPS, and time to completion for the current
 running group. It's impossible to estimate runtime of the following groups (if
 running group. It's impossible to estimate runtime of the following groups (if
-any). Note that the string is displayed in order, so it's possible to tell which
-of the jobs are currently doing what. The first character is the first job
-defined in the job file, and so forth.
-
-When fio is done (or interrupted by :kbd:`ctrl-c`), it will show the data for
-each thread, group of threads, and disks in that order. For each data direction,
-the output looks like::
-
-    Client1 (g=0): err= 0:
-      write: io=    32MiB, bw=   666KiB/s, iops=89 , runt= 50320msec
-        slat (msec): min=    0, max=  136, avg= 0.03, stdev= 1.92
-        clat (msec): min=    0, max=  631, avg=48.50, stdev=86.82
-        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, majf=0, minf=17
-      IO depths    : 1=0.1%, 2=0.3%, 4=0.5%, 8=99.0%, 16=0.0%, 32=0.0%, >32=0.0%
-         submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
-         complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=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%
-
-The client number is printed, along with the group id and error of that
-thread. Below is the I/O statistics, here for writes. In the order listed, they
-denote:
-
-**io**
-               Number of megabytes I/O performed.
-
-**bw**
-               Average bandwidth rate.
-
-**iops**
-               Average I/Os performed per second.
-
-**runt**
-               The runtime of that thread.
+any).
+
+..
+       Example output was based on the following:
+       TZ=UTC fio --iodepth=16 --ioengine=posixaio --filename=/tmp/fiofile \
+               --direct=1 --size=100M --time_based --runtime=50s --rate_iops=89 \
+               --bs=7K --name=Client1 --rw=write
+
+When fio is done (or interrupted by :kbd:`Ctrl-C`), it will show the data for
+each thread, group of threads, and disks in that order. For each overall thread (or
+group) the output looks like::
+
+       Client1: (groupid=0, jobs=1): err= 0: pid=16109: Sat Jun 24 12:07:54 2017
+         write: IOPS=88, BW=623KiB/s (638kB/s)(30.4MiB/50032msec)
+           slat (nsec): min=500, max=145500, avg=8318.00, stdev=4781.50
+           clat (usec): min=170, max=78367, avg=4019.02, stdev=8293.31
+            lat (usec): min=174, max=78375, avg=4027.34, stdev=8291.79
+           clat percentiles (usec):
+            |  1.00th=[  302],  5.00th=[  326], 10.00th=[  343], 20.00th=[  363],
+            | 30.00th=[  392], 40.00th=[  404], 50.00th=[  416], 60.00th=[  445],
+            | 70.00th=[  816], 80.00th=[ 6718], 90.00th=[12911], 95.00th=[21627],
+            | 99.00th=[43779], 99.50th=[51643], 99.90th=[68682], 99.95th=[72877],
+            | 99.99th=[78119]
+          bw (  KiB/s): min=  532, max=  686, per=0.10%, avg=622.87, stdev=24.82, samples=  100
+          iops        : min=   76, max=   98, avg=88.98, stdev= 3.54, samples=  100
+           lat (usec) : 250=0.04%, 500=64.11%, 750=4.81%, 1000=2.79%
+           lat (msec) : 2=4.16%, 4=1.84%, 10=4.90%, 20=11.33%, 50=5.37%
+           lat (msec) : 100=0.65%
+         cpu          : usr=0.27%, sys=0.18%, ctx=12072, majf=0, minf=21
+         IO depths    : 1=85.0%, 2=13.1%, 4=1.8%, 8=0.1%, 16=0.0%, 32=0.0%, >=64=0.0%
+            submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
+            complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
+            issued rwt: total=0,4450,0, short=0,0,0, dropped=0,0,0
+            latency   : target=0, window=0, percentile=100.00%, depth=8
+
+The job name (or first job's name when using :option:`group_reporting`) is printed,
+along with the group id, count of jobs being aggregated, last error id seen (which
+is 0 when there are no errors), pid/tid of that thread and the time the job/group
+completed.  Below are the I/O statistics for each data direction performed (showing
+writes in the example above).  In the order listed, they denote:
+
+**read/write/trim**
+               The string before the colon shows the I/O direction the statistics
+               are for.  **IOPS** is the average I/Os performed per second.  **BW**
+               is the average bandwidth rate shown as: value in power of 2 format
+               (value in power of 10 format).  The last two values show: (**total
+               I/O performed** in power of 2 format / **runtime** of that thread).
 
 **slat**
 
 **slat**
-               Submission latency (avg being the average, stdev being the standard
-               deviation). This is the time it took to submit the I/O. For sync I/O,
-               the slat is really the completion latency, since queue/complete is one
-               operation there. This value can be in milliseconds or microseconds, fio
-               will choose the most appropriate base and print that. In the example
-               above, milliseconds is the best scale. Note: in :option:`--minimal` mode
+               Submission latency (**min** being the minimum, **max** being the
+               maximum, **avg** being the average, **stdev** being the standard
+               deviation).  This is the time it took to submit the I/O.  For
+               sync I/O this row is not displayed as the slat is really the
+               completion latency (since queue/complete is one operation there).
+               This value can be in nanoseconds, microseconds or milliseconds ---
+               fio will choose the most appropriate base and print that (in the
+               example above nanoseconds was the best scale).  Note: in :option:`--minimal` mode
                latencies are always expressed in microseconds.
 
 **clat**
                latencies are always expressed in microseconds.
 
 **clat**
@@ -3091,11 +3126,15 @@ denote:
                explanation).
 
 **bw**
                explanation).
 
 **bw**
-               Bandwidth. Same names as the xlat stats, but also includes an
-               approximate percentage of total aggregate bandwidth this thread received
-               in this group. This last value is only really useful if the threads in
-               this group are on the same disk, since they are then competing for disk
-               access.
+               Bandwidth statistics based on samples. Same names as the xlat stats,
+               but also includes the number of samples taken (**samples**) and an
+               approximate percentage of total aggregate bandwidth this thread
+               received in its group (**per**). This last value is only really
+               useful if the threads in this group are on the same disk, since they
+               are then competing for disk access.
+
+**iops**
+               IOPS statistics based on samples. Same names as bw.
 
 **cpu**
                CPU usage. User and system time, along with the number of context
 
 **cpu**
                CPU usage. User and system time, along with the number of context
@@ -3123,9 +3162,9 @@ denote:
 **IO complete**
                Like the above submit number, but for completions instead.
 
 **IO complete**
                Like the above submit number, but for completions instead.
 
-**IO issued**
-               The number of read/write requests issued, and how many of them were
-               short.
+**IO issued rwt**
+               The number of read/write/trim requests issued, and how many of them were
+               short or dropped.
 
 **IO latencies**
                The distribution of I/O completion latencies. This is the time from when
 
 **IO latencies**
                The distribution of I/O completion latencies. This is the time from when
@@ -3134,27 +3173,31 @@ denote:
                I/O completed within 2 msecs, 20=12.8% means that 12.8% of the I/O took
                more than 10 msecs, but less than (or equal to) 20 msecs.
 
                I/O completed within 2 msecs, 20=12.8% means that 12.8% of the I/O took
                more than 10 msecs, but less than (or equal to) 20 msecs.
 
+..
+       Example output was based on the following:
+       TZ=UTC fio --ioengine=null --iodepth=2 --size=100M --numjobs=2 \
+               --rate_process=poisson --io_limit=32M --name=read --bs=128k \
+               --rate=11M --name=write --rw=write --bs=2k --rate=700k
+
 After each client has been listed, the group statistics are printed. They
 will look like this::
 
     Run status group 0 (all jobs):
 After each client has been listed, the group statistics are printed. They
 will look like this::
 
     Run status group 0 (all jobs):
-       READ: io=64MB, aggrb=22178, minb=11355, maxb=11814, mint=2840msec, maxt=2955msec
-      WRITE: io=64MB, aggrb=1302, minb=666, maxb=669, mint=50093msec, maxt=50320msec
+       READ: bw=20.9MiB/s (21.9MB/s), 10.4MiB/s-10.8MiB/s (10.9MB/s-11.3MB/s), io=64.0MiB (67.1MB), run=2973-3069msec
+      WRITE: bw=1231KiB/s (1261kB/s), 616KiB/s-621KiB/s (630kB/s-636kB/s), io=64.0MiB (67.1MB), run=52747-53223msec
 
 
-For each data direction, it prints:
+For each data direction it prints:
 
 
+**bw**
+               Aggregate bandwidth of threads in this group followed by the
+               minimum and maximum bandwidth of all the threads in this group.
+               Values outside of brackets are power-of-2 format and those
+               within are the equivalent value in a power-of-10 format.
 **io**
 **io**
-               Number of megabytes I/O performed.
-**aggrb**
-               Aggregate bandwidth of threads in this group.
-**minb**
-               The minimum average bandwidth a thread saw.
-**maxb**
-               The maximum average bandwidth a thread saw.
-**mint**
-               The smallest runtime of the threads in that group.
-**maxt**
-               The longest runtime of the threads in that group.
+               Aggregate I/O performed of all threads in this group. The
+               format is the same as bw.
+**run**
+               The smallest and longest runtimes of the threads in this group.
 
 And finally, the disk statistics are printed. They will look like this::
 
 
 And finally, the disk statistics are printed. They will look like this::
 
@@ -3170,7 +3213,7 @@ numbers denote:
                Number of merges I/O the I/O scheduler.
 **ticks**
                Number of ticks we kept the disk busy.
                Number of merges I/O the I/O scheduler.
 **ticks**
                Number of ticks we kept the disk busy.
-**io_queue**
+**in_queue**
                Total time spent in the disk queue.
 **util**
                The disk utilization. A value of 100% means we kept the disk
                Total time spent in the disk queue.
 **util**
                The disk utilization. A value of 100% means we kept the disk