- Users - libvirt List Archives

[libvirt-users] performance overhead with backing chains?
by Riccardo Ravaioli 15 Nov '18

15 Nov '18

Hi, I was wondering if there are any studies on the performance overhead of a QEMU/KVM virtual machine when the backing chain of its disk(s) is of size n, with n > 1. In particular, it would be useful to know until what size we can expect little or no impact on a Linux virtual machine, for instance. Thanks! Regards, Riccardo

1 0

[libvirt-users] create vm timeout
by netsurfed 15 Nov '18

15 Nov '18

Hi all: I create VM on most hypervisors very quickly, about 2 seconds. But some hypervisors are slow, taking more than 10 seconds. I started the debug log for libvirtd and found that some threads had timed out. Thread 95205 has two 5-second timeouts, but I don't know why? 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 Here are some log fragments: 2018-11-13 14:21:39.942+0000: 95205: debug : virEventPollRunOnce:650 : Poll got 0 event(s) 2018-11-13 14:21:39.942+0000: 95205: debug : virEventPollDispatchTimeouts:432 : Dispatch 2 2018-11-13 14:21:39.942+0000: 95205: info : virEventPollDispatchTimeouts:455 : EVENT_POLL_DISPATCH_TIMEOUT: timer=2 2018-11-13 14:21:39.942+0000: 95205: info : virObjectRef:296 : OBJECT_REF: obj=0x561dca9e7b60 2018-11-13 14:21:39.942+0000: 95205: info : virKeepAliveTimerInternal:136 : RPC_KEEPALIVE_TIMEOUT: ka=0x561dca9e7b60 client=0x561dca9e6e60 countToDeath=5 idle=5 2018-11-13 14:21:39.942+0000: 95205: debug : virNetMessageNew:46 : msg=0x561dca9e2880 tracked=0 2018-11-13 14:21:39.942+0000: 95205: debug : virNetMessageEncodePayloadEmpty:492 : Encode length as 28 2018-11-13 14:21:39.942+0000: 95205: debug : virKeepAliveMessage:104 : Sending keepalive request to client 0x561dca9e6e60 2018-11-13 14:21:39.942+0000: 95205: info : virKeepAliveMessage:107 : RPC_KEEPALIVE_SEND: ka=0x561dca9e7b60 client=0x561dca9e6e60 prog=1801807216 vers=1 proc=1 2018-11-13 14:21:39.942+0000: 95205: info : virEventPollUpdateTimeout:265 : EVENT_POLL_UPDATE_TIMEOUT: timer=2 frequency=5000 2018-11-13 14:21:39.942+0000: 95205: debug : virEventPollUpdateTimeout:282 : Set timer freq=5000 expires=1542118904942 2018-11-13 14:21:39.942+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip interrupt, 1 140197681715264 2018-11-13 14:21:39.942+0000: 95205: debug : virNetServerClientSendMessageLocked:1480 : msg=0x561dca9e2880 proc=1 len=28 offset=0 2018-11-13 14:21:39.942+0000: 95205: info : virNetServerClientSendMessageLocked:1488 : RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x561dca9e6e60 len=28 prog=1801807216 vers=1 proc=1 type=2 status=0 serial=0 2018-11-13 14:21:39.942+0000: 95205: debug : virNetServerClientCalculateHandleMode:166 : tls=(nil) hs=-1, rx=0x561dca9e1050 tx=0x561dca9e2880 2018-11-13 14:21:39.942+0000: 95205: debug : virNetServerClientCalculateHandleMode:201 : mode=3 2018-11-13 14:21:39.942+0000: 95205: info : virEventPollUpdateHandle:152 : EVENT_POLL_UPDATE_HANDLE: watch=12 events=3 2018-11-13 14:21:39.942+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip interrupt, 1 140197681715264 2018-11-13 14:21:39.942+0000: 95205: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x561dca9e7b60 2018-11-13 14:21:39.942+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2 2018-11-13 14:21:39.942+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12 2018-11-13 14:21:39.942+0000: 95205: debug : virEventRunDefaultImpl:311 : running default event implementation 2018-11-13 14:21:39.942+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2 2018-11-13 14:21:39.942+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=0 w=1, f=5 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=1 w=2, f=7 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=2 w=3, f=9 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=3 w=4, f=10 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=4 w=5, f=11 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=5 w=6, f=12 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=6 w=7, f=13 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=7 w=8, f=14 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=8 w=9, f=15 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=9 w=10, f=17 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=10 w=11, f=18 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=11 w=12, f=19 e=5 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCalculateTimeout:338 : Calculate expiry of 2 timers 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCalculateTimeout:346 : Got a timeout scheduled for 1542118904942 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCalculateTimeout:359 : Schedule timeout then=1542118904942 now=1542118899943 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCalculateTimeout:369 : Timeout at 1542118904942 due in 4999 ms 2018-11-13 14:21:39.943+0000: 95205: info : virEventPollRunOnce:640 : EVENT_POLL_RUN: nhandles=12 timeout=4999 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollRunOnce:650 : Poll got 1 event(s) 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchTimeouts:432 : Dispatch 2 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:478 : Dispatch 12 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=0 w=1 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=1 w=2 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=2 w=3 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=3 w=4 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=4 w=5 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=5 w=6 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=6 w=7 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=7 w=8 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=8 w=9 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=9 w=10 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=10 w=11 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=11 w=12 2018-11-13 14:21:39.943+0000: 95205: info : virEventPollDispatchHandles:506 : EVENT_POLL_DISPATCH_HANDLE: watch=12 events=2 2018-11-13 14:21:39.943+0000: 95205: debug : virNetMessageFree:87 : msg=0x561dca9e2880 nfds=0 cb=(nil) 2018-11-13 14:21:39.943+0000: 95205: debug : virNetServerClientCalculateHandleMode:166 : tls=(nil) hs=-1, rx=0x561dca9e1050 tx=(nil) 2018-11-13 14:21:39.943+0000: 95205: debug : virNetServerClientCalculateHandleMode:201 : mode=1 2018-11-13 14:21:39.943+0000: 95205: info : virEventPollUpdateHandle:152 : EVENT_POLL_UPDATE_HANDLE: watch=12 events=1 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip interrupt, 1 140197681715264 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12 2018-11-13 14:21:39.943+0000: 95205: debug : virEventRunDefaultImpl:311 : running default event implementation 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=0 w=1, f=5 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=1 w=2, f=7 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=2 w=3, f=9 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=3 w=4, f=10 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=4 w=5, f=11 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=5 w=6, f=12 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=6 w=7, f=13 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=7 w=8, f=14 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=8 w=9, f=15 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=9 w=10, f=17 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=10 w=11, f=18 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=11 w=12, f=19 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCalculateTimeout:338 : Calculate expiry of 2 timers 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCalculateTimeout:346 : Got a timeout scheduled for 1542118904942 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCalculateTimeout:359 : Schedule timeout then=1542118904942 now=1542118899943 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCalculateTimeout:369 : Timeout at 1542118904942 due in 4999 ms 2018-11-13 14:21:39.943+0000: 95205: info : virEventPollRunOnce:640 : EVENT_POLL_RUN: nhandles=12 timeout=4999 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollRunOnce:650 : Poll got 1 event(s) 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchTimeouts:432 : Dispatch 2 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:478 : Dispatch 12 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=0 w=1 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=1 w=2 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=2 w=3 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=3 w=4 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=4 w=5 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=5 w=6 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=6 w=7 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=7 w=8 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=8 w=9 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=9 w=10 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=10 w=11 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollDispatchHandles:492 : i=11 w=12 2018-11-13 14:21:39.943+0000: 95205: info : virEventPollDispatchHandles:506 : EVENT_POLL_DISPATCH_HANDLE: watch=12 events=1 2018-11-13 14:21:39.943+0000: 95205: debug : virNetMessageDecodeLength:161 : Got length, now need 28 total (24 more) 2018-11-13 14:21:39.943+0000: 95205: debug : virNetServerClientCalculateHandleMode:166 : tls=(nil) hs=-1, rx=0x561dca9e1050 tx=(nil) 2018-11-13 14:21:39.943+0000: 95205: debug : virNetServerClientCalculateHandleMode:201 : mode=1 2018-11-13 14:21:39.943+0000: 95205: info : virEventPollUpdateHandle:152 : EVENT_POLL_UPDATE_HANDLE: watch=12 events=1 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip interrupt, 1 140197681715264 2018-11-13 14:21:39.943+0000: 95205: info : virNetServerClientDispatchRead:1231 : RPC_SERVER_CLIENT_MSG_RX: client=0x561dca9e6e60 len=28 prog=1801807216 vers=1 proc=2 type=2 status=0 serial=0 2018-11-13 14:21:39.943+0000: 95205: debug : virKeepAliveCheckMessage:374 : ka=0x561dca9e7b60, client=0x561dca9e6e60, msg=0x561dca9e1050 2018-11-13 14:21:39.943+0000: 95205: info : virKeepAliveCheckMessage:391 : RPC_KEEPALIVE_RECEIVED: ka=0x561dca9e7b60 client=0x561dca9e6e60 prog=1801807216 vers=1 proc=2 2018-11-13 14:21:39.943+0000: 95205: debug : virKeepAliveCheckMessage:400 : Got keepalive response from client 0x561dca9e6e60 2018-11-13 14:21:39.943+0000: 95205: info : virEventPollUpdateTimeout:265 : EVENT_POLL_UPDATE_TIMEOUT: timer=2 frequency=5000 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollUpdateTimeout:282 : Set timer freq=5000 expires=1542118904943 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip interrupt, 1 140197681715264 2018-11-13 14:21:39.943+0000: 95205: debug : virNetMessageFree:87 : msg=0x561dca9e1050 nfds=0 cb=(nil) 2018-11-13 14:21:39.943+0000: 95205: debug : virNetMessageNew:46 : msg=0x561dca9e1050 tracked=1 2018-11-13 14:21:39.943+0000: 95205: debug : virNetServerClientCalculateHandleMode:166 : tls=(nil) hs=-1, rx=0x561dca9e1050 tx=(nil) 2018-11-13 14:21:39.943+0000: 95205: debug : virNetServerClientCalculateHandleMode:201 : mode=1 2018-11-13 14:21:39.943+0000: 95205: info : virEventPollUpdateHandle:152 : EVENT_POLL_UPDATE_HANDLE: watch=12 events=1 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip interrupt, 1 140197681715264 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12 2018-11-13 14:21:39.943+0000: 95205: debug : virEventRunDefaultImpl:311 : running default event implementation 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=0 w=1, f=5 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=1 w=2, f=7 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=2 w=3, f=9 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=3 w=4, f=10 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=4 w=5, f=11 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=5 w=6, f=12 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=6 w=7, f=13 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=7 w=8, f=14 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=8 w=9, f=15 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=9 w=10, f=17 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=10 w=11, f=18 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=11 w=12, f=19 e=1 d=0 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCalculateTimeout:338 : Calculate expiry of 2 timers 2018-11-13 14:21:39.943+0000: 95205: debug : virEventPollCalculateTimeout:346 : Got a timeout scheduled for 1542118904943 2018-11-13 14:21:39.944+0000: 95205: debug : virEventPollCalculateTimeout:359 : Schedule timeout then=1542118904943 now=1542118899944 2018-11-13 14:21:39.944+0000: 95205: debug : virEventPollCalculateTimeout:369 : Timeout at 1542118904943 due in 4999 ms 2018-11-13 14:21:39.944+0000: 95205: info : virEventPollRunOnce:640 : EVENT_POLL_RUN: nhandles=12 timeout=4999 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollRunOnce:650 : Poll got 0 event(s) 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchTimeouts:432 : Dispatch 2 2018-11-13 14:21:44.948+0000: 95205: info : virEventPollDispatchTimeouts:455 : EVENT_POLL_DISPATCH_TIMEOUT: timer=2 2018-11-13 14:21:44.948+0000: 95205: info : virObjectRef:296 : OBJECT_REF: obj=0x561dca9e7b60 2018-11-13 14:21:44.948+0000: 95205: info : virKeepAliveTimerInternal:136 : RPC_KEEPALIVE_TIMEOUT: ka=0x561dca9e7b60 client=0x561dca9e6e60 countToDeath=5 idle=5 2018-11-13 14:21:44.948+0000: 95205: debug : virNetMessageNew:46 : msg=0x561dca9e06b0 tracked=0 2018-11-13 14:21:44.948+0000: 95205: debug : virNetMessageEncodePayloadEmpty:492 : Encode length as 28 2018-11-13 14:21:44.948+0000: 95205: debug : virKeepAliveMessage:104 : Sending keepalive request to client 0x561dca9e6e60 2018-11-13 14:21:44.948+0000: 95205: info : virKeepAliveMessage:107 : RPC_KEEPALIVE_SEND: ka=0x561dca9e7b60 client=0x561dca9e6e60 prog=1801807216 vers=1 proc=1 2018-11-13 14:21:44.948+0000: 95205: info : virEventPollUpdateTimeout:265 : EVENT_POLL_UPDATE_TIMEOUT: timer=2 frequency=5000 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollUpdateTimeout:282 : Set timer freq=5000 expires=1542118909948 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip interrupt, 1 140197681715264 2018-11-13 14:21:44.948+0000: 95205: debug : virNetServerClientSendMessageLocked:1480 : msg=0x561dca9e06b0 proc=1 len=28 offset=0 2018-11-13 14:21:44.948+0000: 95205: info : virNetServerClientSendMessageLocked:1488 : RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x561dca9e6e60 len=28 prog=1801807216 vers=1 proc=1 type=2 status=0 serial=0 2018-11-13 14:21:44.948+0000: 95205: debug : virNetServerClientCalculateHandleMode:166 : tls=(nil) hs=-1, rx=0x561dca9e1050 tx=0x561dca9e06b0 2018-11-13 14:21:44.948+0000: 95205: debug : virNetServerClientCalculateHandleMode:201 : mode=3 2018-11-13 14:21:44.948+0000: 95205: info : virEventPollUpdateHandle:152 : EVENT_POLL_UPDATE_HANDLE: watch=12 events=3 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip interrupt, 1 140197681715264 2018-11-13 14:21:44.948+0000: 95205: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x561dca9e7b60 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12 2018-11-13 14:21:44.948+0000: 95205: debug : virEventRunDefaultImpl:311 : running default event implementation 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=0 w=1, f=5 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=1 w=2, f=7 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=2 w=3, f=9 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=3 w=4, f=10 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=4 w=5, f=11 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=5 w=6, f=12 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=6 w=7, f=13 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=7 w=8, f=14 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=8 w=9, f=15 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=9 w=10, f=17 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=10 w=11, f=18 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=11 w=12, f=19 e=5 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCalculateTimeout:338 : Calculate expiry of 2 timers 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCalculateTimeout:346 : Got a timeout scheduled for 1542118909948 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCalculateTimeout:359 : Schedule timeout then=1542118909948 now=1542118904948 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCalculateTimeout:369 : Timeout at 1542118909948 due in 5000 ms 2018-11-13 14:21:44.948+0000: 95205: info : virEventPollRunOnce:640 : EVENT_POLL_RUN: nhandles=12 timeout=5000 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollRunOnce:650 : Poll got 1 event(s) 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchTimeouts:432 : Dispatch 2 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:478 : Dispatch 12 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=0 w=1 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=1 w=2 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=2 w=3 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=3 w=4 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=4 w=5 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=5 w=6 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=6 w=7 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=7 w=8 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=8 w=9 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=9 w=10 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=10 w=11 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=11 w=12 2018-11-13 14:21:44.948+0000: 95205: info : virEventPollDispatchHandles:506 : EVENT_POLL_DISPATCH_HANDLE: watch=12 events=2 2018-11-13 14:21:44.948+0000: 95205: debug : virNetMessageFree:87 : msg=0x561dca9e06b0 nfds=0 cb=(nil) 2018-11-13 14:21:44.948+0000: 95205: debug : virNetServerClientCalculateHandleMode:166 : tls=(nil) hs=-1, rx=0x561dca9e1050 tx=(nil) 2018-11-13 14:21:44.948+0000: 95205: debug : virNetServerClientCalculateHandleMode:201 : mode=1 2018-11-13 14:21:44.948+0000: 95205: info : virEventPollUpdateHandle:152 : EVENT_POLL_UPDATE_HANDLE: watch=12 events=1 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip interrupt, 1 140197681715264 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12 2018-11-13 14:21:44.948+0000: 95205: debug : virEventRunDefaultImpl:311 : running default event implementation 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=0 w=1, f=5 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=1 w=2, f=7 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=2 w=3, f=9 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=3 w=4, f=10 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=4 w=5, f=11 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=5 w=6, f=12 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=6 w=7, f=13 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=7 w=8, f=14 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=8 w=9, f=15 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=9 w=10, f=17 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=10 w=11, f=18 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=11 w=12, f=19 e=1 d=0 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCalculateTimeout:338 : Calculate expiry of 2 timers 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCalculateTimeout:346 : Got a timeout scheduled for 1542118909948 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCalculateTimeout:359 : Schedule timeout then=1542118909948 now=1542118904948 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollCalculateTimeout:369 : Timeout at 1542118909948 due in 5000 ms 2018-11-13 14:21:44.948+0000: 95205: info : virEventPollRunOnce:640 : EVENT_POLL_RUN: nhandles=12 timeout=5000 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollRunOnce:650 : Poll got 1 event(s) 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchTimeouts:432 : Dispatch 2 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:478 : Dispatch 12 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=0 w=1 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=1 w=2 2018-11-13 14:21:44.948+0000: 95205: debug : virEventPollDispatchHandles:492 : i=2 w=3 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollDispatchHandles:492 : i=3 w=4 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollDispatchHandles:492 : i=4 w=5 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollDispatchHandles:492 : i=5 w=6 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollDispatchHandles:492 : i=6 w=7 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollDispatchHandles:492 : i=7 w=8 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollDispatchHandles:492 : i=8 w=9 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollDispatchHandles:492 : i=9 w=10 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollDispatchHandles:492 : i=10 w=11 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollDispatchHandles:492 : i=11 w=12 2018-11-13 14:21:44.949+0000: 95205: info : virEventPollDispatchHandles:506 : EVENT_POLL_DISPATCH_HANDLE: watch=12 events=1 2018-11-13 14:21:44.949+0000: 95205: debug : virNetMessageDecodeLength:161 : Got length, now need 28 total (24 more) 2018-11-13 14:21:44.949+0000: 95205: debug : virNetServerClientCalculateHandleMode:166 : tls=(nil) hs=-1, rx=0x561dca9e1050 tx=(nil) 2018-11-13 14:21:44.949+0000: 95205: debug : virNetServerClientCalculateHandleMode:201 : mode=1 2018-11-13 14:21:44.949+0000: 95205: info : virEventPollUpdateHandle:152 : EVENT_POLL_UPDATE_HANDLE: watch=12 events=1 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip interrupt, 1 140197681715264 2018-11-13 14:21:44.949+0000: 95205: info : virNetServerClientDispatchRead:1231 : RPC_SERVER_CLIENT_MSG_RX: client=0x561dca9e6e60 len=28 prog=1801807216 vers=1 proc=2 type=2 status=0 serial=0 2018-11-13 14:21:44.949+0000: 95205: debug : virKeepAliveCheckMessage:374 : ka=0x561dca9e7b60, client=0x561dca9e6e60, msg=0x561dca9e1050 2018-11-13 14:21:44.949+0000: 95205: info : virKeepAliveCheckMessage:391 : RPC_KEEPALIVE_RECEIVED: ka=0x561dca9e7b60 client=0x561dca9e6e60 prog=1801807216 vers=1 proc=2 2018-11-13 14:21:44.949+0000: 95205: debug : virKeepAliveCheckMessage:400 : Got keepalive response from client 0x561dca9e6e60 2018-11-13 14:21:44.949+0000: 95205: info : virEventPollUpdateTimeout:265 : EVENT_POLL_UPDATE_TIMEOUT: timer=2 frequency=5000 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollUpdateTimeout:282 : Set timer freq=5000 expires=1542118909949 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip interrupt, 1 140197681715264 2018-11-13 14:21:44.949+0000: 95205: debug : virNetMessageFree:87 : msg=0x561dca9e1050 nfds=0 cb=(nil) 2018-11-13 14:21:44.949+0000: 95205: debug : virNetMessageNew:46 : msg=0x561dca9e1050 tracked=1 2018-11-13 14:21:44.949+0000: 95205: debug : virNetServerClientCalculateHandleMode:166 : tls=(nil) hs=-1, rx=0x561dca9e1050 tx=(nil) 2018-11-13 14:21:44.949+0000: 95205: debug : virNetServerClientCalculateHandleMode:201 : mode=1 2018-11-13 14:21:44.949+0000: 95205: info : virEventPollUpdateHandle:152 : EVENT_POLL_UPDATE_HANDLE: watch=12 events=1 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip interrupt, 1 140197681715264 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12 2018-11-13 14:21:44.949+0000: 95205: debug : virEventRunDefaultImpl:311 : running default event implementation 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=0 w=1, f=5 e=1 d=0 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=1 w=2, f=7 e=1 d=0 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=2 w=3, f=9 e=1 d=0 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=3 w=4, f=10 e=1 d=0 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=4 w=5, f=11 e=1 d=0 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=5 w=6, f=12 e=1 d=0 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=6 w=7, f=13 e=1 d=0 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=7 w=8, f=14 e=1 d=0 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=8 w=9, f=15 e=1 d=0 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=9 w=10, f=17 e=1 d=0 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=10 w=11, f=18 e=1 d=0 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=11 w=12, f=19 e=1 d=0 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollCalculateTimeout:338 : Calculate expiry of 2 timers 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollCalculateTimeout:346 : Got a timeout scheduled for 1542118909949 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollCalculateTimeout:359 : Schedule timeout then=1542118909949 now=1542118904949 2018-11-13 14:21:44.949+0000: 95205: debug : virEventPollCalculateTimeout:369 : Timeout at 1542118909949 due in 5000 ms 2018-11-13 14:21:44.949+0000: 95205: info : virEventPollRunOnce:640 : EVENT_POLL_RUN: nhandles=12 timeout=5000 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollRunOnce:650 : Poll got 0 event(s) 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollDispatchTimeouts:432 : Dispatch 2 2018-11-13 14:21:49.954+0000: 95205: info : virEventPollDispatchTimeouts:455 : EVENT_POLL_DISPATCH_TIMEOUT: timer=2 2018-11-13 14:21:49.954+0000: 95205: info : virObjectRef:296 : OBJECT_REF: obj=0x561dca9e7b60 2018-11-13 14:21:49.954+0000: 95205: info : virKeepAliveTimerInternal:136 : RPC_KEEPALIVE_TIMEOUT: ka=0x561dca9e7b60 client=0x561dca9e6e60 countToDeath=5 idle=5 2018-11-13 14:21:49.954+0000: 95205: debug : virNetMessageNew:46 : msg=0x561dca9d9d90 tracked=0 2018-11-13 14:21:49.954+0000: 95205: debug : virNetMessageEncodePayloadEmpty:492 : Encode length as 28 2018-11-13 14:21:49.954+0000: 95205: debug : virKeepAliveMessage:104 : Sending keepalive request to client 0x561dca9e6e60 2018-11-13 14:21:49.954+0000: 95205: info : virKeepAliveMessage:107 : RPC_KEEPALIVE_SEND: ka=0x561dca9e7b60 client=0x561dca9e6e60 prog=1801807216 vers=1 proc=1 2018-11-13 14:21:49.954+0000: 95205: info : virEventPollUpdateTimeout:265 : EVENT_POLL_UPDATE_TIMEOUT: timer=2 frequency=5000 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollUpdateTimeout:282 : Set timer freq=5000 expires=1542118914954 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip interrupt, 1 140197681715264 2018-11-13 14:21:49.954+0000: 95205: debug : virNetServerClientSendMessageLocked:1480 : msg=0x561dca9d9d90 proc=1 len=28 offset=0 2018-11-13 14:21:49.954+0000: 95205: info : virNetServerClientSendMessageLocked:1488 : RPC_SERVER_CLIENT_MSG_TX_QUEUE: client=0x561dca9e6e60 len=28 prog=1801807216 vers=1 proc=1 type=2 status=0 serial=0 2018-11-13 14:21:49.954+0000: 95205: debug : virNetServerClientCalculateHandleMode:166 : tls=(nil) hs=-1, rx=0x561dca9e1050 tx=0x561dca9d9d90 2018-11-13 14:21:49.954+0000: 95205: debug : virNetServerClientCalculateHandleMode:201 : mode=3 2018-11-13 14:21:49.954+0000: 95205: info : virEventPollUpdateHandle:152 : EVENT_POLL_UPDATE_HANDLE: watch=12 events=3 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip interrupt, 1 140197681715264 2018-11-13 14:21:49.954+0000: 95205: info : virObjectUnref:259 : OBJECT_UNREF: obj=0x561dca9e7b60 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12 2018-11-13 14:21:49.954+0000: 95205: debug : virEventRunDefaultImpl:311 : running default event implementation 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=0 w=1, f=5 e=1 d=0 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=1 w=2, f=7 e=1 d=0 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=2 w=3, f=9 e=1 d=0 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=3 w=4, f=10 e=1 d=0 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=4 w=5, f=11 e=1 d=0 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=5 w=6, f=12 e=1 d=0 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=6 w=7, f=13 e=1 d=0 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=7 w=8, f=14 e=1 d=0 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=8 w=9, f=15 e=1 d=0 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=9 w=10, f=17 e=1 d=0 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=10 w=11, f=18 e=1 d=0 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=11 w=12, f=19 e=5 d=0 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollCalculateTimeout:338 : Calculate expiry of 2 timers 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollCalculateTimeout:346 : Got a timeout scheduled for 1542118914954 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollCalculateTimeout:359 : Schedule timeout then=1542118914954 now=1542118909954 2018-11-13 14:21:49.954+0000: 95205: debug : virEventPollCalculateTimeout:369 : Timeout at 1542118914954 due in 5000 ms 2018-11-13 14:21:49.955+0000: 95205: info : virEventPollRunOnce:640 : EVENT_POLL_RUN: nhandles=12 timeout=5000 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollRunOnce:650 : Poll got 1 event(s) 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchTimeouts:432 : Dispatch 2 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:478 : Dispatch 12 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=0 w=1 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=1 w=2 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=2 w=3 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=3 w=4 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=4 w=5 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=5 w=6 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=6 w=7 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=7 w=8 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=8 w=9 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=9 w=10 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=10 w=11 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollDispatchHandles:492 : i=11 w=12 2018-11-13 14:21:49.955+0000: 95205: info : virEventPollDispatchHandles:506 : EVENT_POLL_DISPATCH_HANDLE: watch=12 events=2 2018-11-13 14:21:49.955+0000: 95205: debug : virNetMessageFree:87 : msg=0x561dca9d9d90 nfds=0 cb=(nil) 2018-11-13 14:21:49.955+0000: 95205: debug : virNetServerClientCalculateHandleMode:166 : tls=(nil) hs=-1, rx=0x561dca9e1050 tx=(nil) 2018-11-13 14:21:49.955+0000: 95205: debug : virNetServerClientCalculateHandleMode:201 : mode=1 2018-11-13 14:21:49.955+0000: 95205: info : virEventPollUpdateHandle:152 : EVENT_POLL_UPDATE_HANDLE: watch=12 events=1 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollInterruptLocked:722 : Skip interrupt, 1 140197681715264 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12 2018-11-13 14:21:49.955+0000: 95205: debug : virEventRunDefaultImpl:311 : running default event implementation 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollCleanupTimeouts:525 : Cleanup 2 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollCleanupHandles:574 : Cleanup 12 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=0 w=1, f=5 e=1 d=0 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=1 w=2, f=7 e=1 d=0 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=2 w=3, f=9 e=1 d=0 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=3 w=4, f=10 e=1 d=0 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=4 w=5, f=11 e=1 d=0 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=5 w=6, f=12 e=1 d=0 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=6 w=7, f=13 e=1 d=0 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=7 w=8, f=14 e=1 d=0 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=8 w=9, f=15 e=1 d=0 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=9 w=10, f=17 e=1 d=0 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=10 w=11, f=18 e=1 d=0 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollMakePollFDs:401 : Prepare n=11 w=12, f=19 e=1 d=0 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollCalculateTimeout:338 : Calculate expiry of 2 timers 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollCalculateTimeout:346 : Got a timeout scheduled for 1542118914954 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollCalculateTimeout:359 : Schedule timeout then=1542118914954 now=1542118909955 2018-11-13 14:21:49.955+0000: 95205: debug : virEventPollCalculateTimeout:369 : Timeout at 1542118914954 due in 4999 ms 2018-11-13 14:21:49.955+0000: 95205: info : virEventPollRunOnce:640 : EVENT_POLL_RUN: nhandles=12 timeout=4999

