<div style="line-height:1.7;color:#000000;font-size:14px;font-family:Arial"><div>Hi all:</div><div> <span style="color: rgb(33, 33, 33); font-family: inherit; font-size: 16px; white-space: pre-wrap;">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?</span></div><div><div><pre style="width: 1076.34px;"><span style="color: rgb(33, 33, 33); font-family: inherit; font-size: 16px; white-space: pre-wrap;" class="">Below some information about my hypervisor:</span></pre></div><div><pre style="width: 1076.34px;"><span style="color: rgb(33, 33, 33); font-family: inherit; font-size: 16px; white-space: pre-wrap;" class="">[root@node1 datapool]# virsh -v 3.4.0</span></pre><pre style="width: 1076.34px;"><span style="color: rgb(33, 33, 33); font-family: inherit; font-size: 16px; white-space: pre-wrap;" class="">[root@node1 datapool]# qemu-x86_64 --version qemu-x86_64 version 2.9.0 Copyright (c) 2003-2017 Fabrice Bellard and the QEMU Project developers</span></pre><pre style="width: 1076.34px;"><span style="color: rgb(33, 33, 33); font-family: inherit; font-size: 16px; white-space: pre-wrap;" class="">[root@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</span></pre></div></div><div><span style="color: rgb(33, 33, 33); font-size: 16px;">There are too many debug logs. I paste the log of thread 99225 below:</span></div><div><br></div><div><div><span style="white-space:pre"> </span>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</div><div><span style="white-space:pre"> </span>Line 58680: 2018-11-13 14:22:30.129+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f80166f0</div><div><span style="white-space:pre"> </span>Line 58681: 2018-11-13 14:22:30.129+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f8257e60</div><div><span style="white-space:pre"> </span>Line 58682: 2018-11-13 14:22:30.129+0000: 95225: debug : qemuProcessLaunch:5634 : Creating domain log file</div><div><span style="white-space:pre"> </span>Line 58683: 2018-11-13 14:22:30.129+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f80166f0</div><div><span style="white-space:pre"> </span>Line 58684: 2018-11-13 14:22:30.129+0000: 95225: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f822c006560 classname=qemuDomainLogContext</div><div><span style="white-space:pre"> </span>Line 58685: 2018-11-13 14:22:30.129+0000: 95225: debug : qemuDomainLogContextNew:4563 : Context new 0x7f822c006560 stdioLogD=1</div><div><span style="white-space:pre"> </span>Line 58686: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetSocketNewConnectUNIX:640 : path=/var/run/libvirt/virtlogd-sock spawnDaemon=0 binary=<null></div><div><span style="white-space:pre"> </span>Line 58687: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetSocketNewConnectUNIX:704 : connect() succeeded</div><div><span style="white-space:pre"> </span>Line 58688: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetSocketNew:236 : localAddr=0x7f8244ca5530 remoteAddr=0x7f8244ca55c0 fd=20 errfd=-1 pid=0</div><div><span style="white-space:pre"> </span>Line 58689: 2018-11-13 14:22:30.130+0000: 95225: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f822c00aab0 classname=virNetSocket</div><div><span style="white-space:pre"> </span>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</div><div><span style="white-space:pre"> </span>Line 58691: 2018-11-13 14:22:30.130+0000: 95225: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f822c00b1b0 classname=virNetClient</div><div><span style="white-space:pre"> </span>Line 58692: 2018-11-13 14:22:30.130+0000: 95225: info : virNetClientNew:328 : RPC_CLIENT_NEW: client=0x7f822c00b1b0 sock=0x7f822c00aab0</div><div><span style="white-space:pre"> </span>Line 58693: 2018-11-13 14:22:30.130+0000: 95225: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f822c00ac50 classname=virNetClientProgram</div><div><span style="white-space:pre"> </span>Line 58694: 2018-11-13 14:22:30.130+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f822c00ac50</div><div><span style="white-space:pre"> </span>Line 58695: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetMessageNew:46 : msg=0x7f822c00a900 tracked=0</div><div><span style="white-space:pre"> </span>Line 58696: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetMessageEncodePayload:387 : Encode length as 164</div><div><span style="white-space:pre"> </span>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</div><div><span style="white-space:pre"> </span>Line 58698: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetClientCallNew:2073 : New call 0x7f822c00acc0: msg=0x7f822c00a900, expectReply=1, nonBlock=0</div><div><span style="white-space:pre"> </span>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)</div><div><span style="white-space:pre"> </span>Line 58700: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetClientIO:1938 : We have the buck head=0x7f822c00acc0 call=0x7f822c00acc0</div><div><span style="white-space:pre"> </span>Line 58701: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetSocketUpdateIOCallback:2198 : Watch not registered on socket 0x7f822c00aab0</div><div><span style="white-space:pre"> </span>Line 58702: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetMessageDecodeLength:161 : Got length, now need 48 total (44 more)</div><div><span style="white-space:pre"> </span>Line 58703: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetMessageDecodeNumFDs:336 : Got 1 FDs from peer</div><div><span style="white-space:pre"> </span>Line 58704: 2018-11-13 14:22:30.130+0000: 95225: info : virNetSocketRecvFD:2048 : RPC_SOCKET_RECV_FD: sock=0x7f822c00aab0 fd=23</div><div><span style="white-space:pre"> </span>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</div><div><span style="white-space:pre"> </span>Line 58706: 2018-11-13 14:22:30.130+0000: 95225: debug : virKeepAliveCheckMessage:374 : ka=(nil), client=0x7f82505b0086, msg=0x7f822c00b210</div><div><span style="white-space:pre"> </span>Line 58707: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetMessageClear:74 : msg=0x7f822c00b210 nfds=0</div><div><span style="white-space:pre"> </span>Line 58708: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetClientIOEventLoopPassTheBuck:1562 : Giving up the buck 0x7f822c00acc0</div><div><span style="white-space:pre"> </span>Line 58709: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetClientIOEventLoopPassTheBuck:1576 : No thread to pass the buck to</div><div><span style="white-space:pre"> </span>Line 58710: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetSocketUpdateIOCallback:2198 : Watch not registered on socket 0x7f822c00aab0</div><div><span style="white-space:pre"> </span>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</div><div><span style="white-space:pre"> </span>Line 58712: 2018-11-13 14:22:30.130+0000: 95225: debug : virNetMessageFree:87 : msg=0x7f822c00a900 nfds=1 cb=(nil)</div><div><span style="white-space:pre"> </span>Line 58713: 2018-11-13 14:22:30.130+0000: 95225: debug : virFileClose:110 : Closed fd 23</div><div><span style="white-space:pre"> </span>Line 58714: 2018-11-13 14:22:30.130+0000: 95225: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f81f80166f0</div><div><span style="white-space:pre"> </span>Line 58715: 2018-11-13 14:22:30.130+0000: 95225: debug : qemuProcessLaunch:5640 : Building emulator command line</div><div><span style="white-space:pre"> </span>Line 58716: 2018-11-13 14:22:30.130+0000: 95225: debug : virFileClose:110 : Closed fd 23</div><div><span style="white-space:pre"> </span>Line 58717: 2018-11-13 14:22:30.130+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f80166f0</div><div><span style="white-space:pre"> </span>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</div><div><span style="white-space:pre"> </span>Line 58719: 2018-11-13 14:22:30.131+0000: 95225: debug : virArchFromHost:181 : Mapped x86_64 to 32 (x86_64)</div><div><span style="white-space:pre"> </span>Line 58720: 2018-11-13 14:22:30.131+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f8257e60</div><div><span style="white-space:pre"> </span>Line 58721: 2018-11-13 14:22:30.131+0000: 95225: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f81f8257e60</div><div><span style="white-space:pre"> </span>Line 58722: 2018-11-13 14:22:30.131+0000: 95225: debug : virCPUCheckFeature:817 : arch=x86_64, cpu=0x7f822c00c090, feature=svm</div><div><span style="white-space:pre"> </span>Line 58723: 2018-11-13 14:22:30.131+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f80166f0</div><div><span style="white-space:pre"> </span>Line 58724: 2018-11-13 14:22:30.131+0000: 95225: info : virNetDevProbeVnetHdr:208 : Enabling IFF_VNET_HDR</div><div><span style="white-space:pre"> </span>Line 58772: 2018-11-13 14:22:30.132+0000: 95225: debug : virNetDevSetMACInternal:277 : SIOCSIFHWADDR vnet0 MAC=fe:54:00:28:29:1d - Success</div><div><span style="white-space:pre"> </span>Line 58773: 2018-11-13 14:22:30.132+0000: 95225: debug : virFileClose:110 : Closed fd 25</div><div><span style="white-space:pre"> </span>Line 58775: 2018-11-13 14:22:30.132+0000: 95225: debug : virFileClose:110 : Closed fd 25</div><div><span style="white-space:pre"> </span>Line 58777: 2018-11-13 14:22:30.132+0000: 95225: debug : virFileClose:110 : Closed fd 25</div><div><span style="white-space:pre"> </span>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</div><div><span style="white-space:pre"> </span>Line 58789: 2018-11-13 14:22:30.133+0000: 95225: debug : virFileClose:110 : Closed fd 25</div><div><span style="white-space:pre"> </span>Line 58791: 2018-11-13 14:22:30.133+0000: 95225: debug : virFileClose:110 : Closed fd 27</div><div><span style="white-space:pre"> </span>Line 58792: 2018-11-13 14:22:30.133+0000: 95225: debug : virFileClose:110 : Closed fd 29</div><div><span style="white-space:pre"> </span>Line 58793: 2018-11-13 14:22:30.133+0000: 95225: debug : virCommandRunAsync:2451 : Command result 0, with PID 95350</div><div><span style="white-space:pre"> </span>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</div><div><span style="white-space:pre"> </span>Line 58997: 2018-11-13 14:22:30.146+0000: 95225: debug : virFileClose:110 : Closed fd 26</div><div><span style="white-space:pre"> </span>Line 58998: 2018-11-13 14:22:30.146+0000: 95225: debug : virFileClose:110 : Closed fd 28</div><div><span style="white-space:pre"> </span>Line 58999: 2018-11-13 14:22:30.147+0000: 95225: debug : virFileClose:110 : Closed fd 25</div><div><span style="white-space:pre"> </span>Line 59000: 2018-11-13 14:22:30.147+0000: 95225: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f81f80166f0</div><div><span style="white-space:pre"> </span>Line 59001: 2018-11-13 14:22:30.147+0000: 95225: debug : virFileClose:110 : Closed fd 25</div><div><span style="white-space:pre"> </span>Line 59002: 2018-11-13 14:22:30.147+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f80166f0</div><div><span style="white-space:pre"> </span>Line 59003: 2018-11-13 14:22:30.147+0000: 95225: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f81f80166f0</div><div><span style="white-space:pre"> </span>Line 59004: 2018-11-13 14:22:30.147+0000: 95225: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x7f81f80166f0</div><div><span style="white-space:pre"> </span>Line 60062: 2018-11-13 14:22:40.161+0000: 95225: info : virObjectRef:296 : OBJECT_REF: obj=0x7f81f80166f0</div><div><span style="white-space:pre"> </span>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</div></div></div>