[Qemu-devel] Serious regression of 9p read performance, huge amount of openat syscalls on plain file descriptors

[Lutz Vieweg]

Hi all,

I have been using 9p mounts on guests for quite some time, and enjoyed
their nice performance.

But not anymore: I noticed that just "dd"-ing large plain files to /dev/zero
on the guest system became very slow, even if the data is completely
in the cache of the host. The rate maxes at ~ 30MB/s while the qemu process
on the host eats lots of CPU).
Both qemu (from source repository) and host kernel (3.1.6)
were upgraded since the last good benchmark, so this could be the
result of some recent change...

Looking for the cause I noticed that the qemu process, according to strace,
does an insane amount of "openat" syscalls - about 820 per second! - while
the guest system is reading the file (in 64kB chunks, if that matters).
I guess it's no wonder that this huge amount of "open" operations per
second will slow down whatever I/O qemu is trying to do.

Especially strange is that the fds passed into the openat syscall as the
first parameter refers to the file being read (not the directory it is in,
which has a different fd), according to "lsof".
And the openat syscall always returns 0x1000 as a result (if strace is not
lying), which is neither a credible fd, nor an errno I'd know of:

> [pid 29236] syscall_295(0x1b, 0x7fe46044a670, 0x1, 0x109e000, 0, 0, 0x7fe46034ae00, 
> 0x7fe46034ae00, 0x7fe46034ae00, 0x7fe46034ae00, 0x7fe46034ae00, 0x7fe46034ae00, 
> 0x7fe46034ae00, 0x7fe46034ae00, 0x7fe46034ae00, 0x7fe46034ae00, 0x7fe46034ae00, 
> 0x7fe46034ae00, 0x7fe46034ae00, 0x7fe46034ae00, 0x7fe46034ae00, 0x7fe46034ae00, 
> 0x7fe46034ae00, 0x7fe46034ae00, 0x7fe46034ae00, 0x7fe46034ae00, 0x7fe46034ae00, 
> 0x7fe46034ae00, 0x7fe46034ae00, 0x7fe46034ae00, 0x7fe46034ae00, 0x7fe46034ae00 
> <unfinished ...>
> [pid 29236] <... syscall_295 resumed> ) = 0x1000
> [pid 29235] syscall_295(0x1c, 0x7fe4659d8070, 0x1, 0x16df000, 0, 0, 0x7fe4658d8800, 
> 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 
> 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 
> 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 
> 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 
> 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800 
> <unfinished ...>
> [pid 29235] <... syscall_295 resumed> ) = 0x1000
> [pid 29234] syscall_295(0x1b, 0x7fe4659d8070, 0x1, 0x109f000, 0, 0, 0x7fe4658d8800, 
> 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 
> 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 
> 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 
> 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 
> 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800, 0x7fe4658d8800 
> <unfinished ...>
> [pid 29234] <... syscall_295 resumed> ) = 0x1000

Alas, I could not get gdb to tell me exactly where those openat calls are
made from (in the qemu-kvm source) - the functions that contain those calls
are static and seem to become inlined.

Does anyone have an idea what may have caused this? Do you still see
good read performance when reading big plain files from a 9p mount.

Regards,

Lutz Vieweg