1 1

[libvirt-users] virsh reboot "in shutdown" state?
by Michael Taboada 13 Nov '18

13 Nov '18

Hi all, I've got a weird issue, and I'm trying to confirm if it's a bug, and if so, if there is a workaround until it is fixed. The situation is this: If I virsh reboot <domain> --mode acpi, it will actually reboot the domain cleanly (watching from the console allows me to see the full shutdown messages, followed by a bootup). However, after this point, virsh domstate <domain> provides the state "in shutdown". From what I read, this is only supposed to persist for more than a tiny fraction of a second if there was a problem killing qemu or cleaning up its resources which, to my knowledge, should not apply here since there is no killing of qemu involved, just an acpi signal sent to the domain. Am I wrong? Either way, the only way to run any start/stop type commands with virsh after running the reboot command is to destroy the domain, obviously not very practical. I've attached console output from my tests, and the log of the same time period below. System info: libvirt 4.8.0-2, qemu 3.0.0-3, linux 4.18.6.arch1-1, running on arch linux. Thanks, -Michael. ############################# Log of virsh commands: ############################# [lilmike@iof838 ~]$ virsh start test Domain test started [lilmike@iof838 ~]$ virsh domstate test running [lilmike@iof838 ~]$ virsh shutdown test --mode acpi Domain test is being shutdown [lilmike@iof838 ~]$ virsh domstate test shut off [lilmike@iof838 ~]$ sudo pgrep qemu-system 815 857 [lilmike@iof838 ~]$ virsh start test Domain test started [lilmike@iof838 ~]$ virsh domstate test running [lilmike@iof838 ~]$ virsh reboot test --mode acpi Domain test is being rebooted [lilmike@iof838 ~]$ virsh domstate test in shutdown [lilmike@iof838 ~]$ ############################# libvirt log file of domain: ############################# 2018-11-12 13:36:44.042+0000: starting up libvirt version: 4.8.0, qemu version: 3.0.0, kernel: 4.18.16-arch1-1-ARCH, hostname: mthost.mwtd.net LC_ALL=C PATH=/usr/local/sbin:/usr/local/bin:/usr/bin QEMU_AUDIO_DRV=spice /usr/bin/qemu-system-x86_64 -name guest=test,debug-threads=on -S -object secret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain-9-test/master-key.aes -machine pc-i440fx-3.0,accel=kvm,usb=off,vmport=off,dump-guest-core=off -cpu Westmere,vme=on,ss=on,pclmuldq=on,pcid=on,x2apic=on,tsc-deadline=on,hypervisor=on,arat=on,tsc_adjust=on,umip=on,pdpe1gb=on,rdtscp=on,topoext=on -m 1024 -realtime mlock=off -smp 1,sockets=1,cores=1,threads=1 -uuid 8060a1de-66e9-4300-8677-0fdb0f830379 -no-user-config -nodefaults -chardev socket,id=charmonitor,fd=52,server,nowait -mon chardev=charmonitor,id=monitor,mode=control -rtc base=utc,driftfix=slew -global kvm-pit.lost_tick_policy=delay -no-hpet -no-shutdown -global PIIX4_PM.disable_s3=1 -global PIIX4_PM.disable_s4=1 -boot menu=on,strict=on -device ich9-usb-ehci1,id=usb,bus=pci.0,addr=0x6.0x7 -device ich9-usb-uhci1,masterbus=usb.0,firstport=0,bus=pci.0,multifunction=on,addr=0x6 -device ich9-usb-uhci2,masterbus=usb.0,firstport=2,bus=pci.0,addr=0x6.0x1 -device ich9-usb-uhci3,masterbus=usb.0,firstport=4,bus=pci.0,addr=0x6.0x2 -device ahci,id=sata0,bus=pci.0,addr=0x7 -drive file=/var/lib/livecd/arch.iso,format=raw,if=none,id=drive-sata0-0-0,media=cdrom,readonly=on -device ide-cd,bus=sata0.0,drive=drive-sata0-0-0,id=sata0-0-0,bootindex=1 -netdev tap,fd=54,id=hostnet0 -device e1000,netdev=hostnet0,id=net0,mac=52:54:00:e1:28:d3,bus=pci.0,addr=0x3 -netdev tap,fd=55,id=hostnet1 -device e1000,netdev=hostnet1,id=net1,mac=52:54:00:74:d0:3f,bus=pci.0,addr=0x4 -chardev pty,id=charserial0 -device isa-serial,chardev=charserial0,id=serial0 -device usb-tablet,id=input0,bus=usb.0,port=1 -spice port=5902,addr=127.0.0.1,disable-ticketing,image-compression=off,seamless-migration=on -device qxl-vga,id=video0,ram_size=67108864,vram_size=67108864,vram64_size_mb=0,vgamem_mb=16,max_outputs=1,bus=pci.0,addr=0x2 -device intel-hda,id=sound0,bus=pci.0,addr=0x5 -device hda-duplex,id=sound0-codec0,bus=sound0.0,cad=0 -chardev spicevmc,id=charredir0,name=usbredir -device usb-redir,chardev=charredir0,id=redir0,bus=usb.0,port=2 -chardev spicevmc,id=charredir1,name=usbredir -device usb-redir,chardev=charredir1,id=redir1,bus=usb.0,port=3 -device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x8 -sandbox on,obsolete=deny,elevateprivileges=deny,spawn=deny,resourcecontrol=deny -msg timestamp=on 2018-11-12T13:36:44.112904Z qemu-system-x86_64: -chardev pty,id=charserial0: char device redirected to /dev/pts/3 (label charserial0) 2018-11-12T13:37:35.867474Z qemu-system-x86_64: terminating on signal 15 from pid 597 (/usr/bin/libvirtd) 2018-11-12 13:37:36.192+0000: shutting down, reason=shutdown 2018-11-12 13:37:52.035+0000: starting up libvirt version: 4.8.0, qemu version: 3.0.0, kernel: 4.18.16-arch1-1-ARCH, hostname: mthost.mwtd.net LC_ALL=C PATH=/usr/local/sbin:/usr/local/bin:/usr/bin QEMU_AUDIO_DRV=spice /usr/bin/qemu-system-x86_64 -name guest=test,debug-threads=on -S -object secret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain-10-test/master-key.aes -machine pc-i440fx-3.0,accel=kvm,usb=off,vmport=off,dump-guest-core=off -cpu Westmere,vme=on,ss=on,pclmuldq=on,pcid=on,x2apic=on,tsc-deadline=on,hypervisor=on,arat=on,tsc_adjust=on,umip=on,pdpe1gb=on,rdtscp=on,topoext=on -m 1024 -realtime mlock=off -smp 1,sockets=1,cores=1,threads=1 -uuid 8060a1de-66e9-4300-8677-0fdb0f830379 -no-user-config -nodefaults -chardev socket,id=charmonitor,fd=52,server,nowait -mon chardev=charmonitor,id=monitor,mode=control -rtc base=utc,driftfix=slew -global kvm-pit.lost_tick_policy=delay -no-hpet -no-shutdown -global PIIX4_PM.disable_s3=1 -global PIIX4_PM.disable_s4=1 -boot menu=on,strict=on -device ich9-usb-ehci1,id=usb,bus=pci.0,addr=0x6.0x7 -device ich9-usb-uhci1,masterbus=usb.0,firstport=0,bus=pci.0,multifunction=on,addr=0x6 -device ich9-usb-uhci2,masterbus=usb.0,firstport=2,bus=pci.0,addr=0x6.0x1 -device ich9-usb-uhci3,masterbus=usb.0,firstport=4,bus=pci.0,addr=0x6.0x2 -device ahci,id=sata0,bus=pci.0,addr=0x7 -drive file=/var/lib/livecd/arch.iso,format=raw,if=none,id=drive-sata0-0-0,media=cdrom,readonly=on -device ide-cd,bus=sata0.0,drive=drive-sata0-0-0,id=sata0-0-0,bootindex=1 -netdev tap,fd=54,id=hostnet0 -device e1000,netdev=hostnet0,id=net0,mac=52:54:00:e1:28:d3,bus=pci.0,addr=0x3 -netdev tap,fd=55,id=hostnet1 -device e1000,netdev=hostnet1,id=net1,mac=52:54:00:74:d0:3f,bus=pci.0,addr=0x4 -chardev pty,id=charserial0 -device isa-serial,chardev=charserial0,id=serial0 -device usb-tablet,id=input0,bus=usb.0,port=1 -spice port=5902,addr=127.0.0.1,disable-ticketing,image-compression=off,seamless-migration=on -device qxl-vga,id=video0,ram_size=67108864,vram_size=67108864,vram64_size_mb=0,vgamem_mb=16,max_outputs=1,bus=pci.0,addr=0x2 -device intel-hda,id=sound0,bus=pci.0,addr=0x5 -device hda-duplex,id=sound0-codec0,bus=sound0.0,cad=0 -chardev spicevmc,id=charredir0,name=usbredir -device usb-redir,chardev=charredir0,id=redir0,bus=usb.0,port=2 -chardev spicevmc,id=charredir1,name=usbredir -device usb-redir,chardev=charredir1,id=redir1,bus=usb.0,port=3 -device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x8 -sandbox on,obsolete=deny,elevateprivileges=deny,spawn=deny,resourcecontrol=deny -msg timestamp=on 2018-11-12T13:37:52.106657Z qemu-system-x86_64: -chardev pty,id=charserial0: char device redirected to /dev/pts/3 (label charserial0)

