Virtio block flush (VIRTIO_BLK_T_FLUSH) not syncing data to host

[pclesr]

Describe the bug

It appears that a sync on an ext4 file in the guest does not result in the data on the host also being sync'd out to disk.

To Reproduce

Using the file tester fio with the following config file:

[globa]
rw=write
ioengine=sync
bs=32k
direct=0
size=128m
numjobs=1
fsync_on_close=1
loops=10

When running this on the host to establish a baseline and running the linux perf utility (with call graphs enabled), one sees on an ancient (android) 4.14 kernel many calls to sync

    5.50%     0.00%  fio              [kernel.kallsyms]     [k] sys_fsync
            |
            ---sys_fsync
               do_fsync
               vfs_fsync_range
               ext4_sync_file
               file_write_and_wait_range

perf is run with
perf record -a --call-graph dwarf,16384 -F 200 -o /tmp/perf.data /tmp/fio /tmp/fio.job
Then the results with perf report and perf script.

When running the exact same fio and config in the VM, the bandwidth reported by fio is 4x that of the host baseline, indicating that the data is never actually sync'd to the medium. The page cache on the host is functioning as a huge disk cache. Running perf on the host during the execution of the fio test in the VM results shows no calls to sync.

The test is run against a virtio disk (/dev/vdb) that is formatted as an ext4 disk on the host, and then specified in the list of devices in the VMs config.json and mounted in the guest.

If perf is run in the VM (with a 5.7 kernel), then perf shows calls both to sync and the ext4 write call in the VM kernel:

   20.56%     0.03%  fio              [kernel.kallsyms]  [k] new_sync_write
            |
             --20.54%--new_sync_write
                       ext4_file_write_iter

so I do not believe it is a problem with fio.

It does not seem to matter what the VM config is. Firecracker is master as of 31 August 2020.

Expected behaviour

I would have expected that synchronous IO in the VM would be worse than on the host.

Environment

Firecracker v0.21.0-473-gf2f6d8f8
Host: Android 4.14
Guest: 5.7 kernel.org
rootfs: Alpine
Arch: arm64
perf version 4.14.133.g2e3484a
fio-3.16-32-g8c302

Running on an Android system with a 2 core A57 with a 14gig eMMC.

[    0.490202] mmc0: new HS400 MMC card at address 0001
[    0.491261] mmcblk0: mmc0:0001 S0J56X 14.8 GiB

Additional context

This is an embedded application, and because of power loss issues, data that is synchronously written in the guest needs to be resident on media.

I am running baseline perf numbers in both disk and network so that my masters can see how good firecracker is, opposed to all the other VM alternatives. 👍

I am a C programmer, and hardly know Rust. However, I wonder if there is any issue in src/devices/src/virtio/block/request.rs because the write is against a memory object, yet the flush is against a disk object?

In the guest:

 cat /proc/partitions
major minor  #blocks  name

 254        0      32768 vda
 254       16     614400 vdb
 254       32       9736 vdc


/ # mount /dev/vdb /bar
[   32.101662] EXT4-fs (vdb): recovery complete
[   32.104363] EXT4-fs (vdb): mounted filesystem with ordered data mode. Opts: (null)
/ # df
Filesystem           1K-blocks      Used Available Use% Mounted on
/dev/root                27633     26978         0 100% /
devtmpfs                117700         0    117700   0% /dev
/dev/vdb                588352    177272    392648  31% /bar

Checks

• [x ] Have you searched the Firecracker Issues database for similar problems?
• [ x] Have you read the existing relevant Firecracker documentation?
• [ x] Are you certain the bug being reported is a Firecracker issue?

[sandreim]

Thanks for logging this @pclesr . We'll take a deeper look and let you know our findings.

[pclesr]

metrics showing flush received:

  "block": {
    "activate_fails": 0,
    "cfg_fails": 0,
    "no_avail_buffer": 348,
    "event_fails": 0,
    "execute_fails": 0,
    "invalid_reqs_count": 0,
    "flush_count": 55,
    "queue_event_count": 4819,
    "rate_limiter_event_count": 0,
    "update_count": 0,
    "update_fails": 0,
    "read_bytes": 8795136,
    "write_bytes": 1342458880,
    "read_count": 1180,
    "write_count": 63419,
    "rate_limiter_throttled_events": 0
  },

[bzld]

It seems calling file.flush() does not provide the expected guarantees while file.sync_all() would indicate the host system to really flush its disk caches, see analog ticket here:
cloud-hypervisor/cloud-hypervisor#399

[sandreim]

Thanks @bzld. I am not sure we need to call fsync() at all in the current block device emulation, since the file is opened with O_SYNC this implies that each write returns after data has been sent to the underlying hardware just like a write()+ fsync().

[bzld]

@sandreim Yes, O_SYNC would do the same trick - but is the disk file really opened that way? I can't see it here:

