Re: open/stat64 syscalls run faster on Xen VM than standard Linux

[xuehai zhang <hai@cs.uchicago.edu>]

Mats,

Thank you so much for your help.

>>-----Original Message-----
>>From: xen-devel-bounces@lists.xensource.com 
>>[mailto:xen-devel-bounces@lists.xensource.com] On Behalf Of 
>>xuehai zhang
>>Sent: 29 November 2005 12:40
>>To: Anthony Liguori
>>Cc: Kate Keahey; Tim Freeman; Xen Mailing List
>>Subject: Re: [Xen-devel] open/stat64 syscalls run faster on 
>>Xen VM than standard Linux
>>
>>Anthony Liguori wrote:
>>
>>>This may just be the difference between having the extra level of 
>>>block caching from using a loop back device.
>>>
>>>Try running the same benchmark on a domain that uses an actual 
>>>partition.  While the syscalls may appear to be faster, I 
>>
>>imagine it's 
>>
>>>because the cost of pulling in a block has already been 
>>
>>payed so the 
>>
>>>overall workload is unaffected.
>>
>>I created a new domainU by using the physical partition 
>>instead of the loopback file as the backends of the VBDs and 
>>I reran the "strace -c /bin/sh -c /bin/echo foo" benchmark 
>>inside of the domU. The following are the results. Comparing 
>>with the results for domU with loopback files as VBDs I 
>>reported in the previous email (quoted below), the average 
>>time of open/stat64 syscalls are very similar, but still much 
>>smaller than the values for standard Linux. If the reason 
>>that open/stat64 run faster on domU with loopback files as 
>>VBDs is because of the extra level of block caching from 
>>using a loop back device, why open/stat64 still run 
>>similarily faster on domU with physical partition as VBDs 
>>when there is no extra level of block caching from using a 
>>loop back device?
> 
> 
> Again, have you run the same test-case on the same physical partition?
> You should be able to do the same trick with mount and chroot for this
> one too. 

Yes, I did. I shutdown the partition-based domU first, then mount the partition and chroot to it, 
and redid "strace -c /bin/sh -c /bin/echo foo". The following results show the write cost is similar 
as the value of physical machine while open and stat64 are still similar as values of loopback 
file-based domU.

# strace -c /bin/sh -c /bin/echo foo

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  21.17    0.000482         482         1           write
  16.07    0.000366          24        15           old_mmap
  14.54    0.000331          37         9         3 open
  11.55    0.000263          10        26           brk
   8.83    0.000201          40         5           read
   7.47    0.000170          85         2           munmap
   4.04    0.000092           8        11           rt_sigaction
   3.16    0.000072          12         6           close
   2.85    0.000065          11         6           fstat64
   2.20    0.000050          25         2           access
   2.20    0.000050           8         6           rt_sigprocmask
   1.80    0.000041          14         3           uname
   1.27    0.000029          15         2           stat64
   0.35    0.000008           8         1           time
   0.35    0.000008           8         1           getppid
   0.35    0.000008           8         1           getpgrp
   0.35    0.000008           8         1           getuid32
   0.35    0.000008           8         1           getgid32
   0.31    0.000007           7         1           getpid
   0.26    0.000006           6         1           execve
   0.26    0.000006           6         1           geteuid32
   0.26    0.000006           6         1           getegid32
------ ----------- ----------- --------- --------- ----------------
100.00    0.002277                   103         3 total

Some more information:
The partition I use is /dev/sda6, which is mapped to /tmp in dom0.

# mount /tmp

# df -lh
Filesystem            Size  Used Avail Use% Mounted on
/dev/sda1             1.5G  728M  661M  53% /
tmpfs                  62M  4.0K   62M   1% /dev/shm
/dev/sda5             938M  250M  640M  29% /var
/dev/sda6             4.2G  2.9G  1.2G  72% /tmp

# ls /tmp
bcfg-run.nightly  dbuta/  initrd/      media/              mpd2.console_root=    opt/      sbin/  usr/
beckman/          dev/    lib/         mnt/                mpd2.logfile_rbutler  proc/     srv/   var/
bin/              etc/    lost+found/  mpd2/               mpd2.logfile_robl     root/     sys/   vosg/
boot/             home/   mdtest*      mpd2.console_robl=  mpd2.logfile_root     sandbox/  tmp/ 
zoid_threads/