2 1

[libvirt-users] usb post passthough stopped workng after kernel upgrade
by daggs 09 Nov '18

09 Nov '18

Greetings, I have a vm on debian 9.5 to which I pass an specific usb from the host. here is the relevant part in the vm's xml file: <hostdev mode='subsystem' type='usb' managed='yes'> <source> <vendor id='0x148f'/> <product id='0x5572'/> </source> <address type='usb' bus='0' port='1'/> </hostdev> the address line was added automatically by libvirt. everything was working well with kernel 4.15.11-1~bpo9+1 until I needed to upgrade the kernel to latest possible version due to usb issues I've upgraded to 4.18.6-1~bpo9+1. after the upgrade, my vm doesn't starts anymore, I see this msg: error: Failed to start domain router error: internal error: qemu unexpectedly closed the monitor: 2018-11-02T13:43:32.174730Z qemu-system-x86_64: -device usb-host,hostbus=1,hostaddr=4,id=hostdev4,bus=usb.0,port=1: failed to find host usb device 1:4 how can a kernel upgrade cause this? is there a fix for this issue? Thanks, Dagg.

1 2

[libvirt-users] virsh dominfo not returning any stats
by Tony Lin 09 Nov '18

09 Nov '18

Hi there, We're running virsh on centos and hit a couple of issues. First instance is cpu.time not incrementing even with the VMs on the hypervisor running a stress tool. After running 'virsh domstats' sometimes it'll go into a state where no output is generated at all. Have anyone seen something like this? We're running a pretty recent build of libvirt. # virsh versionCompiled against library: libvirt 3.9.0Using library: libvirt 3.9.0Using API: QEMU 3.9.0RUNNING HYPERVISOR: QEMU 2.9.0 Through the two domstats we see that the cpu.time is not increasing, but vcpu.0.time is not. It's also not reporting a vcpu.0.wait on this centos hypervisor. # virsh domstats Domain: '3a1de3d0-9de3-4876-a51a-1337d2ad0b87' state.state=1 state.reason=5 cpu.time=18530581887 cpu.user=430000000 cpu.system=2910000000 balloon.current=786432 balloon.maximum=786432 vcpu.current=1 vcpu.maximum=1 vcpu.0.state=1 vcpu.0.time=1145240000000 # virsh domstats Domain: '3a1de3d0-9de3-4876-a51a-1337d2ad0b87' state.state=1 state.reason=5 cpu.time=18530581887 cpu.user=430000000 cpu.system=2910000000 balloon.current=786432 balloon.maximum=786432 vcpu.current=1 vcpu.maximum=1 vcpu.0.state=1 vcpu.0.time=1153920000000

