| 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 checkout |
| 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 | A \emph{btrace} script is included in the distribution to ease live |
| 185 | tracing of devices. The above could also be accomplished by issuing: |
| 186 | |
| 187 | \begin{verbatim} |
| 188 | % btrace /dev/sda |
| 189 | \end{verbatim} |
| 190 | |
| 191 | By default, \emph{btrace} runs the trace in quiet mode so it will not |
| 192 | include statistics when you break the run. Add the \emph{-S} option to |
| 193 | get that dumped as well. |
| 194 | |
| 195 | \subsection{\label{sec:pc-blktrace}blktrace -- SCSI commands} |
| 196 | |
| 197 | The previous section showed typical file system io actions, but blktrace |
| 198 | can also show SCSI commands going in and out of the queue as submitted |
| 199 | by applications using the SCSI Generic (\emph{sg}) interface. |
| 200 | |
| 201 | \begin{verbatim} |
| 202 | % btrace /dev/cdrom |
| 203 | [...] |
| 204 | 3,0 0 25 0.004884107 13528 G R 0 + 0 [inquiry] |
| 205 | 3,0 0 26 0.004890361 13528 I R 56 (12 00 00 00 38 ..) [inquiry] |
| 206 | 3,0 0 27 0.004891223 13528 P R [inquiry] |
| 207 | 3,0 0 28 0.004893250 13528 D R 56 (12 00 00 00 38 ..) [inquiry] |
| 208 | 3,0 0 29 0.005344910 0 C R (12 00 00 00 38 ..) [0] |
| 209 | \end{verbatim} |
| 210 | |
| 211 | Here we see a program issuing an INQUIRY command to the CDROM device. |
| 212 | The program requested a read of 56 bytes of data, the CDB is included |
| 213 | in parenthesis after the data length. The completion event shows shows |
| 214 | that the command completed successfully. Tracing SCSI commands can be |
| 215 | very useful for debugging problems with programs talking directly to the |
| 216 | device. An example of that would be \emph{cdrecord} burning. |
| 217 | |
| 218 | \subsection{\label{sec:blktrace-post}blktrace -- post-processing} |
| 219 | |
| 220 | Another way to run blktrace is to have blktrace save data away for later |
| 221 | formatting by blkparse. This would be useful if you want to get |
| 222 | measurements while running specific loads. |
| 223 | |
| 224 | To do this, one would specify the device (or devices) to be watched. Then |
| 225 | go run you test cases. Stop the trace, and at your leisure utilize |
| 226 | blkparse to see the results. |
| 227 | |
| 228 | In this example, devices /dev/sdaa, /dev/sdc and /dev/sdo are used in an |
| 229 | LVM volume called adb3/vol. |
| 230 | |
| 231 | \begin{verbatim} |
| 232 | % blktrace /dev/sdaa /dev/sdc /dev/sdo & |
| 233 | [1] 9713 |
| 234 | % |
| 235 | % mkfs -t ext3 /dev/adb3/vol |
| 236 | mke2fs 1.35 (28-Feb-2004) |
| 237 | Filesystem label= |
| 238 | OS type: Linux |
| 239 | Block size=4096 (log=2) |
| 240 | Fragment size=4096 (log=2) |
| 241 | 16793600 inodes, 33555456 blocks |
| 242 | 1677772 blocks (5.00%) reserved for the super user |
| 243 | First data block=0 |
| 244 | Maximum filesystem blocks=4294967296 |
| 245 | 1025 block groups |
| 246 | 32768 blocks per group, 32768 fragments per group |
| 247 | 16384 inodes per group |
| 248 | Superblock backups stored on blocks: |
| 249 | 32768, 98304, 163840, 229376, 294912, 819200, 884736, 1605632, 2654208, |
| 250 | 4096000, 7962624, 11239424, 20480000, 23887872 |
| 251 | |
| 252 | Writing inode tables: done |
| 253 | Creating journal (8192 blocks): done |
| 254 | Writing superblocks and filesystem accounting information: done |
| 255 | |
| 256 | This filesystem will be automatically checked every 27 mounts or |
| 257 | 180 days, whichever comes first. Use tune2fs -c or -i to override. |
| 258 | % |
| 259 | % kill -15 9713 |
| 260 | \end{verbatim} |
| 261 | |
| 262 | Then you could process the events later: |
| 263 | |
| 264 | \begin{verbatim} |
| 265 | % |
| 266 | % blkparse sdaa sdc sdo > events |
| 267 | % less events |
| 268 | 8,32 1 1 0.000000000 9728 G R 384 + 32 [mkfs.ext3] |
| 269 | 8,32 1 2 0.000001959 9728 P R [mkfs.ext3] |
| 270 | 8,32 1 3 0.000002446 9728 Q R 384 + 32 [mkfs.ext3] |
| 271 | 8,32 1 4 0.000005110 9728 D R 384 + 32 [mkfs.ext3] |
| 272 | 8,32 3 5 0.000200570 0 C R 384 + 32 [0] |
| 273 | 8,224 3 1 0.021658989 9728 G R 384 + 32 [mkfs.ext3] |
| 274 | ... |
| 275 | 65,160 3 163392 41.117070504 0 C W 87469088 + 1376 [0] |
| 276 | 8,32 3 163374 41.122683668 0 C W 88168160 + 1376 [0] |
| 277 | 65,160 3 163393 41.129952433 0 C W 87905984 + 1376 [0] |
| 278 | 65,160 3 163394 41.130049431 0 D W 89129344 + 1376 [swapper] |
| 279 | 65,160 3 163395 41.130067135 0 D W 89216704 + 1376 [swapper] |
| 280 | 65,160 3 163396 41.130083785 0 D W 89304096 + 1376 [swapper] |
| 281 | 65,160 3 163397 41.130099455 0 D W 89391488 + 1376 [swapper] |
| 282 | 65,160 3 163398 41.130114732 0 D W 89478848 + 1376 [swapper] |
| 283 | 65,160 3 163399 41.130128885 0 D W 89481536 + 64 [swapper] |
| 284 | 8,32 3 163375 41.134758196 0 C W 86333152 + 1376 [0] |
| 285 | 65,160 3 163400 41.142229726 0 C W 89129344 + 1376 [0] |
| 286 | 65,160 3 163401 41.144952314 0 C W 89481536 + 64 [0] |
| 287 | 8,32 3 163376 41.147441930 0 C W 88342912 + 1376 [0] |
| 288 | 65,160 3 163402 41.155869604 0 C W 89478848 + 1376 [0] |
| 289 | 8,32 3 163377 41.159466082 0 C W 86245760 + 1376 [0] |
| 290 | 65,160 3 163403 41.166944976 0 C W 89216704 + 1376 [0] |
| 291 | 65,160 3 163404 41.178968252 0 C W 89304096 + 1376 [0] |
| 292 | 65,160 3 163405 41.191860173 0 C W 89391488 + 1376 [0] |
| 293 | ... |
| 294 | Events (sdo): 0 entries, 0 skips |
| 295 | |
| 296 | CPU0 (65,160): |
| 297 | Reads Queued: 0, 0KiB Writes Queued: 9, 5,520KiB |
| 298 | Read Dispatches: 0, 0KiB Write Dispatches: 0, 0KiB |
| 299 | Reads Completed: 0, 0KiB Writes Completed: 0, 0KiB |
| 300 | Read Merges: 0 Write Merges: 336 |
| 301 | IO unplugs: 0 Timer unplugs: 0 |
| 302 | CPU1 (65,160): |
| 303 | Reads Queued: 2,411, 38,576KiB Writes Queued: 769, 425,408KiB |
| 304 | Read Dispatches: 2,407, 38,512KiB Write Dispatches: 118, 61,680KiB |
| 305 | Reads Completed: 0, 0KiB Writes Completed: 0, 0KiB |
| 306 | Read Merges: 0 Write Merges: 25,819 |
| 307 | IO unplugs: 0 Timer unplugs: 4 |
| 308 | CPU2 (65,160): |
| 309 | Reads Queued: 2, 32KiB Writes Queued: 18, 10,528KiB |
| 310 | Read Dispatches: 2, 32KiB Write Dispatches: 3, 1,344KiB |
| 311 | Reads Completed: 0, 0KiB Writes Completed: 0, 0KiB |
| 312 | Read Merges: 0 Write Merges: 640 |
| 313 | IO unplugs: 0 Timer unplugs: 0 |
| 314 | CPU3 (65,160): |
| 315 | Reads Queued: 20,572, 329,152KiB Writes Queued: 594, 279,712KiB |
| 316 | Read Dispatches: 20,576, 329,216KiB Write Dispatches: 1,474, 740,720KiB |
| 317 | Reads Completed: 22,985, 367,760KiB Writes Completed: 1,390, 721,168KiB |
| 318 | Read Merges: 0 Write Merges: 16,888 |
| 319 | IO unplugs: 0 Timer unplugs: 0 |
| 320 | |
| 321 | Total (65,160): |
| 322 | Reads Queued: 22,985, 367,760KiB Writes Queued: 1,390, 721,168KiB |
| 323 | Read Dispatches: 22,985, 367,760KiB Write Dispatches: 1,595, 803,744KiB |
| 324 | Reads Completed: 22,985, 367,760KiB Writes Completed: 1,390, 721,168KiB |
| 325 | Read Merges: 0 Write Merges: 43,683 |
| 326 | IO unplugs: 0 Timer unplugs: 4 |
| 327 | ... |
| 328 | \end{verbatim} |
| 329 | |
| 330 | %---------------------------- |
| 331 | \newpage\section{\label{sec:blktrace-ug}blktrace User Guide} |
| 332 | |
| 333 | The \emph{blktrace} utility extracts event traces from the kernel (via |
| 334 | the relay file system). Some background details concerning the run-time |
| 335 | behaviour of blktrace will help to understand some of the more arcane |
| 336 | command line options: |
| 337 | |
| 338 | \begin{itemize} |
| 339 | \item blktrace receives data from the kernel in buffers passed up |
| 340 | through the Relay file system (RelayFS). Each device being traced has |
| 341 | a file created in the mounted directory for the RelayFS, which defaults |
| 342 | to \emph{/relay} -- this can be overridden with the \emph{-r} command |
| 343 | line argument. |
| 344 | |
| 345 | \item blktrace defaults to collecting \emph{all} events that can be |
| 346 | traced. To limit the events being captured, you can specify one or |
| 347 | more filter masks via the \emph{-a} option. |
| 348 | |
| 349 | Alternatively, one may specify the entire mask utilizing a hexadecimal |
| 350 | value that is version-specific. (Requires understanding of the internal |
| 351 | representation of the filter mask.) |
| 352 | |
| 353 | \item As noted above, the events are passed up via a series of buffers |
| 354 | stored into RelayFS files. The size and number of buffers can be |
| 355 | specified via the \emph{-b} and \emph{-n} arguments respectively. |
| 356 | |
| 357 | \item blktrace stores the extracted data into files stored in the |
| 358 | \emph{local} directory. The format of the file names is (by default) |
| 359 | \emph{device}.blktrace.\emph{cpu}, where \emph{device} is the base |
| 360 | device name (e.g, if we are tracing /dev/sda, the base device name would |
| 361 | be \emph{sda}); and \emph{cpu} identifies a CPU for the event stream. |
| 362 | |
| 363 | The \emph{device} portion of the event file name can be changed via |
| 364 | the \emph{-o} option. |
| 365 | |
| 366 | \item blktrace may also be run concurrently with blkparse to produce |
| 367 | \emph{live} output -- to do this specify \emph{-o -} for blktrace. |
| 368 | |
| 369 | \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: |
| 370 | |
| 371 | \begin{enumerate} |
| 372 | \item You may utilize the blktrace utility itself to \emph{kill} |
| 373 | a running trace -- via the \emph{-k} option. |
| 374 | |
| 375 | \item You can specify a run-time duration for blktrace via the |
| 376 | \emph{-w} option -- then blktrace will run for the specified number |
| 377 | of seconds, and then halt. |
| 378 | \end{enumerate} |
| 379 | \end{itemize} |
| 380 | |
| 381 | \subsection{\label{sec:blktrace-args}Command line arguments} |
| 382 | \begin{tabular}{|l|l|l|}\hline |
| 383 | Short & Long & Description \\ \hline\hline |
| 384 | -A \emph{hex-mask} & --set-mask=\emph{hex-mask} & Set filter mask to \emph{hex-mask} \\ \hline |
| 385 | -a \emph{mask} & --act-mask=\emph{mask} & Add \emph{mask} to current filter (see below for masks) \\ \hline |
| 386 | -b \emph{size} & --buffer-size=\emph{size} & Specifies buffer size for event extraction (scaled by $2^{10}$) \\ \hline |
| 387 | -d \emph{dev} & --dev=\emph{dev} & Adds \emph{dev} as a device to trace \\ \hline |
| 388 | -k & --kill & Kill on-going trace \\ \hline |
| 389 | -n \emph{num-sub} & --num-sub=\emph{num-sub} & Specifies number of buffers to use \\ \hline |
| 390 | -o \emph{file} & --output=\emph{file} & Prepend \emph{file} to output file name(s) \\ \hline |
| 391 | -r \emph{rel-path} & --relay=\emph{rel-path} & Specifies RelayFS mount point \\ \hline |
| 392 | -v & --version & Outputs version \\ \hline |
| 393 | -w \emph{seconds} & --stopwatch=\emph{seconds} & Sets run time to the number of seconds specified \\ \hline |
| 394 | \end{tabular} |
| 395 | |
| 396 | \subsubsection{\label{sec:filter-mask}Filter Masks} |
| 397 | The following masks may be passed with the \emph{-a} command line |
| 398 | option, multiple filters may be combined via multiple \emph{-a} command |
| 399 | line options.\smallskip |
| 400 | |
| 401 | \begin{tabular}{|l|l|}\hline |
| 402 | barrier & \emph{barrier} attribute \\ \hline |
| 403 | complete & \emph{completed} by driver \\ \hline |
| 404 | fs & \emph{FS} requests \\ \hline |
| 405 | issue & \emph{issued} to driver \\ \hline |
| 406 | pc & \emph{packet command} events \\ \hline |
| 407 | queue & \emph{queue} operations \\ \hline |
| 408 | read & \emph{read} traces \\ \hline |
| 409 | requeue & \emph{requeue} operations \\ \hline |
| 410 | sync & \emph{synchronous} attribute \\ \hline |
| 411 | write & \emph{write} traces \\ \hline |
| 412 | \end{tabular} |
| 413 | |
| 414 | \subsubsection{\label{sec:request-types}Request types} |
| 415 | blktrace disguingishes between two types of block layer requests, |
| 416 | file system and scsi commands. The former are dubbed \emph{fs} |
| 417 | requests, the latter \emph{pc} requests. File system requests are |
| 418 | normal read/write operations, ie any type of read or write from a |
| 419 | specific disk location at a given size. These requests typically |
| 420 | originate from a user process, but they may also be initiated by |
| 421 | the vm flushing dirty data to disk or the file system syncing |
| 422 | a super or journal block to disk. \emph{pc} requests are SCSI |
| 423 | commands. blktrace sends the command data block as a payload |
| 424 | so that blkparse can decode it. |
| 425 | |
| 426 | %---------------------------- |
| 427 | \newpage\section{\label{sec:blkparse-ug}blkparse User Guide} |
| 428 | |
| 429 | The \emph{blkparse} utility will attempt to combine streams of events |
| 430 | for various devices on various CPUs, and produce a formatted output of |
| 431 | the event information. As with blktrace, some details concerning blkparse |
| 432 | will help in understanding the command line options presented below. |
| 433 | |
| 434 | \begin{itemize} |
| 435 | \item By default, blkparse expects to run in a post-processing mode |
| 436 | -- one where the trace events have been saved by a previous run |
| 437 | of blktrace, and blkparse is combining event streams and dumping |
| 438 | formatted data. |
| 439 | |
| 440 | blkparse \emph{may} be run in a \emph{live} manner concurrently with |
| 441 | blktrace by specifying \emph{-i -} to blkparse, and combining it with |
| 442 | the live option for blktrace. An example would be: |
| 443 | |
| 444 | \begin{verbatim} |
| 445 | % blktrace -d /dev/sda -o - | blkparse -i - |
| 446 | \end{verbatim} |
| 447 | |
| 448 | \item You can set how many blkparse batches event reads via the |
| 449 | \emph{-b} option, the default is to handle events in batches of 512. |
| 450 | |
| 451 | \item If you have saved event traces in blktrace with different output |
| 452 | names (via the \emph{-o} option to blktrace), you must specify the |
| 453 | same \emph{input} name via the \emph{-i} option. |
| 454 | |
| 455 | \item The format of the output data can be controlled via the \emph{-f} |
| 456 | or \emph{-F} options -- see section~\ref{sec:blkparse-format} for details. |
| 457 | |
| 458 | By default, blkparse sends formatted data to standard output. This |
| 459 | may be changed via the \emph{-o} option. |
| 460 | |
| 461 | \end{itemize} |
| 462 | |
| 463 | \newpage\subsection{\label{sec:blkparse-args}Command line arguments} |
| 464 | \begin{tabular}{|l|l|l|}\hline |
| 465 | Short & Long & Description \\ \hline\hline |
| 466 | -b \emph{batch} & --batch={batch} & Standard input read batching \\ \hline |
| 467 | |
| 468 | -i \emph{file} & --input=\emph{file} & Specifies base name for input files -- default is \emph{device}.blktrace.\emph{cpu}. \\ |
| 469 | & & As noted above, specifying \emph{-i -} runs in \emph{live} mode with blktrace \\ |
| 470 | & & (reading data from standard in). \\ \hline |
| 471 | |
| 472 | -F \emph{typ,fmt} & --format=\emph{typ,fmt} & Sets output format \\ |
| 473 | -f \emph{fmt} & --format-spec=\emph{fmt} & (See section~\ref{sec:blkparse-format} for details.) \\ |
| 474 | & & \\ |
| 475 | & & The -f form specifies a format for all events \\ |
| 476 | & & \\ |
| 477 | & & The -F form allows one to specify a format for a specific \\ |
| 478 | & & event type. The single-character \emph{typ} field is one of the \\ |
| 479 | & & action specifiers in section~\ref{sec:act-table} \\ \hline |
| 480 | |
| 481 | |
| 482 | -m & --missing & Print missing entries\\ \hline |
| 483 | |
| 484 | -n & --hash-by-name & Hash processes by name, not by PID\\ \hline |
| 485 | |
| 486 | -o \emph{file} & --output=\emph{file} & Output file \\ \hline |
| 487 | |
| 488 | -q & --quiet & Quite mode \\ \hline |
| 489 | |
| 490 | -s & --per-program-stats & Displays data sorted by program \\ \hline |
| 491 | |
| 492 | -t & --track-ios & Display time deltas per IO \\ \hline |
| 493 | |
| 494 | -w \emph{span} & --stopwatch=\emph{span} & Display traces for the \emph{span} specified -- where span can be: \\ |
| 495 | & & \emph{end-time} -- Display traces from time 0 through \emph{end-time} (in ns) \\ |
| 496 | & & or \\ |
| 497 | & & \emph{start:end-time} -- Display traces from time \emph{start} \\ |
| 498 | & & through {end-time} (in ns). \\ \hline |
| 499 | |
| 500 | -v & --version & Display version \\ \hline |
| 501 | |
| 502 | \end{tabular} |
| 503 | |
| 504 | \newpage |
| 505 | \subsection{\label{sec:blkparse-actions}Trace actions} |
| 506 | |
| 507 | \begin{description} |
| 508 | \item[C -- complete] A previously issued request has been completed. |
| 509 | The output will detail the sector and size of that request, as well |
| 510 | as the success or failure of it. |
| 511 | |
| 512 | \item[D -- issued] A request that previously resided on the block layer |
| 513 | queue or in the io scheduler has been sent to the driver. |
| 514 | |
| 515 | \item[I -- inserted] A request is being sent to the io scheduler for |
| 516 | addition to the internal queue and later service by the driver. The |
| 517 | request is fully formed at this time. |
| 518 | |
| 519 | \item[Q -- queued] This notes intent to queue io at the given location. |
| 520 | No real requests exists yet. |
| 521 | |
| 522 | \item[W -- bounced] The data pages attached to this \emph{bio} are |
| 523 | not reachable by the hardware and must be bounced to a lower memory |
| 524 | location. This causes a big slowdown in io performance, since the data |
| 525 | must be copied to/from kernel buffers. Usually this can be fixed with |
| 526 | using better hardware - either a better io controller, or a platform |
| 527 | with an IOMMU. |
| 528 | |
| 529 | \item[B -- back merge] A previously inserted request exists that ends |
| 530 | on the boundary of where this io begins, so the io scheduler can merge |
| 531 | them together. |
| 532 | |
| 533 | \item[F -- front merge] Same as the back merge, except this io ends |
| 534 | where a previously inserted requests starts. |
| 535 | |
| 536 | \item[M -- front or back merge] One of the above. |
| 537 | |
| 538 | \item[G -- get request] To send any type of request to a block device, |
| 539 | a \emph{struct request} container must be allocated first. |
| 540 | |
| 541 | \item[S -- sleep] No available request structures were available, so |
| 542 | the issuer has to wait for one to be freed. |
| 543 | |
| 544 | \item[P -- plug] When io is queued to a previously empty block device |
| 545 | queue, Linux will plug the queue in anticipation of future ios being |
| 546 | added before this data is needed. |
| 547 | |
| 548 | \item[U -- unplug] Some request data already queued in the device, |
| 549 | start sending requests to the driver. This may happen automatically |
| 550 | if a timeout period has passed (see next entry) or if a number of |
| 551 | requests have been added to the queue. |
| 552 | |
| 553 | \item[T -- unplug due to timer] If nobody requests the io that was queued |
| 554 | after plugging the queue, Linux will automatically unplug it after a |
| 555 | defined period has passed. |
| 556 | |
| 557 | \item[X -- split] On raid or device mapper setups, an incoming io may |
| 558 | straddle a device or internal zone and needs to be chopped up into |
| 559 | smaller pieces for service. This may indicate a performance problem due |
| 560 | to a bad setup of that raid/dm device, but may also just be part of |
| 561 | normal boundary conditions. dm is notably bad at this and will clone |
| 562 | lots of io. |
| 563 | |
| 564 | \item[A -- remap] For stacked devices, incoming io is remapped to device |
| 565 | below it in the io stack. The remap action details what exactly is |
| 566 | being remapped to what. |
| 567 | |
| 568 | \end{description} |
| 569 | |
| 570 | \subsection{\label{sec:blkparse-format}Output Description and Formatting} |
| 571 | |
| 572 | The output from blkparse can be tailored for specific use - in particular, |
| 573 | to ease parsing of output, and/or limit output fields to those the user |
| 574 | wants to see. The data for fields which can be output include: |
| 575 | |
| 576 | \smallskip |
| 577 | \begin{tabular}{|l|l|}\hline |
| 578 | Field & Description \\ |
| 579 | Specifier & \\ \hline\hline |
| 580 | \emph{a} & Action, a (small) string (1 or 2 characters) -- see table below for more details \\ \hline |
| 581 | \emph{c} & CPU id \\ \hline |
| 582 | \emph{C} & Command \\ \hline |
| 583 | \emph{d} & RWBS field, a (small) string (1-3 characters) -- see section below for more details \\ \hline |
| 584 | \emph{D} & 7-character string containing the major and minor numbers of |
| 585 | the event's device \\ |
| 586 | & (separated by a comma). \\ \hline |
| 587 | \emph{e} & Error value \\ \hline |
| 588 | \emph{m} & Minor number of event's device. \\ \hline |
| 589 | \emph{M} & Major number of event's device. \\ \hline |
| 590 | \emph{n} & Number of blocks \\ \hline |
| 591 | \emph{N} & Number of bytes \\ \hline |
| 592 | \emph{p} & Process ID \\ \hline |
| 593 | \emph{P} & Display packet data -- series of hexadecimal values\\ \hline |
| 594 | \emph{s} & Sequence numbers \\ \hline |
| 595 | \emph{S} & Sector number \\ \hline |
| 596 | \emph{t} & Time stamp (nanoseconds) \\ \hline |
| 597 | \emph{T} & Time stamp (seconds) \\ \hline |
| 598 | \emph{u} & Elapsed value in microseconds (\emph{-t} command line option) \\ \hline |
| 599 | \emph{U} & Payload unsigned integer \\ \hline |
| 600 | \end{tabular} |
| 601 | |
| 602 | Note that the user can optionally specify field display width, and |
| 603 | optionally a left-aligned specifier. These precede field specifiers, |
| 604 | with a '\%' character, followed by the optional left-alignment specifer |
| 605 | (-) followed by the width (a decimal number) and then the field. |
| 606 | |
| 607 | Thus, to specify the command in a 12-character field that is left aligned: |
| 608 | |
| 609 | \begin{verbatim} |
| 610 | -f "%-12C" |
| 611 | \end{verbatim} |
| 612 | |
| 613 | \newpage |
| 614 | \subsubsection{\label{sec:act-table}Action Table} |
| 615 | The following table shows the various actions which may be output. |
| 616 | |
| 617 | \begin{tabular}{|l|l|}\hline |
| 618 | Act & Description \\ \hline\hline |
| 619 | A & IO was remapped to a different device \\ \hline |
| 620 | B & IO back merged with request on queue \\ \hline |
| 621 | C & IO completion \\ \hline |
| 622 | D & IO issued to driver \\ \hline |
| 623 | F & IO front merged with request on queue \\ \hline |
| 624 | G & Get request \\ \hline |
| 625 | I & IO inserted onto request queue \\ \hline |
| 626 | P & Plug request \\ \hline |
| 627 | Q & IO handled by request queue code \\ \hline |
| 628 | S & Sleep request \\ \hline |
| 629 | T & Unplug due to timeout \\ \hline |
| 630 | U & Unplug request \\ \hline |
| 631 | W & IO bounced \\ \hline |
| 632 | X & Split \\ \hline |
| 633 | \end{tabular} |
| 634 | |
| 635 | \subsubsection{\label{sec:act-table}RWBS Description} |
| 636 | This is a small string containing at least one character ('R' for read, |
| 637 | 'W' for write operation), and optionally either a 'B' (for barrier |
| 638 | operations) or 'S' (for synchronous operations). |
| 639 | |
| 640 | \subsubsection{\label{sec:default-output}Default output} |
| 641 | |
| 642 | The standard \emph{header} (or initial fields displayed) include: |
| 643 | |
| 644 | \begin{verbatim} |
| 645 | "%D %2c %8s %5T.%9t %5p %2a %3d " |
| 646 | \end{verbatim} |
| 647 | |
| 648 | Breaking this down: |
| 649 | |
| 650 | \begin{description} |
| 651 | \item[\%D] Displays the event's device major/minor as: \%3d,\%-3d. |
| 652 | \item[\%2c] CPU ID (2-character field). |
| 653 | \item[\%8s] Sequence number |
| 654 | \item[\%5T.\%9t] 5-charcter field for the seconds portion of the |
| 655 | time stamp and a 9-character field for the nanoseconds in the time stamp. |
| 656 | \item[\%5p] 5-character field for the process ID. |
| 657 | \item[\%2a] 2-character field for one of the actions. |
| 658 | \item[\%3d] 3-character field for the RWBS data. |
| 659 | \end{description} |
| 660 | |
| 661 | Seeing this in action: |
| 662 | |
| 663 | \begin{verbatim} |
| 664 | 8,0 3 1 0.000000000 697 G W 223490 + 8 [kjournald] |
| 665 | \end{verbatim} |
| 666 | |
| 667 | The header is the data in this line up to the 223490 (starting block). |
| 668 | |
| 669 | The default output for all event types includes this header. |
| 670 | |
| 671 | \paragraph{Default output per action} |
| 672 | |
| 673 | \begin{description} |
| 674 | \item[C -- complete] If a payload is present, this is presented between |
| 675 | parenthesis following the header, followed by the error value. |
| 676 | |
| 677 | If no payload is present, the sector and number of blocks are presented |
| 678 | (with an intervening plus (+) character). If the \emph{-t} option |
| 679 | was specified, then the elapsed time is presented. In either case, |
| 680 | it is followed by the error value for the completion. |
| 681 | |
| 682 | \item[D -- issued] |
| 683 | \item[I -- inserted] |
| 684 | \item[Q -- queued] |
| 685 | \item[W -- bounced] If a payload is present, the number of payload bytes |
| 686 | is output, followed by the payload in hexadecimal between parenthesis. |
| 687 | |
| 688 | If no payload is present, the sector and number of blocks are presented |
| 689 | (with an intervening plus (+) character). If the \emph{-t} option was |
| 690 | specified, then the elapsed time is presented (in parenthesis). In |
| 691 | either case, it is followed by the command associated with the event |
| 692 | (surrounded by square brackets). |
| 693 | |
| 694 | \item[B -- back merge] |
| 695 | \item[F -- front merge] |
| 696 | \item[G -- get request] |
| 697 | \item[M -- front or back merge] |
| 698 | \item[S -- sleep] The starting sector and number of blocks is output |
| 699 | (with an intervening plus (+) character), followed by the command |
| 700 | associated with the event (surrounded by square brackets). |
| 701 | |
| 702 | \item[P -- plug] The command associated with the event (surrounded by |
| 703 | square brackets) is output. |
| 704 | |
| 705 | \item[U -- unplug] |
| 706 | \item[T -- unplug due to timer] The command associated with the event |
| 707 | (surrounded by square brackets) is output, followed by the number of |
| 708 | requests outstanding. |
| 709 | |
| 710 | \item[X -- split] The original starting sector followed by the new |
| 711 | sector (separated by a slash (/) is output, followed by the command |
| 712 | associated with the event (surrounded by square brackets). |
| 713 | |
| 714 | \item[A -- remap] Sector and length is output, along with the original |
| 715 | device and sector offset. |
| 716 | |
| 717 | \end{description} |
| 718 | |
| 719 | %------------------------------ |
| 720 | \newpage |
| 721 | \newpage\section*{\label{sec:blktrace-kg}Appendix: blktrace Kernel Guide} |
| 722 | |
| 723 | The blktrace facility provides an efficient event transfer mechanism which |
| 724 | supplies block IO layer state transition data via the relay |
| 725 | filesystem. This section provides some details as to the interfaces |
| 726 | blktrace utilizes in the kernel to effect this. It is good background data |
| 727 | to help understand some of the outputs and command-line options above. |
| 728 | |
| 729 | \subsection{blktrace.h Definitions} |
| 730 | Files which include $<linux/blktrace.h>$ are supplied with the following |
| 731 | definitions: |
| 732 | |
| 733 | \subsubsection{Trace Action Specifiers} |
| 734 | \begin{tabular}{|l|l|}\hline |
| 735 | BLK\_TA\_QUEUE & (RQ) Command queued to request\_queue. \\ |
| 736 | & (BIO) Command queued by elevator. \\ \hline |
| 737 | BLK\_TA\_BACKMERGE & Back merging elevator operation \\ \hline |
| 738 | BLK\_TA\_FRONTMERGE & Front merging elevator operation \\ \hline |
| 739 | BLK\_TA\_GETRQ & Free request retrieved. \\ \hline |
| 740 | BLK\_TA\_SLEEPRQ & No requests available, device unplugged. \\ \hline |
| 741 | BLK\_TA\_REQUEUE & Request requeued. \\ \hline |
| 742 | BLK\_TA\_ISSUE & Command set to driver for request\_queue. \\ \hline |
| 743 | BLK\_TA\_COMPLETE & Command completed by driver. \\ \hline |
| 744 | BLK\_TA\_PLUG & Device is plugged \\ \hline |
| 745 | BLK\_TA\_UNPLUG\_IO & Unplug device as IO is made available. \\ \hline |
| 746 | BLK\_TA\_UNPLUG\_TIMER & Unplug device after timer expired. \\ \hline |
| 747 | BLK\_TA\_INSERT & Insert request into queue. \\ \hline |
| 748 | BLK\_TA\_SPLIT & BIO split into 2 or more requests. \\ \hline |
| 749 | BLK\_TA\_BOUNCE & BIO was bounced \\ \hline |
| 750 | BLK\_TA\_REMAP & BIO was remapped \\ \hline |
| 751 | \end{tabular} |
| 752 | |
| 753 | %.......................................... |
| 754 | \subsection{blktrace.h Routines} |
| 755 | Files which include $<linux/blktrace.h>$ are supplied with the following |
| 756 | kernel routine invocable interfaces: |
| 757 | |
| 758 | \begin{description} |
| 759 | \item[blk\_add\_trace\_rq(struct request\_queue *q, struct request\_queue |
| 760 | *rq, u32 what)] |
| 761 | Adds a trace event describing the state change of the passed in |
| 762 | request\_queue. The \emph{what} parameter describes the change in |
| 763 | the request\_queue state, and is one of the request queue action |
| 764 | specifiers -- BLK\_TA\_QUEUE, BLK\_TA\_REQUEUE, BLK\_TA\_ISSUE, |
| 765 | or BLK\_TA\_COMPLETE. |
| 766 | |
| 767 | \item[blk\_add\_trace\_bio(struct request\_queue *q, struct bio *bio, |
| 768 | u32 what)] |
| 769 | Adds a trace event for the BIO passed in. The \emph{what} parameter |
| 770 | describes the action being performed on the BIO, and is one of |
| 771 | BLK\_TA\_BACKMERGE, BLK\_TA\_FRONTMERGE, or BLK\_TA\_QUEUE. |
| 772 | |
| 773 | \item[blk\_add\_trace\_generic(struct request\_queue *q, struct bio *bio, |
| 774 | int rw, u32 what)] |
| 775 | Adds a \emph{generic} trace event -- not one of the request queue |
| 776 | or BIO traces. The \emph{what} parameter describes the action being |
| 777 | performed on the BIO (if bio is non-NULL), and is one of |
| 778 | BLK\_TA\_PLUG, BLK\_TA\_GETRQ or BLK\_TA\_SLEEPRQ. |
| 779 | |
| 780 | \item[blk\_add\_trace\_pdu\_int(struct request\_queue *q, u32 what, |
| 781 | u32 pdu)] |
| 782 | Adds a trace with some payload data -- in this case, an unsigned |
| 783 | 32-bit entity (the \emph{pdu} parameter). The \emph{what} parameter |
| 784 | describes the nature of the payload, and is one of |
| 785 | BLK\_TA\_UNPLUG\_IO or BLK\_TA\_UNPLUG\_TIMER. |
| 786 | |
| 787 | \item[blk\_add\_trace\_remap(struct request\_queue *q, struct bio *bio, |
| 788 | dev\_t dev, sector\_t sector)] |
| 789 | Adds a trace with a remap event. \emph{dev} and \emph{sector} denote |
| 790 | the original device this \emph{bio} was mapped from. |
| 791 | |
| 792 | |
| 793 | \end{description} |
| 794 | \end{document} |