On 6/9/19 21:38, Brad Campbell wrote:
7022@1567775824.002106:kvm_vm_ioctl type 0xc008ae67, arg 0x7ffe13b0c970 7022@1567775824.002115:kvm_vm_ioctl type 0xc008ae67, arg 0x7ffe13b0c980 7022@1567775824.003122:kvm_vm_ioctl type 0xc008ae67, arg 0x7ffe13b0c970
Does this look familiar to anyone?
Ugh. System timer. So with the timer interrupt removed and an added trace on IRQ > 0: qxl/guest-0: 79096403248: qxldd: DrvCopyBits 14955@1567780063.149527:kvm_vcpu_ioctl cpu_index 2, type 0xae80, arg (nil) 14956@1567780063.150291:qxl_ring_res_put 0 #res=1 14955@1567780063.163672:kvm_run_exit cpu_index 2, reason 2 14955@1567780063.163688:qxl_io_write 0 native addr=4 (QXL_IO_NOTIFY_OOM) val=0 size=1 async=0 14955@1567780063.163704:qxl_spice_oom 0 14955@1567780063.163720:kvm_vcpu_ioctl cpu_index 2, type 0xae80, arg (nil) 14956@1567780063.163755:qxl_ring_command_check 0 native 14956@1567780063.163779:qxl_ring_res_push 0 native s#=0 res#=1 last=0x7f3c0d44b6e0 notify=yes 14956@1567780063.163816:qxl_ring_res_push_rest 0 ring 1/8 [326,325] 14956@1567780063.163841:qxl_send_events 0 1 14956@1567780063.163868:qxl_ring_cursor_check 0 native 14956@1567780063.163888:qxl_ring_command_check 0 native 14924@1567780063.163879:kvm_set_irq irq 11, level 1, status 1 14954@1567780063.163895:kvm_run_exit cpu_index 1, reason 2 14954@1567780063.163965:qxl_io_write 0 native addr=3 (QXL_IO_UPDATE_IRQ) val=0 size=1 async=0 14954@1567780063.164006:kvm_set_irq irq 11, level 0, status 1 14954@1567780063.164029:kvm_vcpu_ioctl cpu_index 1, type 0xae80, arg (nil) 14954@1567780063.164065:kvm_run_exit cpu_index 1, reason 2 14954@1567780063.164080:qxl_io_write 0 native addr=3 (QXL_IO_UPDATE_IRQ) val=0 size=1 async=0 14954@1567780063.164104:kvm_vcpu_ioctl cpu_index 1, type 0xae80, arg (nil) 14955@1567780063.266778:kvm_run_exit cpu_index 2, reason 2 14955@1567780063.266790:qxl_io_write 0 native addr=0 (QXL_IO_NOTIFY_CMD) val=0 size=1 async=0 14955@1567780063.266809:kvm_vcpu_ioctl cpu_index 2, type 0xae80, arg (nil) 14956@1567780063.266822:qxl_ring_cursor_check 0 native 14956@1567780063.266842:qxl_ring_command_check 0 native 79213750625 qxl-0/cmd: cmd @ 0x10000000104b598 draw: surface_id 0 type copy effect opaque src 100000001fecbf8 (id 9fe0870780 type 0 flags 0 width 1920 height 1080, fmt 8 flags 0 x 1920 y 1080 stride 7680 palette 0 data 100000001fecc28) area 1920x1080+0+0 rop 8 14956@1567780063.266983:qxl_ring_command_get 0 native 14956@1567780063.267044:qxl_ring_command_check 0 native 14956@1567780063.267070:qxl_ring_cursor_check 0 native 14956@1567780063.267087:qxl_ring_command_check 0 native 14956@1567780063.267109:qxl_ring_command_req_notification 0 14955@1567780063.267967:kvm_run_exit cpu_index 2, reason 2 14955@1567780063.267987:qxl_io_write 0 native addr=7 (QXL_IO_LOG) val=0 size=1 async=0 14955@1567780063.268015:qxl_io_log 0 qxldd: DrvCopyBits So if I'm not mistaken (for the nth time), we have KVM_RUN on cpu index 2 here: 14955@1567780063.163720:kvm_vcpu_ioctl cpu_index 2, type 0xae80, arg (nil) And it returns here : 14955@1567780063.266778:kvm_run_exit cpu_index 2, reason 2 Does that imply guest code is running for ~100ms on that vcpu? Brad -- An expert is a person who has found out by his own painful experience all the mistakes that one can make in a very narrow field. - Niels Bohr