1 0

[libvirt-users] Getting two different guest in the same network
by Tjaco 09 Nov '18

09 Nov '18

Dear list, Being a libvirt noob, I have some trouble understanding. It is about getting two different guest in the same network. *********** I've defined a network with libvirt. This is the source xml: <network> <name>private2</name> <uuid>9684f2c6-6fd0-491b-9cb5-80ee268b01ce</uuid> <bridge name='br2' stp='on' delay='0'/> <mac address='52:54:00:b0:0a:c5'/> <ip address='10.0.0.1' netmask='255.255.255.0'> <dhcp> <range start='10.0.0.20' end='10.0.0.254'/> </dhcp> </ip> <ip family='ipv6' address='2001:db8:ca2:3::1' prefix='64'> </ip> </network> There is no 'forward' identifier so this should define an isolated network. br2 Was not pre-defined, it appeard after defining this network with libvirt. *********** ps aux shows: /usr/sbin/dnsmasq --conf-file=/var/lib/libvirt/dnsmasq/private2.conf *********** ip a shows: 11: br2: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default qlen 1000 link/ether 52:54:00:b0:0a:c5 brd ff:ff:ff:ff:ff:ff inet 10.0.0.1/24 brd 10.0.0.255 scope global br2 valid_lft forever preferred_lft forever inet6 2001:db8:ca2:3::1/64 scope global valid_lft forever preferred_lft forever inet6 fe80::5054:ff:feb0:ac5/64 scope link valid_lft forever preferred_lft forever 12: br2-nic: <BROADCAST,MULTICAST> mtu 1500 qdisc fq_codel master br2 state DOWN group default qlen 1000 link/ether 52:54:00:b0:0a:c5 brd ff:ff:ff:ff:ff:ff *********** virsh net-list --all shows: Name State Autostart Persistent ---------------------------------------------------------- private2 active yes yes *********** Then I start two guests with different MAC-addresses and differt UUID's Both guests are set on DHCP. They share the same network config: <interface type='network'> <mac address='52:54:00:xx:xx:xx'/> <source network='private2'/> <model type='virtio'/> <address type='pci' domain='0x0000' bus='0x00' slot='0x03' function='0x0'/> </interface> Both guests take a lot of time to boot, waiting for network configuration. Then they end up having the same IP address, not able to communicate with each other. What am I missing? Your advise is much appreciated.