> This is just to rule out other variations (where in the file-system
> different files live, just as an example). 
> 
> I'm also not entirely convinced that you don't get some double-caching
> with this method too - there is the real hard-disk driver in Dom0, then
> the virtual disk driver in DomU, and the file-system driver in DomU. I
> don't know if the real or virtual block-device driver itself will cache
> things or not. Someone who knows may want to comment on this... 

I would like to know the caching mechanism of real or virtual block-device driver too.

> Still, I agree with Anthony - run some REAL loads on the system, rather
> than microbenchmark a particular, very small function of the whole
> system. Microbenchmarks are very good at showing how long some
> particular thing takes, but they are also very sensitive to extremely
> small changes in the system architecture, which for a bigger load would
> not be noticable. 

> I'm doing my best to explain things here, but I'm not sure if I'm
> getting the point across, as it seems like you're trying very hard to
> get back to the same original question. We do know that Xen behaves
> different than Linux. One reason for this is that it's dealing with
> hardware devices through a virtual device. This will most of the time
> slow things down, but as you've seen, for example due to the
> double-caching effect, you may sometimes actually gain from it,
> particularly with very small workloads. 

I am sorry that I didn't describe before about why I am doing all these microbechmarks. The reason 
behind is actually coming from the fact that the VM outperforms the physical machine when I ran some 
real application on both of them originally (VM and physical machine are configured as similar as 
possible). We all expect that the Xen VM presents a little bit worse performance than the compatible 
physical machine. So, the performance "gain" on VM to run the same application is really an abnormal 
observation, which has been made me worried a lot in the past week. That is why I spent so much time 
tracing down what happens in the application until the level of system calls. So, the problem is 
original from running the actual application.

Thanks.

Xuehai

