# I/O Profiling Linux provide extensive kernel profiling capabilities, including the ability to trace operations at the block I/O layer. These tools are incredibly powerful, though sometimes overwhelming in their flexibility. This document captures some common recipes for profiling Linux I/O. * [Perf](#perf) * [Blktrace](#blktrace) ## Perf The Linux `perf` command can instrument CPU performance counters, and the extensive set of kernel trace points. A great place to get started understanding `perf` are Brendan Gregg's [perf examples](http://www.brendangregg.com/perf.html). The two modes of operation are "live" reporting via `perf top`, and record and report via `perf record` and `perf {report,script}`. Recording the stack traces for `block:block_rq_insert` event allows determination of what Pebble level code is generating block requests. ### Installation Ubuntu AWS installation: ``` sudo apt-get install linux-tools-common linux-tools-4.4.0-1049-aws linux-cloud-tools-4.4.0-1049-aws ``` ### Recording `perf record` (and `perf top`) requires read and write access to `/sys/kernel/debug/tracing`. Running as root as an easiest way to get the right permissions. ``` # Trace all block device (disk I/O) requests with stack traces, until Ctrl-C. sudo perf record -e block:block_rq_insert -ag # Trace all block device (disk I/O) issues and completions with stack traces, until Ctrl-C. sudo perf record -e block:block_rq_issue -e block:block_rq_complete -ag ``` The `-a` flag records events on all CPUs (almost always desirable). The `-g` flag records call graphs (a.k.a stack traces). Capturing the stack trace makes the recording somewhat more expensive, but it enables determining the originator of the event. Note the stack traces include both the kernel and application code, allowing pinpointing the source of I/O as due to flush, compaction, WAL writes, etc. The `-e` flag controls which events are instrumented. The list of `perf` events is enormous. See `sudo perf list`. The `-o` flag controls where output is recorded. The default is `perf.data`. In order to record events for a specific duration, you can append `-- sleep ` to the command line. ``` # Trace all block device (disk I/O) requests with stack traces for 10s. sudo perf record -e block:block_rq_insert -ag -- sleep 10 ``` ### Reporting The recorded perf data (`perf.data`) can be explored using `perf report` and `perf script`. ``` # Show perf.data in an ncurses browser. sudo perf report # Show perf.data as a text report. sudo perf report --stdio ``` As an example, `perf report --stdio` from perf data gathered using `perf record -e block:block_rq_insert -ag` will show something like: ``` 96.76% 0.00% pebble pebble [.] runtime.goexit | ---runtime.goexit | |--85.58%-- github.com/cockroachdb/pebble/internal/record.NewLogWriter.func2 | runtime/pprof.Do | github.com/cockroachdb/pebble/internal/record.(*LogWriter).flushLoop-fm | github.com/cockroachdb/pebble/internal/record.(*LogWriter).flushLoop | github.com/cockroachdb/pebble/internal/record.(*LogWriter).flushPending | github.com/cockroachdb/pebble/vfs.(*syncingFile).Sync | github.com/cockroachdb/pebble/vfs.(*syncingFile).syncFdatasync-fm | github.com/cockroachdb/pebble/vfs.(*syncingFile).syncFdatasync | syscall.Syscall | entry_SYSCALL_64_fastpath | sys_fdatasync | do_fsync | vfs_fsync_range | ext4_sync_file | filemap_write_and_wait_range | __filemap_fdatawrite_range | do_writepages | ext4_writepages | blk_finish_plug | blk_flush_plug_list | blk_mq_flush_plug_list | blk_mq_insert_requests ``` This is showing that `96.76%` of block device requests on the entire system were generated by the `pebble` process, and `85.58%` of the block device requests on the entire system were generated from WAL syncing within this `pebble` process. The `perf script` command provides access to the raw request data. While there are various pre-recorded scripts that can be executed, it is primarily useful for seeing call stacks along with the "trace" data. For block requests, the trace data shows the device, the operation type, the offset, and the size. ``` # List all events from perf.data with recommended header and fields. sudo perf script --header -F comm,pid,tid,cpu,time,event,ip,sym,dso,trace ... pebble 6019/6019 [008] 16492.555957: block:block_rq_insert: 259,0 WS 0 () 3970952 + 256 [pebble] 7fff813d791a blk_mq_insert_requests 7fff813d8878 blk_mq_flush_plug_list 7fff813ccc96 blk_flush_plug_list 7fff813cd20c blk_finish_plug 7fff812a143d ext4_writepages 7fff8119ea1e do_writepages 7fff81191746 __filemap_fdatawrite_range 7fff8119188a filemap_write_and_wait_range 7fff81297c41 ext4_sync_file 7fff81244ecb vfs_fsync_range 7fff81244f8d do_fsync 7fff81245243 sys_fdatasync 7fff8181ae6d entry_SYSCALL_64_fastpath 3145e0 syscall.Syscall 6eddf3 github.com/cockroachdb/pebble/vfs.(*syncingFile).syncFdatasync 6f069a github.com/cockroachdb/pebble/vfs.(*syncingFile).syncFdatasync-fm 6ed8d2 github.com/cockroachdb/pebble/vfs.(*syncingFile).Sync 72542f github.com/cockroachdb/pebble/internal/record.(*LogWriter).flushPending 724f5c github.com/cockroachdb/pebble/internal/record.(*LogWriter).flushLoop 72855e github.com/cockroachdb/pebble/internal/record.(*LogWriter).flushLoop-fm 7231d8 runtime/pprof.Do 727b09 github.com/cockroachdb/pebble/internal/record.NewLogWriter.func2 2c0281 runtime.goexit ``` Let's break down the trace data: ``` 259,0 WS 0 () 3970952 + 256 | | | | | | | + size (sectors) | | | | | + offset (sectors) | | | +- flags: R(ead), W(rite), B(arrier), S(ync), D(iscard), N(one) | +- device: , ``` The above is indicating that a synchronous write of `256` sectors was performed starting at sector `3970952`. The sector size is device dependent and can be determined with `blockdev --report `, though it is almost always `512` bytes. In this case, the sector size is `512` bytes indicating that this is a write of 128 KB. ## Blktrace The `blktrace` tool records similar info to `perf`, but is targeted to the block layer instead of being general purpose. The `blktrace` command records data, while the `blkparse` command parses and displays data. The `btrace` command is a shortcut for piping the output from `blktrace` directly into `blkparse. ### Installation Ubuntu AWS installation: ``` sudo apt-get install blktrace ``` ## Usage ``` # Pipe the output of blktrace directly into blkparse. sudo blktrace -d /dev/nvme1n1 -o - | blkparse -i - # Equivalently. sudo btrace /dev/nvme1n1 ``` The information captured by `blktrace` is similar to what `perf` captures: ``` sudo btrace /dev/nvme1n1 ... 259,0 4 186 0.016411295 11538 Q WS 129341760 + 296 [pebble] 259,0 4 187 0.016412100 11538 Q WS 129342016 + 40 [pebble] 259,0 4 188 0.016412200 11538 G WS 129341760 + 256 [pebble] 259,0 4 189 0.016412714 11538 G WS 129342016 + 40 [pebble] 259,0 4 190 0.016413148 11538 U N [pebble] 2 259,0 4 191 0.016413255 11538 I WS 129341760 + 256 [pebble] 259,0 4 192 0.016413321 11538 I WS 129342016 + 40 [pebble] 259,0 4 193 0.016414271 11538 D WS 129341760 + 256 [pebble] 259,0 4 194 0.016414860 11538 D WS 129342016 + 40 [pebble] 259,0 12 217 0.016687595 0 C WS 129341760 + 256 [0] 259,0 12 218 0.016700021 0 C WS 129342016 + 40 [0] ``` The standard format is: ``` + [] ``` See `man blkparse` for an explanation of the actions. The `blktrace` output can be used to highlight problematic I/O patterns. For example, it can be used to determine there are an excessive number of small sequential read I/Os indicating that dynamic readahead is not working correctly.