[libvirt-users] libvirt call qemu to create vm need more than 10 seconds

Thu Nov 15 02:16:15 UTC 2018

Hi all:
    It takes more than 10 seconds to create a vm on a Dell R830 machine, but it takes less than 2 seconds on other machines. This is not normal, so I turned on the debug log for libvirtd. I analyzed the log and found that the time was spent on libvirtd calling qemu. Thread 95225 calls the qemuProcessLaunch interface at 14:22:30.129 and then builds the emulator command line, but the qemuDomainObjTaint method is called after 10 seconds. I tried to analyze the qemuProcessLaunch function to find the reason, but nothing was found. What is the cause?
Below some information about my hypervisor:
[root at node1 datapool]# virsh -v
3.4.0
[root at node1 datapool]# qemu-x86_64 --version
qemu-x86_64 version 2.9.0
Copyright (c) 2003-2017 Fabrice Bellard and the QEMU Project developers
[root at node1 datapool]# uname -a
Linux node1 3.10.0-693.el7.x86_64 #1 SMP Tue Aug 22 21:09:27 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
There are too many debug logs. I paste the log of thread 99225 below:


Line 58679: 2018-11-13 14:22:30.129+0000: 95225: debug : qemuProcessLaunch:5614 : vm=0x7f822c002fe0 name=6efd749c-3162-4ac4-90e6-b3fca6fde9bc id=1 asyncJob=6 incoming.launchURI=<null> incoming.deferredURI=<null> incoming.fd=-1 incoming.path=<null> snapshot=(nil) vmop=0 flags=0x11
Line 58680: 2018-11-13 14:22:30.129+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f80166f0
Line 58681: 2018-11-13 14:22:30.129+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f8257e60
Line 58682: 2018-11-13 14:22:30.129+0000: 95225: debug : qemuProcessLaunch:5634 : Creating domain log file
Line 58683: 2018-11-13 14:22:30.129+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f80166f0
Line 58684: 2018-11-13 14:22:30.129+0000: 95225: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f822c006560 classname=qemuDomainLogContext
Line 58685: 2018-11-13 14:22:30.129+0000: 95225: debug : qemuDomainLogContextNew:4563 : Context new 0x7f822c006560 stdioLogD=1
Line 58686: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetSocketNewConnectUNIX:640 : path=/var/run/libvirt/virtlogd-sock spawnDaemon=0 binary=<null>
Line 58687: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetSocketNewConnectUNIX:704 : connect() succeeded
Line 58688: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetSocketNew:236 : localAddr=0x7f8244ca5530 remoteAddr=0x7f8244ca55c0 fd=20 errfd=-1 pid=0
Line 58689: 2018-11-13 14:22:30.130+0000: 95225: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f822c00aab0 classname=virNetSocket
Line 58690: 2018-11-13 14:22:30.130+0000: 95225: info : virNetSocketNew:292 : RPC_SOCKET_NEW: sock=0x7f822c00aab0 fd=20 errfd=-1 pid=0 localAddr=127.0.0.1;0, remoteAddr=127.0.0.1;0
Line 58691: 2018-11-13 14:22:30.130+0000: 95225: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f822c00b1b0 classname=virNetClient
Line 58692: 2018-11-13 14:22:30.130+0000: 95225: info : virNetClientNew:328 : RPC_CLIENT_NEW: client=0x7f822c00b1b0 sock=0x7f822c00aab0
Line 58693: 2018-11-13 14:22:30.130+0000: 95225: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f822c00ac50 classname=virNetClientProgram
Line 58694: 2018-11-13 14:22:30.130+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f822c00ac50
Line 58695: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetMessageNew:46 : msg=0x7f822c00a900 tracked=0
Line 58696: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetMessageEncodePayload:387 : Encode length as 164
Line 58697: 2018-11-13 14:22:30.130+0000: 95225: info : virNetClientSendInternal:2120 : RPC_CLIENT_MSG_TX_QUEUE: client=0x7f822c00b1b0 len=164 prog=2270401305 vers=1 proc=1 type=0 status=0 serial=0
Line 58698: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetClientCallNew:2073 : New call 0x7f822c00acc0: msg=0x7f822c00a900, expectReply=1, nonBlock=0
Line 58699: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetClientIO:1879 : Outgoing message prog=2270401305 version=1 serial=0 proc=1 type=0 length=164 dispatch=(nil)
Line 58700: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetClientIO:1938 : We have the buck head=0x7f822c00acc0 call=0x7f822c00acc0
Line 58701: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetSocketUpdateIOCallback:2198 : Watch not registered on socket 0x7f822c00aab0
Line 58702: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetMessageDecodeLength:161 : Got length, now need 48 total (44 more)
Line 58703: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetMessageDecodeNumFDs:336 : Got 1 FDs from peer
Line 58704: 2018-11-13 14:22:30.130+0000: 95225: info : virNetSocketRecvFD:2048 : RPC_SOCKET_RECV_FD: sock=0x7f822c00aab0 fd=23
Line 58705: 2018-11-13 14:22:30.130+0000: 95225: info : virNetClientCallDispatch:1267 : RPC_CLIENT_MSG_RX: client=0x7f822c00b1b0 len=48 prog=2270401305 vers=1 proc=1 type=5 status=0 serial=0
Line 58706: 2018-11-13 14:22:30.130+0000: 95225: debug : virKeepAliveCheckMessage:374 : ka=(nil), client=0x7f82505b0086, msg=0x7f822c00b210
Line 58707: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetMessageClear:74 : msg=0x7f822c00b210 nfds=0
Line 58708: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetClientIOEventLoopPassTheBuck:1562 : Giving up the buck 0x7f822c00acc0
Line 58709: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetClientIOEventLoopPassTheBuck:1576 : No thread to pass the buck to
Line 58710: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetSocketUpdateIOCallback:2198 : Watch not registered on socket 0x7f822c00aab0
Line 58711: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetClientIO:1968 : All done with our call head=(nil) call=0x7f822c00acc0 rv=0
Line 58712: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetMessageFree:87 : msg=0x7f822c00a900 nfds=1 cb=(nil)
Line 58713: 2018-11-13 14:22:30.130+0000: 95225: debug : virFileClose:110 : Closed fd 23
Line 58714: 2018-11-13 14:22:30.130+0000: 95225: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f81f80166f0
Line 58715: 2018-11-13 14:22:30.130+0000: 95225: debug : qemuProcessLaunch:5640 : Building emulator command line
Line 58716: 2018-11-13 14:22:30.130+0000: 95225: debug : virFileClose:110 : Closed fd 23
Line 58717: 2018-11-13 14:22:30.130+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f80166f0
Line 58718: 2018-11-13 14:22:30.130+0000: 95225: debug : qemuBuildCommandLine:9894 : driver=0x7f81f8011790 def=0x7f822c00b7e0 mon=0x7f822c0062a0 json=1 qemuCaps=0x7f822c002e80 migrateURI=(null) snapshot=(nil) vmop=0
Line 58719: 2018-11-13 14:22:30.131+0000: 95225: debug : virArchFromHost:181 : Mapped x86_64 to 32 (x86_64)
Line 58720: 2018-11-13 14:22:30.131+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f8257e60
Line 58721: 2018-11-13 14:22:30.131+0000: 95225: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f81f8257e60
Line 58722: 2018-11-13 14:22:30.131+0000: 95225: debug : virCPUCheckFeature:817 : arch=x86_64, cpu=0x7f822c00c090, feature=svm
Line 58723: 2018-11-13 14:22:30.131+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f80166f0
Line 58724: 2018-11-13 14:22:30.131+0000: 95225: info : virNetDevProbeVnetHdr:208 : Enabling IFF_VNET_HDR
Line 58772: 2018-11-13 14:22:30.132+0000: 95225: debug : virNetDevSetMACInternal:277 : SIOCSIFHWADDR vnet0 MAC=fe:54:00:28:29:1d - Success
Line 58773: 2018-11-13 14:22:30.132+0000: 95225: debug : virFileClose:110 : Closed fd 25
Line 58775: 2018-11-13 14:22:30.132+0000: 95225: debug : virFileClose:110 : Closed fd 25
Line 58777: 2018-11-13 14:22:30.132+0000: 95225: debug : virFileClose:110 : Closed fd 25
Line 58782: 2018-11-13 14:22:30.132+0000: 95225: debug : virCommandRunAsync:2448 : About to run ovs-vsctl --timeout=5 -- --if-exists del-port vnet0 -- add-port lcs_br_1 vnet0 -- set Interface vnet0 'external-ids:attached-mac="52:54:00:28:29:1d"' -- set Interface vnet0 'external-ids:iface-id="04af9169-2c72-45e9-845d-3d162268728b"' -- set Interface vnet0 'external-ids:vm-id="6efd749c-3162-4ac4-90e6-b3fca6fde9bc"' -- set Interface vnet0 external-ids:iface-status=active
Line 58789: 2018-11-13 14:22:30.133+0000: 95225: debug : virFileClose:110 : Closed fd 25
Line 58791: 2018-11-13 14:22:30.133+0000: 95225: debug : virFileClose:110 : Closed fd 27
Line 58792: 2018-11-13 14:22:30.133+0000: 95225: debug : virFileClose:110 : Closed fd 29
Line 58793: 2018-11-13 14:22:30.133+0000: 95225: debug : virCommandRunAsync:2451 : Command result 0, with PID 95350
Line 58993: 2018-11-13 14:22:30.146+0000: 95225: debug : virCommandRun:2299 : Result status 0, stdout: '' stderr: '2018-11-13 14:22:30.136+0000: 95350: debug : virFileClose:110 : Closed fd 27
Line 58997: 2018-11-13 14:22:30.146+0000: 95225: debug : virFileClose:110 : Closed fd 26
Line 58998: 2018-11-13 14:22:30.146+0000: 95225: debug : virFileClose:110 : Closed fd 28
Line 58999: 2018-11-13 14:22:30.147+0000: 95225: debug : virFileClose:110 : Closed fd 25
Line 59000: 2018-11-13 14:22:30.147+0000: 95225: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f81f80166f0
Line 59001: 2018-11-13 14:22:30.147+0000: 95225: debug : virFileClose:110 : Closed fd 25
Line 59002: 2018-11-13 14:22:30.147+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f80166f0
Line 59003: 2018-11-13 14:22:30.147+0000: 95225: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f81f80166f0
Line 59004: 2018-11-13 14:22:30.147+0000: 95225: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f81f80166f0
Line 60062: 2018-11-13 14:22:40.161+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f80166f0
Line 60063: 2018-11-13 14:22:40.161+0000: 95225: warning : qemuDomainObjTaint:4415 : Domain id=1 name='6efd749c-3162-4ac4-90e6-b3fca6fde9bc' uuid=6efd749c-3162-4ac4-90e6-b3fca6fde9bc is tainted: high-privileges
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/libvirt-users/attachments/20181115/6f8bc6ab/attachment.htm>