Hide Forgot
Created attachment 500587 [details] vdsm logs. Description of problem: noticed that it takes more then usual to start a new VM, it differs between 1-3 minutes, on a very high performance machines. from investigation I did, it appears that thread goes to sleep for a minute after performing memTestAndCommit check, and after almost a minute, continues to VM wrapper thread, which prepares the volume, creates the XML, and sends to libvirt. also, performed some code modification on order to isolate this issue and following are the results: 1) disabled resource locking in memTestAndCommit function under /usr/share/vdsm/clientIf.py def memTestAndCommit(self, newVm): """ Test if enough memory is available for new VM (currently unused) """ #self._memLock.acquire() using script, started bunch of disk-less VMs, it took a minute to start each VM. pleas refer to 'vdsm-disable_lock.log' - attached. 2) disabled relative 'if' that call this function in /usr/share/vdsm/vm.py def _startUnderlyingVm(self): try: if 'recover' not in self.conf: #if not self.cif.memTestAndCommit(self): # self.setDownStatus(ERROR, # 'Out of memory - machine not created') # return rc, err = self._prepostVmScript('pre_vm') using script, started a bunch of disk-less VMs, it took a minute to start 10 vms. please refer to 'vdsm-disable_if.log' - attached. not sure if its a regression.
Created attachment 502004 [details] libvirt logs
Haim, which version of libvirt you were running? Log inspection shows, we wait too long on file descriptors to became available for I/O, although they are, e.g.: 17:45:48.577: 1961: debug : virExecWithHook:761 : LC_ALL=C PATH=/sbin:/usr/sbin:/bin:/usr/bin HOME=/root USER=root LOGNAME=root /usr/libexec/qemu-kvm -device ? -device pci-assign,? -device virtio-blk-pci,? -device virtio-net-pci,? 17:45:48.578: 1961: debug : virCommandRunAsync:1214 : Command result 0, with PID 5486 .... 17:46:01.303: 1961: debug : virCommandRun:1084 : Result status 0, stdout: '' stderr: 'name "pci-bridge", bus PCI 17:46:01.316: 1961: debug : virExecWithHook:761 : LC_ALL=C PATH=/sbin:/usr/sbin:/bin:/usr/bin HOME=/root USER=root LOGNAME=root /usr/libexec/qemu-kvm -device ? -device pci-assign,? -device virtio-blk-pci,? -device virtio-net-pci,? 17:46:01.316: 1961: debug : virCommandRunAsync:1214 : Command result 0, with PID 5694 ... 17:46:19.330: 1961: debug : virCommandRun:1084 : Result status 0, stdout: '' stderr: 'name "pci-bridge", bus PCI 17:46:19.626: 1961: debug : virJSONValueToString:1062 : result={"execute":"qmp_capabilities"} 17:46:19.626: 1961: debug : virEventPollUpdateHandle:144 : Update handle w=31 e=15 17:46:19.626: 1961: debug : virEventPollInterruptLocked:690 : Interrupting ... 17:46:27.300: 1961: debug : virEventPollInterruptLocked:690 : Interrupting 17:46:27.300: 1961: debug : virJSONValueFromString:933 : string={"return": {}} Moreover, notice (it is not shown here, but in attached logs) when qemu outputs on stdout we pick output immediately.
(In reply to comment #5) > Haim, which version of libvirt you were running? Log inspection shows, we wait > too long on file descriptors to became available for I/O, although they are, > e.g.: > > 17:45:48.577: 1961: debug : virExecWithHook:761 : LC_ALL=C > PATH=/sbin:/usr/sbin:/bin:/usr/bin HOME=/root USER=root LOGNAME=root > /usr/libexec/qemu-kvm -device ? -device pci-assign,? -device virtio-blk-pci,? > -device virtio-net-pci,? > 17:45:48.578: 1961: debug : virCommandRunAsync:1214 : Command result 0, with > PID 5486 > .... > 17:46:01.303: 1961: debug : virCommandRun:1084 : Result status 0, stdout: '' > stderr: 'name "pci-bridge", bus PCI > > > 17:46:01.316: 1961: debug : virExecWithHook:761 : LC_ALL=C > PATH=/sbin:/usr/sbin:/bin:/usr/bin HOME=/root USER=root LOGNAME=root > /usr/libexec/qemu-kvm -device ? -device pci-assign,? -device virtio-blk-pci,? > -device virtio-net-pci,? > 17:46:01.316: 1961: debug : virCommandRunAsync:1214 : Command result 0, with > PID 5694 > ... > 17:46:19.330: 1961: debug : virCommandRun:1084 : Result status 0, stdout: '' > stderr: 'name "pci-bridge", bus PCI > > > 17:46:19.626: 1961: debug : virJSONValueToString:1062 : > result={"execute":"qmp_capabilities"} > 17:46:19.626: 1961: debug : virEventPollUpdateHandle:144 : Update handle w=31 > e=15 > 17:46:19.626: 1961: debug : virEventPollInterruptLocked:690 : Interrupting > ... > 17:46:27.300: 1961: debug : virEventPollInterruptLocked:690 : Interrupting > 17:46:27.300: 1961: debug : virJSONValueFromString:933 : string={"return": {}} > > > Moreover, notice (it is not shown here, but in attached logs) when qemu outputs > on stdout we pick output immediately. libvirt-0.9.1-1.el6.x86_64
Well, I can't see any problem in the code, but I might be wrong. What I still think of is qemu might be slow. I mean - it can, under some circumstances, take long qemu to write output and quit, which result in slow libvirt. So Haim, would you mind reproduce this, and when you reach the point, where everything is so lazy, just run qemu manually: LC_ALL=C PATH=/sbin:/usr/sbin:/bin:/usr/bin HOME=/root USER=root LOGNAME=root /usr/libexec/qemu-kvm -device ? -device pci-assign,? -device virtio-blk-pci,? -device virtio-net-pci,? This write something on stderr. If this command runs more than, say 5 seconds, I believe this is qemu issue. Thanks.