With the YugabyteDB database, we persist data by guaranteeing the data changes, such inserts, updates, deletes, etc. to be persisted. As with many databases and other programs that have this requirement, we do this by writing it to a file and call fsync().
However, there is a thing that I wondered about for a long time: if I calculate the time spent on the fsync() call when doing batch oriented work with YugabyteDB, the time spent waiting is often 20ms or more.
This time looks high. And you have to wait for fsync(), because only if it finishes successfully, the data is guaranteed to be stored on persistent media.
Let's follow the work that is done down into the linux kernel, and see if we can find a reason!
The first step is to see what exactly we do in YugabyteDB. For normal write calls, for which we use the write() system call, this is problematic because the Yugabyte database is a threaded application, and we use write() on many occasions, which would give lots and lots of data.
But for writing to the YugabyteDB WAL files, we use the writev() (vector write) system call. The writev() alias vector write call allows multiple requests to be submitted in one go synchronously. Below we see the vector writes submitting two write requests each.
So to see the WAL writing and fsync activity, we can use the strace utility and only show the writev and fsync() system calls. This is how that looks like:
$ strace -fp $(pgrep tserver) -e writev,fsync
...
[pid 1995] writev(121, [{iov_base="\20\0\0\0\235+\346\235:\0\222\357", iov_len=12}, {iov_base="\22\5\10\2\20\226U\30\260\261\277\311\242\377\2042", iov_len=16}], 2) = 28
[pid 1995] writev(121, [{iov_base="g\314\30\0\320v\332\237\244)\304\177", iov_len=12}, {iov_base="\n\323\230c\10\1\22\315\230c\n\5\10\2\20\227U\21\0\2006\373\232\250\311_H\0 \3*\256"..., iov_len=1625191}], 2) = 1625203
[pid 1995] fsync(121) = 0
[pid 1995] writev(121, [{iov_base="\20\0\0\0\337\21N\212\315\357C\300", iov_len=12}, {iov_base="\22\5\10\2\20\227U\30\225\231\350\341\242\377\2042", iov_len=16}], 2) = 28
[pid 1995] writev(121, [{iov_base="g\314\30\0\327]?\33\377\36\3446", iov_len=12}, {iov_base="\n\323\230c\10\1\22\315\230c\n\5\10\2\20\230U\21\0\320I\10\233\250\311_H\0 \3*\256"..., iov_len=1625191}], 2) = 1625203
[pid 1995] fsync(121) = 0
[pid 1995] writev(121, [{iov_base="\20\0\0\0\221\f\260\351\367h_\350", iov_len=12}, {iov_base="\22\5\10\2\20\230U\30\251\245\371\375\242\377\2042", iov_len=16}], 2) = 28
[pid 1995] writev(121, [{iov_base="g\314\30\0\26\234\252W\304g\262n", iov_len=12}, {iov_base="\n\323\230c\10\1\22\315\230c\n\5\10\2\20\231U\21\0p\7\24\233\250\311_H\0 \3*\256"..., iov_len=1625191}], 2) = 1625203
[pid 1995] fsync(121) = 0
...
So -in general, not strictly!-, during a batch operation such as a batch insert, there's two writev() calls, one small call, about 28 bytes (the last number of the total size of the writev() request), and one big, which is 1625203 bytes.
This is where things start to get fuzzy, at least for me. The big write that is performed is seems to be 1625203 bytes, which is a little more than 1.5 MB. The YugabyteDB threshold for performing fsync is 1 second or 1 MB, but this is approximately 50% more?
But still, this is still reasonably known territory, right? We write data buffered, and then perform fsync(), there is no reason that that would take 20ms....or is it?
The next layer to look at is the block IO layer, or "bio" layer. To look at this layer, there are some brilliant tools in the bcc tools package, which use linux eBPF.
The tool to use here is biosnoop: a tool to 'snoop' on the BIO layer.
This is how that looks like for the same requests for which we looked at with strace:
TIME(s) COMM PID DISK T SECTOR BYTES LAT(ms)
15.492545 append [worker 1668 nvme1n1 W 107830376 4096 0.69
15.493980 append [worker 1668 nvme1n1 W 107830384 262144 2.08
15.495007 append [worker 1668 nvme1n1 W 107830896 262144 3.08
15.495918 append [worker 1668 nvme1n1 W 107831408 262144 3.95
15.497194 append [worker 1668 nvme1n1 W 107831920 262144 5.19
15.497705 append [worker 1668 nvme1n1 W 107832432 262144 5.67
15.499456 append [worker 1668 nvme1n1 W 107832944 262144 7.39
15.500215 append [worker 1668 nvme1n1 W 107833456 53248 8.14
15.507690 append [worker 1668 nvme1n1 W 104958050 1024 0.77
15.512486 append [worker 1668 nvme1n1 W 107833552 4096 0.59
15.514076 append [worker 1668 nvme1n1 W 107833560 262144 2.14
15.515213 append [worker 1668 nvme1n1 W 107834072 262144 3.24
15.515951 append [worker 1668 nvme1n1 W 107834584 262144 3.95
15.516999 append [worker 1668 nvme1n1 W 107835608 200704 4.90
15.517053 append [worker 1668 nvme1n1 W 107835096 262144 5.01
15.517995 append [worker 1668 nvme1n1 W 107836512 110592 5.85
15.518299 append [worker 1668 nvme1n1 W 107836000 262144 6.17
15.529624 append [worker 1668 nvme1n1 W 104958052 4096 0.62
This snippet from biosnoop shows the requests as the block IO layer sees it. Above we see the result of two times the combination of writev()/writev()/fsync().
But there are many more requests here? If we carefully look, we see that the first request is a request of 4096 bytes. That is probably the first writev(), although bigger.
But the important thing to see are the requests that follow that, each with a size of 262144 bytes, alias 256 kB.
Each of the bigger requests of 256k shows a latency of approximately 3ms or higher. This is the average IO latency time that I recognise, but you can also clearly see here that smaller requests get a better latency, and thus bigger ones have worse latency.
But where comes the 262144 / 256k come from?
The answer to that comes with the linux kernel files that are part of the disk subsystem and drivers in /sys/block/<blockdevice>/queue. This is a meta-directory, and contains information and settings about the disk.
The thing to look for is max_sectors_kb:
# cat max_sectors_kb
256
This means the maximum IO size is 256 kB! So the kernel broke down the large requests in the biggest size it is set to handle, which here is 256 kB!
Let's see if we can increase the IO size: the maximum allowed size is specified in max_hw_sectors_kb:
# cat max_hw_sectors_kb
256
Nope. We can't increase the IO size, it's already at its maximum. :-(
In case you're wondering what I run on, this is Amazon EC2 c5.
So now combining/going back to the requests that we measured using biosnoop: these are the requests from the large writev() request, but are broken down to 256kB chunks because of the maximum IO size, and then submitted to the block device.
Each of these requests takes approximately 3ms or higher, and there seems to be a tendency for successive large IO requests to get increasing latency.
Overall, this explains the fsync() latency that we see, these are the result of the chunks of 256kB that the fsync() call has to dispatch and wait for, which adds up to the 20ms or higher that we see with batches, when we fsync after (more than) 1M.
Top comments (1)
Excellent article, feels like I’m reading a detective story.
I bet you also ran the test on you machine (not aws). How much did the batch latency improved after you increased the maximum allowed IO size?