2:15 a.m.
On 11/15/18 3:16 AM, netsurfed wrote:
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@node1 datapool]# virsh -v
3.4.0
[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
[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
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
I wonder what is happening here. Anyway, it looks like you have some log
filters enabled. Do you think it is possible to turn them off and share
the log (e.g. on some file sharing service or just uploading it somewhere)?
Michal