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

[Lutz Vieweg]

The regression does not exist in the way that I suspected - it's just
that the default for 9p mount option "msize=4096" causes the bad
performance when reading large files on the guest.

I was mislead because...

a) mount -o remount,msize=...,...
   seems to work (with mount reporting the changed value afterwards),
   but it doesn't - only the msize chosen at first mount time is relevant/used.

b) gdb lied to me:
     > catch syscall openat
     Catchpoint 1 (syscall 'openat' [295])
   I learned the hard way that the system supplied gdb made wrong assumptions
   on which syscall number is associated with what function.
   In fact, the so often used syscall was "preadv", not "openat".

Thus my only suggestion is to change the default for "msize="
to 131072 (128k), this results in a speed up from ~ 30MB/s to ~ 290MB/s
in the large-file reading use case.

Regards,

Lutz Vieweg


On 01/12/2012 07:42 PM, Lutz Vieweg wrote:
> 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