1 0

[libvirt-users] Problems getting nwfilter to work
by Marc 08 Nov '18

08 Nov '18

Hi folks, I'm using libvirt 3.9.0 running under CentOS 7.5. I want the guests, which are all within the same subnet (e.g. 10.0.0.x.), only talk to their default gateway (e.g. 10.0.0.1) but to each other. This is caused by a design issue of our network platform. I set up a filter rule and attached it to the interface of a guest using nwfilter-define: <filter name='private_ip' chain='ipv4'> <uuid>foobar</uuid> <rule action='accept' direction='out' priority='100'> <ip srcipaddr='$IP' dstipaddr='10.0.0.1'/> </rule> <rule action='accept' direction='in' priority='110'> <ip srcipaddr='10.0.0.1' dstipaddr='$IP'/> </rule> <rule action='drop' direction='inout' priority='500'> <all/> </rule> </filter> t simply doesn't work. The guest can talk to the other guests within the same subnet. All guests are connected to a bridge interface. The IP of the guest interface is defined in the guests' xml file. Is there any additional kernel module to load? The module br_netfilter is already loaded and /proc/sys/net/bridge/bridge-nf-call-iptables is set to 1. After hours of googling and testing I still couldn't find a solution. Please help! Thank you very much in advance Marc

1 0

