The symptom: 100 Gbyte uploads stalling
A microservice that managed and processed large files — encrypting them before storing them on S3 — was taking hours to upload 100 Gbyte files, while files as large as 40 Gbytes completed in minutes. Cloud-wide monitoring in Atlas showed a high rate of pageins during the large uploads.
Pageins are disk reads of a page of memory, and they are ordinary for many workloads, but the gap between the 40 Gbyte and 100 Gbyte cases pointed at something size-dependent.
Checking the storage layer
The 60-second performance checklist starts with disk behavior, so iostat(1) came first. The r_await column stood out: the average wait for reads was 33 ms, which is on the high side, and it tracked with queueing visible in avgqu-sz. Request sizes worked out to roughly 128 Kbytes (divide rkB/s by r/s).
# 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
Reads tend to have applications waiting on them, unlike writes that can be absorbed by write-back caching, so that latency was worth investigating before blaming the device.
Latency distribution and I/O sizes
Averages hide outliers, and outliers would be the signature of a failing device. The biolatency eBPF tool from bcc produced a latency histogram showing most I/O landing between 16 and 127 ms, with some stragglers out to 0.5–1.0 seconds.
# /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 | |
Nothing there looked like hardware. The spread was consistent with the queueing seen in iostat(1), and bitesize confirmed the request pattern: I/O concentrated in the 128–255 Kbyte bucket, exactly what the earlier output implied.
# /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 |****************************************|
Memory and the page cache
free(1) was the next checklist item, and it reframed the problem. Only 349 Mbytes of memory remained free, but 48,643 Mbytes — 48 Gbytes — sat in the buffer/page cache on a 64-Gbyte system.
# free -m
total used free shared buff/cache available
Mem: 64414 15421 349 5 48643 48409
Swap: 0 0 0
Combine that with the file sizes and a theory emerges: do the 100 Gbyte files exceed what the page cache can hold, while 40 Gbyte files fit comfortably? If so, the backing reads that iostat(1) and biolatency were recording are the file being pulled back off disk after eviction.
Page cache statistics
cachestat, a tool built on Ftrace that has since been ported to bcc/eBPF, reports hit and miss statistics for the page cache. It showed hit ratios bouncing between 6.5% and 74% — far below the upper-90s range that indicates healthy caching. This is cache busting: the 100 Gbyte file does not fit within 48 Gbytes of page cache, so misses generate disk I/O and drag down throughput.
# /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
[...]
Two remedies follow. The immediate one is to run on a larger-memory instance that can hold 100 Gbyte files. The longer-term one belongs to the developers: rework the code around the memory constraint, for example by processing parts of the file instead of making repeated passes over the whole thing.
Confirming with a smaller file
A 32 Gbyte upload collected against the same tooling served as the control. cachestat reported a hit ratio near 100%.
# /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
At that size the service can perform all of its passes over the file from memory without going back to disk. free(1) showed the file 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) showed little disk I/O, which is what the caching theory predicts.
# 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
[...]
Where the tooling stands
cachestat was the tool that cracked this case, but it remains experimental. It was written for Ftrace under two constraints: low overhead, and use of the Ftrace function profiler only. The statistics it produces are needed often enough that they arguably belong in /proc rather than in a separate tool. Kernel memory-management engineers, present when this was raised at the LSFMMBPF 2019 keynote in Puerto Rico, pointed to challenges in exposing them properly, and a robust solution would likely need their expertise.
Kernel support may never arrive, since these are hot-path counters and adding them is not free. In the meantime cachestat works, at the cost of regular maintenance to keep it functional.