>>XenLinux (physical partition as VBDs)
>>
>>root@cctest1:~/c# strace -c /bin/sh -c /bin/echo foo
>>% time     seconds  usecs/call     calls    errors syscall
>>------ ----------- ----------- --------- --------- ----------------
>>  39.56    0.001955        1955         1           write
>>  18.94    0.000936         936         1           execve
>>   7.65    0.000378          24        16           old_mmap
>>   7.57    0.000374          42         9         2 open
>>   6.27    0.000310          52         6           read
>>   5.10    0.000252          84         3           munmap
>>   4.92    0.000243           9        26           brk
>>   1.92    0.000095          14         7           close
>>   1.78    0.000088           8        11           rt_sigaction
>>   1.40    0.000069          10         7           fstat64
>>   1.01    0.000050           8         6           rt_sigprocmask
>>   0.93    0.000046          23         2           access
>>   0.79    0.000039          13         3           uname
>>   0.69    0.000034          17         2           stat64
>>   0.38    0.000019          19         1           ioctl
>>   0.16    0.000008           8         1           getppid
>>   0.16    0.000008           8         1           getpgrp
>>   0.14    0.000007           7         1           time
>>   0.14    0.000007           7         1           getuid32
>>   0.14    0.000007           7         1           getgid32
>>   0.12    0.000006           6         1           getpid
>>   0.12    0.000006           6         1           getegid32
>>   0.10    0.000005           5         1           geteuid32
>>------ ----------- ----------- --------- --------- ----------------
>>100.00    0.004942                   109         2 total
>>
>>Thanks.
>>
>>Xuehai
>>
>>
>>
>>>xuehai zhang wrote:
>>>
>>>
>>>>Dear all,
>>>>When I debugged the execution performance of an application using 
>>>>strace, I found there are some system calls like open and stat64 
>>>>which run faster on XenLinux than the standard Linux. The 
>>
>>following 
>>
>>>>is the output of running "strace -c /bin/sh -c /bin/echo 
>>
>>foo" on both 
>>
>>>>systems. An open call runs averagely 109 usec on standard 
>>
>>Linux but 
>>
>>>>only 41 usecs on XenLinux. An stat64 call runs
>>>>75 usecs on standard Linux but only 19 usecs on XenLinux.
>>>>The Xen VM runs on the same physical machine as the 
>>
>>standard Linux. 
>>
>>>>It uses loopback files in dom0 as the backends of VBDs.
>>>>Any insight is highly appreciated.
>>>>Thanks.
>>>>Xuehai
>>>>
>>>>XenLinux:
>>>># strace -c /bin/sh -c /bin/echo foo
>>>>
>>>>% time     seconds  usecs/call     calls    errors syscall
>>>>------ ----------- ----------- --------- --------- ----------------
>>>> 39.05    0.001972        1972         1           write
>>>> 19.35    0.000977         977         1           execve
>>>>  7.74    0.000391          24        16           old_mmap
>>>>  7.23    0.000365          41         9         2 open
>>>>  6.06    0.000306          51         6           read
>>>>  5.17    0.000261          10        26           brk
>>>>  4.93    0.000249          83         3           munmap
>>>>  1.98    0.000100          14         7           close
>>>>  1.90    0.000096           9        11           rt_sigaction
>>>>  1.52    0.000077          11         7           fstat64
>>>>  1.01    0.000051           9         6           rt_sigprocmask
>>>>  0.95    0.000048          24         2           access
>>>>  0.81    0.000041          14         3           uname
>>>>  0.75    0.000038          19         2           stat64
>>>>  0.38    0.000019          19         1           ioctl
>>>>  0.18    0.000009           9         1           time
>>>>  0.18    0.000009           9         1           getppid
>>>>  0.16    0.000008           8         1           getpgrp
>>>>  0.16    0.000008           8         1           getuid32
>>>>  0.14    0.000007           7         1           getgid32
>>>>  0.12    0.000006           6         1           getpid
>>>>  0.12    0.000006           6         1           geteuid32
>>>>  0.12    0.000006           6         1           getegid32
>>>>------ ----------- ----------- --------- --------- ----------------
>>>>100.00    0.005050                   109         2 total
>>>>
>>>>
>>>>Standard Linux:
>>>># strace -c /bin/sh -c /bin/echo foo
>>>>
>>>>% time     seconds  usecs/call     calls    errors syscall
>>>>------ ----------- ----------- --------- --------- ----------------
>>>> 22.90    0.000982         109         9         2 open
>>>> 22.85    0.000980         980         1           execve
>>>> 10.87    0.000466          29        16           old_mmap
>>>> 10.45    0.000448         448         1           write
>>>>  7.06    0.000303          51         6           read
>>>>  6.67    0.000286          10        30           brk
>>>>  3.61    0.000155          78         2           access
>>>>  3.50    0.000150          75         2           stat64
>>>>  2.91    0.000125          42         3           munmap
>>>>  2.24    0.000096          14         7           close
>>>>  2.12    0.000091          13         7           fstat64
>>>>  1.84    0.000079           7        11           rt_sigaction
>>>>  1.03    0.000044           7         6           rt_sigprocmask
>>>>  0.72    0.000031          10         3           uname
>>>>  0.19    0.000008           8         1           geteuid32
>>>>  0.16    0.000007           7         1           time
>>>>  0.16    0.000007           7         1           getppid
>>>>  0.16    0.000007           7         1           getpgrp
>>>>  0.16    0.000007           7         1           getuid32
>>>>  0.14    0.000006           6         1           getpid
>>>>  0.14    0.000006           6         1           getgid32
>>>>  0.12    0.000005           5         1           getegid32
>>>>------ ----------- ----------- --------- --------- ----------------
>>>>100.00    0.004289                   112         2 total
>>>>
>>>>_______________________________________________
>>>>Xen-devel mailing list
>>>>Xen-devel@lists.xensource.com
>>>>http://lists.xensource.com/xen-devel
>>>>
>>>
>>>
>>
>>_______________________________________________
>>Xen-devel mailing list
>>Xen-devel@lists.xensource.com
>>http://lists.xensource.com/xen-devel
>>
>>
> 
> 
>