[libvirt-users] How to find out what is deleting my vms
by Andy Gibbs 08 Nov '18

08 Nov '18

Hi, I have a CentOS-7 server running KVM but also oVirt. Recently, following updates, VMs not handled by oVirt have been deleting themselves after they shut down. Previously to this, I have not had any problems of this nature. I cannot say whether the problem is coming from oVirt updates or not. I am creating a VM using "virsh define myvm.xml" on the server, starting it through virt-manager on my local PC, performing work inside the VM and then closing down the operating system inside the VM, and then once it has completed shutting down it shows "Shutoff" as the status in virt-manager and then maybe 5 seconds later it disappears from the list entirely and has been deleted. To start the VM again, requires "virsh define myvm.xml" to be run again. What I cannot determine is **why** the VM is deleted. I am using "virsh define" which I understand should create a persistent VM, and I have enabled "audit_level=2" and "audit_logging=1" in libvirtd.conf but can't see anything helpful in the log output (although maybe I don't know what I'm looking for). Is anyone, please, able to help me work out what is deleting my VMs once they shut down ... and, if possible, why?! Many, many thanks, Andy

2 2

[libvirt-users] timeout on VM actions prone to hang
by Nikola Ciprich 08 Nov '18

08 Nov '18

Hi fellow libvirt users, I'd like to ask, whether somebody possibly dealt with similar problem we're hitting.. Some of libvirt VM operations (ie fs freeze) are prone to hang for long time, in case the guest agent is in some bad state.. My question is, if it's possible to set some timeout for such operations, or we have to deal with it ie with separate thread and some timers? we're using python libvirt bindings.. I'll appreciate any advice BR nik -- ------------------------------------- Ing. Nikola CIPRICH LinuxBox.cz, s.r.o. 28.rijna 168, 709 00 Ostrava tel.: +420 591 166 214 fax: +420 596 621 273 mobil: +420 777 093 799 www.linuxbox.cz mobil servis: +420 737 238 656 email servis: servis(a)linuxbox.cz -------------------------------------

3 2

[libvirt-users] libvirt with persistent device names
by Jan Marquardt 07 Nov '18

07 Nov '18

Hi, I am trying to create a logical volume storage pool with persistent device names for the block devices, because I can't/don't want to ensure that /dev/sd* names are persistent through reboots. virsh # pool-define-as web2067 logical - - /dev/disk/by-path/pci-0000:18:00.0-scsi-0:2:2:0 web2067 /dev/web2067 virsh # pool-build web2067 These two steps work as expected and the pv and the vg get created, but when I try to start the pool I get the following error: virsh # pool-start web2067 error: Failed to start pool web2067 error: unsupported configuration: cannot find any matching source devices for logical volume group 'web2067' If I do the same steps just with /dev/sdX instead of /dev/disk/by-path/..., the pool gets created correctly. This looks like a bug for me or am I wrong? If this is the case, is this and known issue and fixed in later versions? I am running Ubuntu 18.04 with libvirt in version 4.0.0. Best Regards Jan

2 2