These are rough notes.
A service team was debugging a performance issue and noticed it coincided with a high rate of paging. I was asked to help, and used a variety of Linux performance tools to solve this including those that use eBPF and Ftrace. This is a rough post to share this old but good case study of using these tools, and to help justify their further development. No editing, spell checking, or comments. Mostly screenshots.
1. Problem Statement
The microservice managed and processed large files, including encrypting them and then storing them on S3. The problem was that large files, such as 100 Gbytes, seemed to take forever to upload. Hours. Smaller files, as large as 40 Gbytes, were relatively quick, only taking minutes.
A cloud-wide monitoring tool, Atlas, showed a high rate of paging for the larger file uploads:
The blue is pageins (page ins). Pageins are a type of disk I/O where a page of memory is read in from disk, and are normal for many workloads.
You might be able to guess the issue from the problem statement alone.
2. iostat
Starting with my 60-second performance checklist, the iostat(1) tool showed a high rate of disk I/O during a large file upload:
# iostat -xz 1
Linux 4.4.0-1072-aws (xxx) 12/18/2018 _x86_64_ (16 CPU)
avg-cpu: %user %nice %system %iowait %steal %idle
5.03 0.00 0.83 1.94 0.02 92.18
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
xvda 0.00 0.29 0.21 0.17 6.29 3.09 49.32 0.00 12.74 6.96 19.87 3.96 0.15
xvdb 0.00 0.08 44.39 9.98 5507.39 1110.55 243.43 2.28 41.96 41.75 42.88 1.52 8.25
avg-cpu: %user %nice %system %iowait %steal %idle
14.81 0.00 1.08 29.94 0.06 54.11
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
xvdb 0.00 0.00 745.00 0.00 91656.00 0.00 246.06 25.32 33.84 33.84 0.00 1.35 100.40
avg-cpu: %user %nice %system %iowait %steal %idle
14.86 0.00 0.89 24.76 0.06 59.43
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
xvdb 0.00 0.00 739.00 0.00 92152.00 0.00 249.40 24.75 33.49 33.49 0.00 1.35 100.00
avg-cpu: %user %nice %system %iowait %steal %idle
14.95 0.00 0.89 28.75 0.06 55.35
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
xvdb 0.00 0.00 734.00 0.00 91704.00 0.00 249.87 24.93 34.04 34.04 0.00 1.36 100.00
avg-cpu: %user %nice %system %iowait %steal %idle
14.54 0.00 1.14 29.40 0.06 54.86
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
xvdb 0.00 0.00 750.00 0.00 92104.00 0.00 245.61 25.14 33.37 33.37 0.00 1.33 100.00
^C
I'm looking at the r_await column in particular: the average wait time for reads in milliseconds. Reads usually have apps waiting on them; writes may not (write-back caching). An r_wait of 33 ms is kinda high, and likely due to the queueing (avgqu-sz). They are largeish I/O, about 128 Kbytes (divide rkB/s by r/s).
3. biolatency
From bcc, this eBPF tool shows a latency histogram of disk I/O. I'm running it in case the averages are hiding outliers, which could be a device issue:
# /usr/share/bcc/tools/biolatency -m
Tracing block device I/O... Hit Ctrl-C to end.
^C
msecs : count distribution
0 -> 1 : 83 | |
2 -> 3 : 20 | |
4 -> 7 : 0 | |
8 -> 15 : 41 | |
16 -> 31 : 1620 |******* |
32 -> 63 : 8139 |****************************************|
64 -> 127 : 176 | |
128 -> 255 : 95 | |
256 -> 511 : 61 | |
512 -> 1023 : 93 | |
This doesn't look too bad. Most I/O are between 16 and 127 ms. Some outliers reaching the 0.5 to 1.0 second range, but again, there's quite a bit of queueing here seen in the earlier iostat(1) output. I don't think this is a device issue. I think it's the workload.
4. bitesize
As I think it's a workload issue, I want a better look at the I/O sizes in case there's something odd:
# /usr/share/bcc/tools/bitesize
Tracing... Hit Ctrl-C to end.
^C
Process Name = java
Kbytes : count distribution
0 -> 1 : 0 | |
2 -> 3 : 0 | |
4 -> 7 : 0 | |
8 -> 15 : 31 | |
16 -> 31 : 15 | |
32 -> 63 : 15 | |
64 -> 127 : 15 | |
128 -> 255 : 1682 |****************************************|
The I/O is mostly in the 128 to 255 Kbyte bucket, as expected from the iostat(1) output. Nothing odd here.
5. free
Also from the 60-second checklist:
# free -m
total used free shared buff/cache available
Mem: 64414 15421 349 5 48643 48409
Swap: 0 0 0
There's not much memory left, 349 Mbytes, but more interesting is the amount in the buffer/page cache: 48,643 Mbytes (48 Gbytes). This is a 64-Gbyte memory system, and 48 Gbytes is in the page cache (the file system cache).
Along with the numbers from the problem statement, this gives me a theory: Do the 100-Gbyte files bust the page cache, whereas 40-Gbyte files fit?
6. cachestat
cachestat is an experimental tool I developed that uses Ftrace and has since been ported to bcc/eBPF. It shows statistics for the page cache:
# /apps/perf-tools/bin/cachestat
Counting cache functions... Output every 1 seconds.
HITS MISSES DIRTIES RATIO BUFFERS_MB CACHE_MB
1811 632 2 74.1% 17 48009
1630 15132 92 9.7% 17 48033
1634 23341 63 6.5% 17 48029
1851 13599 17 12.0% 17 48019
1941 3689 33 34.5% 17 48007
1733 23007 154 7.0% 17 48034
1195 9566 31 11.1% 17 48011
[...]
This shows many cache misses, with a hit ratio varying between 6.5 and 74%. I usually like to see that in the upper 90's. This is "cache busting." The 100 Gbyte file doesn't fit in the 48 Gbytes of page cache, so we have many page cache misses that will cause disk I/O and relatively poor performance.
The quickest fix is to move to a larger-memory instance that does fit 100 Gbyte files. The developers can also rework the code with the memory constraint in mind to improve performance (e.g., processing parts of the file, instead of making multiple passes over the entire file).
7. Smaller File Test
For further confirmation, I collected the same outputs for a 32 Gbyte file upload.
cachestat shows a ~100% cache hit ratio:
# /apps/perf-tools/bin/cachestat
Counting cache functions... Output every 1 seconds.
HITS MISSES DIRTIES RATIO BUFFERS_MB CACHE_MB
61831 0 126 100.0% 41 33680
53408 0 78 100.0% 41 33680
65056 0 173 100.0% 41 33680
65158 0 79 100.0% 41 33680
55052 0 107 100.0% 41 33680
61227 0 149 100.0% 41 33681
58669 0 71 100.0% 41 33681
33424 0 73 100.0% 41 33681
^C
This smaller size allows the service to process the file (however many passes it takes) entirely from memory, without re-reading it from disk.
free(1) shows it fitting in the page cache:
# free -m
total used free shared buff/cache available
Mem: 64414 18421 11218 5 34773 45407
Swap: 0 0 0
And iostat(1) shows little disk I/O, as expected:
# iostat -xz 1
Linux 4.4.0-1072-aws (xxx) 12/19/2018 _x86_64_ (16 CPU)
avg-cpu: %user %nice %system %iowait %steal %idle
12.25 0.00 1.24 0.19 0.03 86.29
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
xvda 0.00 0.32 0.31 0.19 7.09 4.85 47.59 0.01 12.58 5.44 23.90 3.09 0.15
xvdb 0.00 0.07 0.01 11.13 0.10 1264.35 227.09 0.91 82.16 3.49 82.20 2.80 3.11
avg-cpu: %user %nice %system %iowait %steal %idle
57.43 0.00 2.95 0.00 0.00 39.62
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
avg-cpu: %user %nice %system %iowait %steal %idle
53.50 0.00 2.32 0.00 0.00 44.18
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
xvdb 0.00 0.00 0.00 2.00 0.00 19.50 19.50 0.00 0.00 0.00 0.00 0.00 0.00
avg-cpu: %user %nice %system %iowait %steal %idle
39.02 0.00 2.14 0.00 0.00 58.84
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
[...]
8. Final Notes
cachestat was the killer tool here, but I should stress that it's still experimental. I wrote it for Ftrace with the constraints that it must be low-overhead and use the Ftrace function profiler only. As I mentioned in my LSFMMBPF 2019 keynote in Puerto Rico, where the Linux mm kernel engineers were present, I think the cachestat statistics are so commonly needed that they should be in /proc and not need my experimental tool. They pointed out challenges with providing them properly, and I think any robust solution is going to need their help and expertise. I hope this case study helps show why it is useful and worth the effort.
Until the kernel does support page cache statistics (which may be never: they are hot-path, so adding counters isn't free) we can use my cachestat tool, even if it does require frequent maintenance to keep working.