ceremonyclient/pebble/docs/io_profiling.md

# 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 <duration>` 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: <major>, <minor>
```

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 <device>`,
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:

```
<device> <cpu> <seqnum> <timestamp> <pid> <action> <RWBS> <start-sector> + <size> [<command>]
```

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.