[Xen-devel] FYI: xend extremly slow when on nfsroot due to xenstored

[Stefan Berger <stefanb@xxxxxxxxxx>]

Hi!

In case someone is running into the
same problem...

I have a Xen system that is configured
to boot with 'NFSRoot' ('/' mounted over NFS) and has pretty good performance
in terms of access to the filesystem. 
What struck me on that system was that
'xm start <domain name>' took more than 40 (!) seconds to start a
VM, that means 'xm' blocked the console for this long. After some debugging
and profiling I found that the culprit of this was the interaction of xend
with the xenstore (see below). So, to make it short, the solution is for
now to mount /var/lib/xenstored into ramfs and I am back to ~6 seconds
for 'xm start'.

Here some of the output of xend:

[2007-09-14 09:21:46 7811] DEBUG (DevController:115)
DevController: writing {'protocol': 'x86_64-abi', 'state': '1', 'backend-id':
'0', 'backend': '/local/domain/0/backend/console/1/0'} to /local/domain/1/device/console/0.
[2007-09-14 09:21:46 7811] DEBUG (DevController:117) DevController: writing
{'domain': 'fedora1', 'protocol': 'vt100', 'uuid': '37625b64-be2e-a74a-8696-85613af84ceb',
'frontend': '/local/domain/1/device/console/0', 'state': '1', 'location':
'2', 'online': '1', 'frontend-id': '1'} to /local/domain/0/backend/console/1/0.
[2007-09-14 09:21:46 7811] DEBUG (DevController:122) --> Beginning with
writing
[2007-09-14 09:21:46 7811] DEBUG (DevController:123) ---> Removing frontpath
[2007-09-14 09:21:46 7811] DEBUG (DevController:125) ---> Removing backpath
[2007-09-14 09:21:46 7811] DEBUG (DevController:128) ---> Mkdir backpath
[2007-09-14 09:21:46 7811] DEBUG (DevController:130) ---> Set permissions
[2007-09-14 09:21:47 7811] DEBUG (DevController:135) ---> Mkdir frontpath
[2007-09-14 09:21:47 7811] DEBUG (DevController:137) ---> Set permissions
[2007-09-14 09:21:47 7811] DEBUG (DevController:142) ---> Writing to
frontpath
[2007-09-14 09:21:48 7811] DEBUG (DevController:144) ---> Writing to
backpath
[2007-09-14 09:21:50 7811] DEBUG (DevController:147) --> Committing.
[2007-09-14 09:21:50 7811] DEBUG (DevController:149) --> Ending the
writing. Done.
[2007-09-14 09:21:50 7811] INFO (XendDomainInfo:1347) createDevice: vbd
: {'uuid': '8eeeaeb4-5c04-0bc2-8949-a4539dd3055e', 'bootable': 1, 'driver':
'paravirtualised', 'dev': 'sda1:disk', 'uname': 'file:/home/jailtime/fedora1/fedora1.img',
'mode': 'w', 'backend': '0'}
[2007-09-14 09:21:50 7811] INFO (security:617) Resource label for file:/home/jailtime/fedora1/fedora1.img
not in file, using DEFAULT.
[2007-09-14 09:21:50 7811] INFO (security:771) Access Control Decision
: PERMITTED
[2007-09-14 09:21:50 7811] DEBUG (DevController:115) DevController: writing
{'virtual-device': '2049', 'device-type': 'disk', 'protocol': 'x86_64-abi',
'backend-id': '0', 'state': '1', 'backend': '/local/domain/0/backend/vbd/1/2049'}
to /local/domain/1/device/vbd/2049.
[2007-09-14 09:21:50 7811] DEBUG (DevController:117) DevController: writing
{'domain': 'fedora1', 'frontend': '/local/domain/1/device/vbd/2049', 'uuid':
'8eeeaeb4-5c04-0bc2-8949-a4539dd3055e', 'dev': 'sda1', 'state': '1', 'params':
'/home/jailtime/fedora1/fedora1.img', 'mode': 'w', 'online': '1', 'frontend-id':
'1', 'type': 'file'} to /local/domain/0/backend/vbd/1/2049.
[2007-09-14 09:21:50 7811] DEBUG (DevController:122) --> Beginning with
writing
[2007-09-14 09:21:50 7811] DEBUG (DevController:123) ---> Removing frontpath
[2007-09-14 09:21:50 7811] DEBUG (DevController:125) ---> Removing backpath
[2007-09-14 09:21:50 7811] DEBUG (DevController:128) ---> Mkdir backpath
[2007-09-14 09:21:51 7811] DEBUG (DevController:130) ---> Set permissions
[2007-09-14 09:21:51 7811] DEBUG (DevController:135) ---> Mkdir frontpath
[2007-09-14 09:21:51 7811] DEBUG (DevController:137) ---> Set permissions
[2007-09-14 09:21:51 7811] DEBUG (DevController:142) ---> Writing to
frontpath
[2007-09-14 09:21:52 7811] DEBUG (DevController:144) ---> Writing to
backpath
[2007-09-14 09:21:54 7811] DEBUG (DevController:147) --> Committing.
[2007-09-14 09:21:54 7811] DEBUG (DevController:149) --> Ending the
writing. Done.

A couple of those ~4 second transactions
are occuring and it adds up to > 40 seconds. I still find it surprising
that xenstore internally needs so much more time when running via NFSRoot.
When run on ramfs the xenstore transaction all occur in less than one second.

   Stefan
 
_______________________________________________
Xen-devel mailing list
Xen-devel@xxxxxxxxxxxxxxxxxxx
http://lists.xensource.com/xen-devel