firecracker/src/devices/src/virtio/block/device.rs

Lines 42 to 45 in d9d00ec

	let mut disk_image = OpenOptions::new()
	.read(true)
	.write(!is_disk_read_only)
	.open(PathBuf::from(&disk_image_path))?;

(Also, using fsync() might be faster than O_SYNC because the guest VM can better control which writes must be flushed to disk and which need not. And fdatasync() (rust: sync_data()) might even be slightly faster than fsync())

[pclesr]

Using the 'big hammer' approach does force the data out -- using fsync instead of flush I can now see the sync calls being executed on the host and the bandwidth reported by fio in the VM is much more in line with the underlying hardware.

diff --git a/src/devices/src/virtio/block/request.rs b/src/devices/src/virtio/block/request.rs
index 826eb97a..a546e472 100644
--- a/src/devices/src/virtio/block/request.rs
+++ b/src/devices/src/virtio/block/request.rs
@@ -6,7 +6,7 @@
 // found in the THIRD-PARTY file.

 use std::convert::From;
-use std::io::{self, Seek, SeekFrom, Write};
+use std::io::{self, Seek, SeekFrom};
 use std::mem;
 use std::result;

@@ -227,7 +227,7 @@ impl Request {
                 METRICS.block.write_bytes.add(self.data_len as usize);
                 METRICS.block.write_count.inc();
             }
-            RequestType::Flush => match diskfile.flush() {
+            RequestType::Flush => match diskfile.sync_all() {
                 Ok(_) => {
                     METRICS.block.flush_count.inc();
                     return Ok(0);

diff --git a/src/vmm/src/default_syscalls/filters.rs b/src/vmm/src/default_syscalls/filters.rs
index 1f654bb2..263263c7 100644
--- a/src/vmm/src/default_syscalls/filters.rs
+++ b/src/vmm/src/default_syscalls/filters.rs
@@ -109,6 +109,7 @@ pub fn default_filter() -> Result<SeccompFilter, Error> {
             allow_syscall(libc::SYS_timerfd_settime),
             allow_syscall(libc::SYS_write),
             allow_syscall(libc::SYS_writev),
+            allow_syscall(libc::SYS_fsync),
         ]
         .into_iter()
         .collect(),

Using perf on the host shows the following when the fio test is running in the VM. Before the change, I saw no sync calls on the host.

     2.22%     0.00%  firecracker  [kernel.kallsyms]  [k] sys_fsync
            |
            ---sys_fsync
               do_fsync
               vfs_fsync_range
               ext4_sync_file
               file_write_and_wait_range

[alindima]

Thanks everyone for following up on this.
After giving the issue a little bit more thought and investigating it a little further, here are the conclusions:

• As @bzld pointed out, indeed, the backing file is not opened in O_SYNC mode. Enabling this would work, but would likely have a serious performance impact, essentially bypassing all buffering mechanisms.
• The supposedly "big hammer" approach explored by @pclesr actually seems to be the right solution. Calling the sync_all method on the File instance actually issues a fsync syscall, triggering the right behaviour, with no additional impact.

@pclesr, would you be interested in submitting a PR to mainline with the solution?

[pclesr]

Hello @alindima , yes I can submit a PR. I am working on a slightly cleaner implementation that would keep the existing flush in place so that any buffered data would be sent to the page cache before the sync.

I don't know if that is really necessary, though. My knowledge of how the Rust library buffers data is non-existent.

I will have something ready in a day or two. Thank you very much for looking at this !

[acatangiu]

@pclesr I'm confident that your proposed patch is the complete and correct solution (in terms of VIRTIO_BLK_T_FLUSH operation)

I am working on a slightly cleaner implementation that would keep the existing flush in place so that any buffered data would be sent to the page cache before the sync

The data is already being sent to the page cache as part of previous write()s. The .flush() currently present in our code is actually no-op in the Rust Linux std::File implementation.

The correct function to call is as you mentioned sync_all().

I will have something ready in a day or two. Thank you very much for looking at this !

We would prefer adding the fix mentioned above sooner rather than later, could you prioritize this or should we open a PR with it?

[pclesr]

@acatangiu -- let me run through the steps for contributing in tests/README and I will put together the pull request.

The reason it takes time is that I have to compile/test for my arm target on a Qemu cross environment (arm64VM running on an x86) because my current employer doesn't provide me access to a spiffy AWS Annapurna VM. :-(

[acatangiu]

I don't see how/why this change would be in any way arch-specific. IMHO it would be fine to just post the PR and take advantage of our automated CI that also runs on aarch64.

You can add an integration test (see our tests dir) that fails without the fix and passes with, that you can develop on x86_64. That test will also run on aarch64 in our CI.

[acatangiu]

Also, thanks for the find and the fix! Good catch!

[pclesr]

Created pull request #2185