doc/blktrace.tex

   1 \documentclass{article}
   2
   3 %
   4 % Copyright (C) 2005 Alan D. Brunelle <Alan.Brunelle@hp.com>
   5 %
   6 %  This program is free software; you can redistribute it and/or modify
   7 %  it under the terms of the GNU General Public License as published by
   8 %  the Free Software Foundation; either version 2 of the License, or
   9 %  (at your option) any later version.
  10 %
  11 %  This program is distributed in the hope that it will be useful,
  12 %  but WITHOUT ANY WARRANTY; without even the implied warranty of
  13 %  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  14 %  GNU General Public License for more details.
  15 %
  16 %  You should have received a copy of the GNU General Public License
  17 %  along with this program; if not, write to the Free Software
  18 %  Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA
  19 %
  20
  21 \title{blktrace User Guide}
  22 \author{blktrace: Jens Axboe (axboe@suse.de)\\
  23         User Guide: Alan D. Brunelle (Alan.Brunelle@hp.com)}
  24 \date{4 October 2005}
  25
  26 \begin{document}
  27 \maketitle
  28 %---------------------
  29 \section{\label{sec:intro}Introduction}
  30
  31 blktrace is a block layer IO tracing mechanism which provides detailed
  32 information about request queue operations up to user space. There are
  33 three major components that are provided:
  34
  35 \begin{description}
  36   \item[Kernel patch] A patch to the Linux kernel which includes the
  37   kernel event logging interfaces, and patches to areas within the block
  38   layer to emit event traces.
  39
  40   \item[blktrace] A utility which transfers event traces from the kernel
  41   into either long-term on-disk storage, or provides direct formatted
  42   output (via blkparse).
  43
  44   \item[blkparse] A utility which formats events stored in files, or when
  45   run in \emph{live} mode directly outputs data collected by blktrace.
  46 \end{description}
  47
  48 \subsection{blktrace Download Area}
  49
  50 The blktrace and blkparse utilities and associated kernel patch are provided
  51 as part of the following git repository:
  52
  53 rsync://rsync.kernel.org/pub/scm/linux/kernel/git/axboe/blktrace.git
  54
  55 %--------------------------
  56 \newpage\section{\label{sec:quick-start}Quick Start Guide}
  57
  58 The following sections outline some quick steps towards utilizing
  59 blktrace. Some of the specific instructions below may need to be tailored
  60 to your environment.
  61
  62 \subsection{\label{sec:get-blktrace}Retrieving blktrace}
  63
  64 As noted above, the kernel patch along with the blktrace and blkparse utilities are stored in a git repository. One simple way to get going would be:
  65
  66 \begin{verbatim}
  67 % git clone rsync://rsync.kernel.org/pub/scm/linux/kernel/git/axboe/blktrace.git bt
  68 % cd bt
  69 % git-read-tree -m HEAD && git-checkout-cache -q -f -u -a
  70 \end{verbatim}
  71
  72 \subsection{\label{sec:patching}Patching and configuring the Linux kernel}
  73
  74 A patch for a \emph{specific Linux kernel} is provided in bt/kernel (where
  75 \emph{bt} is the name of the directory from the above git sequence). The
  76 detailed actual patching instructions for a Linux kernel is outside the
  77 scope of this document, but the following may be used as a sample template.
  78
  79 As an example, bt/kernel contains blk-trace-2.6.14-rc1-git-G2, download
  80 linux-2.6.13.tar.bz2 and patch-2.6.14-rc1.bz2
  81
  82 \begin{verbatim}
  83 % tar xjf linux-2.6.13.tar.bz2
  84 % mv linux-2.6.13 linux-2.6.14-rc1
  85 % cd linux-2.6.14-rc1
  86 % bunzip2 -c ../patch-2.6.14-rc1.bz2 | patch -p1
  87 \end{verbatim}
  88
  89 At this point you may (optionally) remove linux-2.6.13.tar.bz2 and
  90 patch-2.6.14-rc1.bz2.
  91
  92 At this point you should configure the Linux kernel for your specific
  93 system -- again, outside the scope of this document -- and then enable
  94 \emph{Support for tracing block io actions.} To do this, run
  95
  96 \begin{verbatim}
  97 % make menuconfig                    or make xconfig, or edit .config, or ...
  98 \end{verbatim}
  99
 100 and navigate through \emph{Device Drivers} and \emph{Block devices}
 101 and then down to \emph{Support for tracing block io actions} and hit Y.
 102
 103 Install the new kernel (and modules\ldots) and reboot.
 104
 105 \subsection{\label{sec:mount}Mounting the RelayFS file system}
 106
 107 blktrace utilizes files under the Relay file system, and thus must have
 108 the mount point set up -- mounted on the directory /relay. To do this
 109 one may do either of the following:
 110
 111 \begin{enumerate}
 112   \item Manually mount after each boot:
 113 \begin{verbatim}
 114 % mount -t relayfs relayfs /relay
 115 \end{verbatim}
 116
 117   \item Add an entry into /etc/fstab, and have it done automatically at
 118   each boot\footnote{Note: after adding the entry to /etc/fstab, you
 119   could then mount the directory this time only by doing: \% mount /relay}:
 120 \begin{verbatim}
 121 relay /relay relayfs default 0 0
 122 \end{verbatim}
 123 \end{enumerate}
 124
 125 \subsection{\label{sec:build}Build the tools}
 126
 127 To build and install the tools, execute the following sequence (as root):
 128
 129 \begin{verbatim}
 130 % cd bt
 131 % make && make install
 132 \end{verbatim}
 133
 134 \subsection{\label{sec:live-blktrace}blktrace -- live}
 135
 136 Now to simply watch what is going on for a specific disk (to stop the
 137 trace, hit control-C):
 138
 139 \begin{verbatim}
 140 % blktrace -d /dev/sda -o - | blkparse -i -
 141   8,0    3        1     0.000000000   697  G   W 223490 + 8 [kjournald]
 142   8,0    3        2     0.000001829   697  P   R [kjournald]
 143   8,0    3        3     0.000002197   697  Q   W 223490 + 8 [kjournald]
 144   8,0    3        4     0.000005533   697  M   W 223498 + 8 [kjournald]
 145   8,0    3        5     0.000008607   697  M   W 223506 + 8 [kjournald]
 146   8,0    3        6     0.000011569   697  M   W 223514 + 8 [kjournald]
 147   8,0    3        7     0.000014407   697  M   W 223522 + 8 [kjournald]
 148   8,0    3        8     0.000017367   697  M   W 223530 + 8 [kjournald]
 149   8,0    3        9     0.000020161   697  M   W 223538 + 8 [kjournald]
 150   8,0    3       10     0.000024062   697  D   W 223490 + 56 [kjournald]
 151   8,0    1       11     0.009507758     0  C   W 223490 + 56 [0]
 152   8,0    1       12     0.009538995   697  G   W 223546 + 8 [kjournald]
 153   8,0    1       13     0.009540033   697  P   R [kjournald]
 154   8,0    1       14     0.009540313   697  Q   W 223546 + 8 [kjournald]
 155   8,0    1       15     0.009542980   697  D   W 223546 + 8 [kjournald]
 156   8,0    1       16     0.013542170     0  C   W 223546 + 8 [0]
 157 ...
 158 ^C
 159 ...
 160 CPU1 (8,0):
 161  Reads Queued:           0,        0KiB  Writes Queued:           7,      128KiB
 162  Read Dispatches:        0,        0KiB  Write Dispatches:        7,      128KiB
 163  Reads Completed:        0,        0KiB  Writes Completed:       11,      168KiB
 164  Read Merges:            0               Write Merges:           25
 165  IO unplugs:             0               Timer unplugs:           0
 166 ...
 167 CPU3 (8,0):
 168  Reads Queued:           0,        0KiB  Writes Queued:           1,       28KiB
 169  Read Dispatches:        0,        0KiB  Write Dispatches:        1,       28KiB
 170  Reads Completed:        0,        0KiB  Writes Completed:        0,        0KiB
 171  Read Merges:            0               Write Merges:            6
 172  IO unplugs:             0               Timer unplugs:           0
 173
 174 Total (8,0):
 175  Reads Queued:           0,        0KiB  Writes Queued:          11,      168KiB
 176  Read Dispatches:        0,        0KiB  Write Dispatches:       11,      168KiB
 177  Reads Completed:        0,        0KiB  Writes Completed:       11,      168KiB
 178  Read Merges:            0               Write Merges:           31
 179  IO unplugs:             0               Timer unplugs:           3
 180
 181 Events (8,0): 89 entries, 0 skips
 182 \end{verbatim}
 183
 184 \subsection{\label{sec:blktrace-post}blktrace -- post-processing}
 185
 186 Another way to run blktrace is to have blktrace save data away for later
 187 formatting by blkparse. This would be useful if you want to get
 188 measurements while running specific loads.
 189
 190 To do this, one would specify the device (or devices) to be watched. Then
 191 go run you test cases. Stop the trace, and at your leisure utilize
 192 blkparse to see the results.
 193
 194 In this example, devices /dev/sdaa, /dev/sdc and /dev/sdo are used in an
 195 LVM volume called adb3/vol.
 196
 197 \begin{verbatim}
 198 % blktrace /dev/sdaa /dev/sdc /dev/sdo &
 199 [1] 9713
 200 %
 201 % mkfs -t ext3 /dev/adb3/vol
 202 mke2fs 1.35 (28-Feb-2004)
 203 Filesystem label=
 204 OS type: Linux
 205 Block size=4096 (log=2)
 206 Fragment size=4096 (log=2)
 207 16793600 inodes, 33555456 blocks
 208 1677772 blocks (5.00%) reserved for the super user
 209 First data block=0
 210 Maximum filesystem blocks=4294967296
 211 1025 block groups
 212 32768 blocks per group, 32768 fragments per group
 213 16384 inodes per group
 214 Superblock backups stored on blocks:
 215         32768, 98304, 163840, 229376, 294912, 819200, 884736, 1605632, 2654208,
 216         4096000, 7962624, 11239424, 20480000, 23887872
 217
 218 Writing inode tables: done
 219 Creating journal (8192 blocks): done
 220 Writing superblocks and filesystem accounting information: done
 221
 222 This filesystem will be automatically checked every 27 mounts or
 223 180 days, whichever comes first.  Use tune2fs -c or -i to override.
 224 %
 225 % kill -15 9713
 226 \end{verbatim}
 227
 228 Then you could process the events later:
 229
 230 \begin{verbatim}
 231 %
 232 % blkparse sdaa sdc sdo > events
 233 % less events
 234   8,32   1        1     0.000000000  9728  G   R 384 + 32 [mkfs.ext3]
 235   8,32   1        2     0.000001959  9728  P   R [mkfs.ext3]
 236   8,32   1        3     0.000002446  9728  Q   R 384 + 32 [mkfs.ext3]
 237   8,32   1        4     0.000005110  9728  D   R 384 + 32 [mkfs.ext3]
 238   8,32   3        5     0.000200570     0  C   R 384 + 32 [0]
 239   8,224  3        1     0.021658989  9728  G   R 384 + 32 [mkfs.ext3]
 240 ...
 241  65,160  3   163392    41.117070504     0  C   W 87469088 + 1376 [0]
 242   8,32   3   163374    41.122683668     0  C   W 88168160 + 1376 [0]
 243  65,160  3   163393    41.129952433     0  C   W 87905984 + 1376 [0]
 244  65,160  3   163394    41.130049431     0  D   W 89129344 + 1376 [swapper]
 245  65,160  3   163395    41.130067135     0  D   W 89216704 + 1376 [swapper]
 246  65,160  3   163396    41.130083785     0  D   W 89304096 + 1376 [swapper]
 247  65,160  3   163397    41.130099455     0  D   W 89391488 + 1376 [swapper]
 248  65,160  3   163398    41.130114732     0  D   W 89478848 + 1376 [swapper]
 249  65,160  3   163399    41.130128885     0  D   W 89481536 + 64 [swapper]
 250   8,32   3   163375    41.134758196     0  C   W 86333152 + 1376 [0]
 251  65,160  3   163400    41.142229726     0  C   W 89129344 + 1376 [0]
 252  65,160  3   163401    41.144952314     0  C   W 89481536 + 64 [0]
 253   8,32   3   163376    41.147441930     0  C   W 88342912 + 1376 [0]
 254  65,160  3   163402    41.155869604     0  C   W 89478848 + 1376 [0]
 255   8,32   3   163377    41.159466082     0  C   W 86245760 + 1376 [0]
 256  65,160  3   163403    41.166944976     0  C   W 89216704 + 1376 [0]
 257  65,160  3   163404    41.178968252     0  C   W 89304096 + 1376 [0]
 258  65,160  3   163405    41.191860173     0  C   W 89391488 + 1376 [0]
 259 ...
 260 Events (sdo): 0 entries, 0 skips
 261
 262 CPU0 (65,160):
 263  Reads Queued:           0,        0KiB  Writes Queued:           9,    5,520KiB
 264  Read Dispatches:        0,        0KiB  Write Dispatches:        0,        0KiB
 265  Reads Completed:        0,        0KiB  Writes Completed:        0,        0KiB
 266  Read Merges:            0               Write Merges:          336
 267  IO unplugs:             0               Timer unplugs:           0
 268 CPU1 (65,160):
 269  Reads Queued:       2,411,   38,576KiB  Writes Queued:         769,  425,408KiB
 270  Read Dispatches:    2,407,   38,512KiB  Write Dispatches:      118,   61,680KiB
 271  Reads Completed:        0,        0KiB  Writes Completed:        0,        0KiB
 272  Read Merges:            0               Write Merges:       25,819
 273  IO unplugs:             0               Timer unplugs:           4
 274 CPU2 (65,160):
 275  Reads Queued:           2,       32KiB  Writes Queued:          18,   10,528KiB
 276  Read Dispatches:        2,       32KiB  Write Dispatches:        3,    1,344KiB
 277  Reads Completed:        0,        0KiB  Writes Completed:        0,        0KiB
 278  Read Merges:            0               Write Merges:          640
 279  IO unplugs:             0               Timer unplugs:           0
 280 CPU3 (65,160):
 281  Reads Queued:      20,572,  329,152KiB  Writes Queued:         594,  279,712KiB
 282  Read Dispatches:   20,576,  329,216KiB  Write Dispatches:    1,474,  740,720KiB
 283  Reads Completed:   22,985,  367,760KiB  Writes Completed:    1,390,  721,168KiB
 284  Read Merges:            0               Write Merges:       16,888
 285  IO unplugs:             0               Timer unplugs:           0
 286
 287 Total (65,160):
 288  Reads Queued:      22,985,  367,760KiB  Writes Queued:       1,390,  721,168KiB
 289  Read Dispatches:   22,985,  367,760KiB  Write Dispatches:    1,595,  803,744KiB
 290  Reads Completed:   22,985,  367,760KiB  Writes Completed:    1,390,  721,168KiB
 291  Read Merges:            0               Write Merges:       43,683
 292  IO unplugs:             0               Timer unplugs:           4
 293 ...
 294 \end{verbatim}
 295
 296 %----------------------------
 297 \newpage\section{\label{sec:blktrace-ug}blktrace User Guide}
 298
 299 The \emph{blktrace} utility extracts event traces from the kernel (via
 300 the relay file system). Some background details concerning the run-time
 301 behaviour of blktrace will help to understand some of the more arcane
 302 command line options:
 303
 304 \begin{itemize}
 305   \item blktrace receives data from the kernel in buffers passed up
 306   through the Relay file system (RelayFS). Each device being traced has
 307   a file created in the mounted directory for the RelayFS, which defaults
 308   to \emph{/relay} -- this can be overridden with the \emph{-r} command
 309   line argument.
 310
 311   \item blktrace defaults to collecting \emph{all} events that can be
 312   traced. To limit the events being captured, you can specify one or
 313   more filter masks via the \emph{-a} option.
 314
 315   Alternatively, one may specify the entire mask utilizing a hexadecimal
 316   value that is version-specific. (Requires understanding of the internal
 317   representation of the filter mask.)
 318
 319   \item As noted above, the events are passed up via a series of buffers
 320   stored into RelayFS files. The size and number of buffers can be
 321   specified via the \emph{-b} and \emph{-n} arguments respectively.
 322
 323   \item blktrace stores the extracted data into files stored in the
 324   \emph{local} directory. The format of the file names is (by default)
 325   \emph{device}.blktrace.\emph{cpu}, where \emph{device} is the base
 326   device name (e.g, if we are tracing /dev/sda, the base device name would
 327   be \emph{sda}); and \emph{cpu} identifies a CPU for the event stream.
 328
 329   The \emph{device} portion of the event file name can be changed via
 330   the \emph{-o} option.
 331
 332   \item blktrace may also be run concurrently with blkparse to produce
 333   \emph{live} output -- to do this specify \emph{-o -} for blktrace.
 334
 335   \item The default behaviour for blktrace is to run forever until explicitly killed by the user (via a control-C, or \emph{kill} utility invocation). There are two ways to modify this:
 336
 337   \begin{enumerate}
 338     \item You may utilize the blktrace utility itself to \emph{kill}
 339     a running trace -- via the \emph{-k} option.
 340
 341     \item You can specify a run-time duration for blktrace via the
 342     \emph{-w} option -- then blktrace will run for the specified number
 343     of seconds, and then halt.
 344   \end{enumerate}
 345 \end{itemize}
 346
 347 \subsection{\label{sec:blktrace-args}Command line arguments}
 348 \begin{tabular}{|l|l|l|}\hline
 349 Short              & Long                       & Description \\ \hline\hline
 350 -A \emph{hex-mask} & --set-mask=\emph{hex-mask} & Set filter mask to \emph{hex-mask} \\ \hline
 351 -a \emph{mask}     & --act-mask=\emph{mask}     & Add \emph{mask} to current filter (see below for masks) \\ \hline
 352 -b \emph{size}     & --buffer-size=\emph{size}  & Specifies buffer size for event extraction (scaled by $2^{10}$) \\ \hline
 353 -d \emph{dev}      & --dev=\emph{dev}           & Adds \emph{dev} as a device to trace \\ \hline
 354 -k                 & --kill                     & Kill on-going trace \\ \hline
 355 -n \emph{num-sub}  & --num-sub=\emph{num-sub}   & Specifies number of buffers to use \\ \hline
 356 -o \emph{file}     & --output=\emph{file}       & Prepend \emph{file} to output file name(s) \\ \hline
 357 -r \emph{rel-path} & --relay=\emph{rel-path}    & Specifies RelayFS mount point \\ \hline
 358 -v                 & --version                  & Outputs version \\ \hline
 359 -w \emph{seconds}  & --stopwatch=\emph{seconds} & Sets run time to the number of seconds specified \\ \hline
 360 \end{tabular}
 361
 362 \subsubsection{\label{sec:filter-mask}Filter Masks}
 363 The following masks may be passed with the \emph{-a} command line
 364 option, multiple filters may be combined via multiple \emph{-a} command
 365 line options.\smallskip
 366
 367 \begin{tabular}{|l|l|}\hline
 368 barrier & \emph{barrier} attribute \\ \hline
 369 complete & \emph{completed} by driver \\ \hline
 370 fs & \emph{FS} requests \\ \hline
 371 issue & \emph{issued} to driver \\ \hline
 372 pc & \emph{packet command} events \\ \hline
 373 queue & \emph{queue} operations \\ \hline
 374 read & \emph{read} traces \\ \hline
 375 requeue & \emph{requeue} operations \\ \hline
 376 sync & \emph{synchronous} attribute \\ \hline
 377 write & \emph{write} traces \\ \hline
 378 \end{tabular}
 379
 380 \subsubsection{\label{sec:request-types}Request types}
 381 blktrace disguingishes between two types of block layer requests,
 382 file system and scsi commands. The former are dubbed \emph{fs}
 383 requests, the latter \emph{pc} requests. File system requests are
 384 normal read/write operations, ie any type of read or write from a
 385 specific disk location at a given size. These requests typically
 386 originate from a user process, but they may also be initiated by
 387 the vm flushing dirty data to disk or the file system syncing
 388 a super or journal block to disk. \emph{pc} requests are SCSI
 389 commands. blktrace sends the command data block as a payload
 390 so that blkparse can decode it.
 391
 392 %----------------------------
 393 \newpage\section{\label{sec:blkparse-ug}blkparse User Guide}
 394
 395 The \emph{blkparse} utility will attempt to combine streams of events
 396 for various devices on various CPUs, and produce a formatted output of
 397 the event information. As with blktrace, some details concerning blkparse
 398 will help in understanding the command line options presented below.
 399
 400 \begin{itemize}
 401   \item By default, blkparse expects to run in a post-processing mode
 402   -- one where the trace events have been saved by a previous run
 403   of blktrace, and blkparse is combining event streams and dumping
 404   formatted data.
 405
 406   blkparse \emph{may} be run in a \emph{live} manner concurrently with
 407   blktrace by specifying \emph{-i -} to blkparse, and combining it with
 408   the live option for blktrace. An example would be:
 409
 410   \begin{verbatim}
 411   % blktrace -d /dev/sda -o - | blkparse -i -
 412   \end{verbatim}
 413
 414   \item You can set how many blkparse batches event reads via the
 415   \emph{-b} option, the default is to handle events in batches of 512.
 416
 417   \item If you have saved event traces in blktrace with different output
 418   names (via the \emph{-o} option to blktrace), you must specify the
 419   same \emph{input} name via the \emph{-i} option.
 420
 421   \item The format of the output data can be controlled via the \emph{-f}
 422   or \emph{-F} options -- see section~\ref{sec:blkparse-format} for details.
 423
 424   By default, blkparse sends formatted data to standard output. This
 425   may be changed via the \emph{-o} option.
 426
 427 \end{itemize}
 428
 429 \newpage\subsection{\label{sec:blkparse-args}Command line arguments}
 430 \begin{tabular}{|l|l|l|}\hline
 431 Short              & Long                       & Description \\ \hline\hline
 432 -b \emph{batch}    & --batch={batch}            & Standard input read batching \\ \hline
 433
 434 -i \emph{file}     & --input=\emph{file}        & Specifies base name for input files -- default is \emph{device}.blktrace.\emph{cpu}. \\
 435                    &                            & As noted above, specifying \emph{-i -} runs in \emph{live} mode with blktrace \\
 436                    &                            & (reading data from standard in). \\ \hline
 437
 438 -F \emph{typ,fmt}  & --format=\emph{typ,fmt}    & Sets output format \\
 439 -f \emph{fmt}      & --format-spec=\emph{fmt}   & (See section~\ref{sec:blkparse-format} for details.) \\
 440                    &                            & \\
 441                    &                            & The -f form specifies a format for all events \\
 442                    &                            & \\
 443                    &                            & The -F form allows one to specify a format for a specific \\
 444                    &                            & event type. The single-character \emph{typ} field is one of the \\
 445                    &                            & action specifiers in section~\ref{sec:act-table} \\ \hline
 446
 447
 448 -m                 & --missing                  & Print missing entries\\ \hline
 449
 450 -n                 & --hash-by-name             & Hash processes by name, not by PID\\ \hline
 451
 452 -o \emph{file}     & --output=\emph{file}       & Output file \\ \hline
 453
 454 -q                 & --quiet                    & Quite mode \\ \hline
 455
 456 -s                 & --per-program-stats        & Displays data sorted by program \\ \hline
 457
 458 -t                 & --track-ios                & Display time deltas per IO \\ \hline
 459
 460 -w \emph{span}     & --stopwatch=\emph{span}    & Display traces for the \emph{span} specified -- where span can be: \\
 461                    &                            & \emph{end-time} -- Display traces from time 0 through \emph{end-time} (in ns) \\
 462                    &                            & or \\
 463                    &                            & \emph{start:end-time} -- Display traces from time \emph{start} \\
 464                    &                            & through {end-time} (in ns). \\ \hline
 465
 466 -v                 & --version                  & Display version \\ \hline
 467
 468 \end{tabular}
 469
 470 \newpage
 471 \subsection{\label{sec:blkparse-actions}Trace actions}
 472
 473 \begin{description}
 474   \item[C -- complete] A previously issued request has been completed.
 475   The output will detail the sector and size of that request, as well
 476   as the success or failure of it.
 477
 478   \item[D -- issued] A request that previously resided on the block layer
 479   queue or in the io scheduler has been sent to the driver.
 480
 481   \item[I -- inserted] A request is being sent to the io scheduler for
 482   addition to the internal queue and later service by the driver. The
 483   request is fully formed at this time.
 484
 485   \item[Q -- queued] This notes intent to queue io at the given location.
 486   No real requests exists yet.
 487
 488   \item[W -- bounced] The data pages attached to this \emph{bio} are
 489   not reachable by the hardware and must be bounced to a lower memory
 490   location. This causes a big slowdown in io performance, since the data
 491   must be copied to/from kernel buffers. Usually this can be fixed with
 492   using better hardware - either a better io controller, or a platform
 493   with an IOMMU.
 494
 495   \item[B -- back merge] A previously inserted request exists that ends
 496   on the boundary of where this io begins, so the io scheduler can merge
 497   them together.
 498
 499   \item[F -- front merge] Same as the back merge, except this io ends
 500   where a previously inserted requests starts.
 501
 502   \item[M -- front or back merge] One of the above.
 503
 504   \item[G -- get request] To send any type of request to a block device,
 505   a \emph{struct request} container must be allocated first.
 506
 507   \item[S -- sleep] No available request structures were available, so
 508   the issuer has to wait for one to be freed.
 509
 510   \item[P -- plug] When io is queued to a previously empty block device
 511   queue, Linux will plug the queue in anticipation of future ios being
 512   added before this data is needed.
 513
 514   \item[U -- unplug] Some request data already queued in the device,
 515   start sending requests to the driver. This may happen automatically
 516   if a timeout period has passed (see next entry) or if a number of
 517   requests have been added to the queue.
 518
 519   \item[T -- unplug due to timer] If nobody requests the io that was queued
 520   after plugging the queue, Linux will automatically unplug it after a
 521   defined period has passed.
 522
 523   \item[X -- split] On raid or device mapper setups, an incoming io may
 524   straddle a device or internal zone and needs to be chopped up into
 525   smaller pieces for service. This may indicate a performance problem due
 526   to a bad setup of that raid/dm device, but may also just be part of
 527   normal boundary conditions. dm is notably bad at this and will clone
 528   lots of io.
 529
 530 \end{description}
 531
 532 \subsection{\label{sec:blkparse-format}Output Description and Formatting}
 533
 534 The output from blkparse can be tailored for specific use - in particular,
 535 to ease parsing of output, and/or limit output fields to those the user
 536 wants to see. The data for fields which can be output include:
 537
 538 \smallskip
 539 \begin{tabular}{|l|l|}\hline
 540 Field    & Description \\
 541 Specifier & \\ \hline\hline
 542 \emph{a} & Action, a (small) string (1 or 2 characters) -- see table below for more details \\ \hline
 543 \emph{c} & CPU id \\ \hline
 544 \emph{C} & Command \\ \hline
 545 \emph{d} & RWBS field, a (small) string (1-3 characters)  -- see section below for more details \\ \hline
 546 \emph{D} & 7-character string containing the major and minor numbers of
 547 the event's device \\
 548          & (separated by a comma). \\ \hline
 549 \emph{e} & Error value \\ \hline
 550 \emph{m} & Minor number of event's device. \\ \hline
 551 \emph{M} & Major number of event's device. \\ \hline
 552 \emph{n} & Number of blocks \\ \hline
 553 \emph{N} & Number of bytes \\ \hline
 554 \emph{p} & Process ID \\ \hline
 555 \emph{P} & Display packet data -- series of hexadecimal values\\ \hline
 556 \emph{s} & Sequence numbers \\ \hline
 557 \emph{S} & Sector number \\ \hline
 558 \emph{t} & Time stamp (nanoseconds) \\ \hline
 559 \emph{T} & Time stamp (seconds) \\ \hline
 560 \emph{u} & Elapsed value in microseconds (\emph{-t} command line option) \\ \hline
 561 \emph{U} & Payload unsigned integer \\ \hline
 562 \end{tabular}
 563
 564 Note that the user can optionally specify field display width, and
 565 optionally a left-aligned specifier. These precede field specifiers,
 566 with a '\%' character, followed by the optional left-alignment specifer
 567 (-) followed by the width (a decimal number) and then the field.
 568
 569 Thus, to specify the command in a 12-character field that is left aligned:
 570
 571 \begin{verbatim}
 572 -f "%-12C"
 573 \end{verbatim}
 574
 575 \newpage
 576 \subsubsection{\label{sec:act-table}Action Table}
 577 The following table shows the various actions which may be output.
 578
 579 \begin{tabular}{|l|l|}\hline
 580 Act & Description \\ \hline\hline
 581 B & IO back merged with request on queue \\ \hline
 582 C & IO completion \\ \hline
 583 D & IO issued to driver \\ \hline
 584 F & IO front merged with request on queue \\ \hline
 585 G & Get request \\ \hline
 586 I & IO inserted onto request queue \\ \hline
 587 P & Plug request \\ \hline
 588 Q & IO handled by request queue code \\ \hline
 589 S & Sleep request \\ \hline
 590 T & Unplug due to timeout \\ \hline
 591 U & Unplug request \\ \hline
 592 W & IO bounced \\ \hline
 593 X & Split \\ \hline
 594 \end{tabular}
 595
 596 \subsubsection{\label{sec:act-table}RWBS Description}
 597 This is a small string containing at least one character ('R' for read,
 598 'W' for write operation), and optionally either a 'B' (for barrier
 599 operations) or 'S' (for synchronous operations).
 600
 601 \subsubsection{\label{sec:default-output}Default output}
 602
 603 The standard \emph{header} (or initial fields displayed) include:
 604
 605 \begin{verbatim}
 606 "%D %2c %8s %5T.%9t %5p %2a %3d "
 607 \end{verbatim}
 608
 609 Breaking this down:
 610
 611 \begin{description}
 612   \item[\%D] Displays the event's device major/minor as: \%3d,\%-3d.
 613   \item[\%2c] CPU ID (2-character field).
 614   \item[\%8s] Sequence number
 615   \item[\%5T.\%9t] 5-charcter field for the seconds portion of the
 616   time stamp and a 9-character field for the nanoseconds in the time stamp.
 617   \item[\%5p] 5-character field for the process ID.
 618   \item[\%2a] 2-character field for one of the actions.
 619   \item[\%3d] 3-character field for the RWBS data.
 620 \end{description}
 621
 622 Seeing this in action:
 623
 624 \begin{verbatim}
 625   8,0    3        1     0.000000000   697  G   W 223490 + 8 [kjournald]
 626 \end{verbatim}
 627
 628 The header is the data in this line up to the 223490 (starting block).
 629
 630 The default output for all event types includes this header.
 631
 632 \paragraph{Default output per action}
 633
 634 \begin{description}
 635   \item[C -- complete] If a payload is present, this is presented between
 636   parenthesis following the header, followed by the error value.
 637
 638   If no payload is present, the sector and number of blocks are presented
 639   (with an intervening plus (+) character). If the \emph{-t} option
 640   was specified, then the elapsed time is presented. In either case,
 641   it is followed by the error value for the completion.
 642
 643   \item[D -- issued]
 644   \item[I -- inserted]
 645   \item[Q -- queued]
 646   \item[W -- bounced] If a payload is present, the number of payload bytes
 647   is output, followed by the payload in hexadecimal between parenthesis.
 648
 649   If no payload is present, the sector and number of blocks are presented
 650   (with an intervening plus (+) character). If the \emph{-t} option was
 651   specified, then the elapsed time is presented (in parenthesis). In
 652   either case, it is followed by the command associated with the event
 653   (surrounded by square brackets).
 654
 655   \item[B -- back merge]
 656   \item[F -- front merge]
 657   \item[G -- get request]
 658   \item[M -- front or back merge]
 659   \item[S -- sleep] The starting sector and number of blocks is output
 660   (with an intervening plus (+) character), followed by the command
 661   associated with the event (surrounded by square brackets).
 662
 663   \item[P -- plug] The command associated with the event (surrounded by
 664   square brackets) is output.
 665
 666   \item[U -- unplug]
 667   \item[T -- unplug due to timer] The command associated with the event
 668   (surrounded by square brackets) is output, followed by the number of
 669   requests outstanding.
 670
 671   \item[X -- split] The original starting sector followed by the new
 672   sector (separated by a slash (/) is output, followed by the command
 673   associated with the event (surrounded by square brackets).
 674
 675 \end{description}
 676
 677 %------------------------------
 678 \newpage
 679 \newpage\section*{\label{sec:blktrace-kg}Appendix: blktrace Kernel Guide}
 680
 681 The blktrace facility provides an efficient event transfer mechanism which
 682 supplies block IO layer state transition data via the relay
 683 filesystem. This section provides some details as to the interfaces
 684 blktrace utilizes in the kernel to effect this. It is good background data
 685 to help understand some of the outputs and command-line options above.
 686
 687 \subsection{blktrace.h Definitions}
 688 Files which include $<linux/blktrace.h>$ are supplied with the following
 689 definitions:
 690
 691 \subsubsection{Trace Action Specifiers}
 692 \begin{tabular}{|l|l|}\hline
 693   BLK\_TA\_QUEUE & (RQ) Command queued to request\_queue. \\
 694                  & (BIO) Command queued by elevator. \\ \hline
 695   BLK\_TA\_BACKMERGE & Back merging elevator operation \\ \hline
 696   BLK\_TA\_FRONTMERGE & Front merging elevator operation \\ \hline
 697   BLK\_TA\_GETRQ & Free request retrieved. \\ \hline
 698   BLK\_TA\_SLEEPRQ & No requests available, device unplugged. \\ \hline
 699   BLK\_TA\_REQUEUE & Request requeued. \\ \hline
 700   BLK\_TA\_ISSUE & Command set to driver for request\_queue. \\ \hline
 701   BLK\_TA\_COMPLETE & Command completed by driver. \\ \hline
 702   BLK\_TA\_PLUG & Device is plugged \\ \hline
 703   BLK\_TA\_UNPLUG\_IO & Unplug device as IO is made available. \\ \hline
 704   BLK\_TA\_UNPLUG\_TIMER & Unplug device after timer expired. \\ \hline
 705   BLK\_TA\_INSERT & Insert request into queue. \\ \hline
 706   BLK\_TA\_SPLIT & BIO split into 2 or more requests. \\ \hline
 707   BLK\_TA\_BOUNCE & BIO was bounced \\ \hline
 708 \end{tabular}
 709
 710 %..........................................
 711 \subsection{blktrace.h Routines}
 712 Files which include $<linux/blktrace.h>$ are supplied with the following
 713 kernel routine invocable interfaces:
 714
 715 \begin{description}
 716   \item[blk\_add\_trace\_rq(struct request\_queue *q, struct request\_queue
 717                                                                 *rq, u32 what)]
 718         Adds a trace event describing the state change of the passed in
 719         request\_queue. The \emph{what} parameter describes the change in
 720         the request\_queue state, and is one of the request queue action
 721         specifiers -- BLK\_TA\_QUEUE, BLK\_TA\_REQUEUE, BLK\_TA\_ISSUE,
 722         or BLK\_TA\_COMPLETE.
 723
 724   \item[blk\_add\_trace\_bio(struct request\_queue *q, struct bio *bio,
 725                                                                 u32 what)]
 726         Adds a trace event for the BIO passed in. The \emph{what} parameter
 727         describes the action being performed on the BIO, and is one of
 728         BLK\_TA\_BACKMERGE, BLK\_TA\_FRONTMERGE, or BLK\_TA\_QUEUE.
 729
 730   \item[blk\_add\_trace\_generic(struct request\_queue *q, struct bio *bio,
 731                                                         int rw, u32 what)]
 732         Adds a \emph{generic} trace event -- not one of the request queue
 733         or BIO traces. The \emph{what} parameter describes the action being
 734         performed on the BIO (if bio is non-NULL), and is one of
 735         BLK\_TA\_PLUG, BLK\_TA\_GETRQ or BLK\_TA\_SLEEPRQ.
 736
 737   \item[blk\_add\_trace\_pdu\_int(struct request\_queue *q, u32 what,
 738                                                                 u32 pdu)]
 739         Adds a trace with some payload data -- in this case, an unsigned
 740         32-bit entity (the \emph{pdu} parameter). The \emph{what} parameter
 741         describes the nature of the payload, and is one of
 742         BLK\_TA\_UNPLUG\_IO or BLK\_TA\_UNPLUG\_TIMER.
 743
 744 \end{description}
 745 \end{document}