From mboxrd@z Thu Jan 1 00:00:00 1970 From: Samuel Thibault Subject: Re: nested KVM slower than QEMU with gnumach guest kernel Date: Mon, 24 Nov 2014 01:42:51 +0100 Message-ID: <20141124004251.GA2589@type> References: <20141111185515.GA16376@type.youpi.perso.aquilenet.fr> <54629EFC.1050307@web.de> <20141116221828.GA13123@type> <54699587.9040109@web.de> Mime-Version: 1.0 Content-Type: text/plain; charset=iso-8859-1 Content-Transfer-Encoding: QUOTED-PRINTABLE Cc: kvm@vger.kernel.org, gleb@kernel.org, pbonzini@redhat.com To: Jan Kiszka Return-path: Received: from domu-toccata.ens-lyon.fr ([140.77.166.138]:46273 "EHLO sonata.ens-lyon.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751265AbaKXApQ (ORCPT ); Sun, 23 Nov 2014 19:45:16 -0500 Content-Disposition: inline In-Reply-To: <54699587.9040109@web.de> Sender: kvm-owner@vger.kernel.org List-ID: Jan Kiszka, le Mon 17 Nov 2014 07:28:23 +0100, a =E9crit : > I suppose this is a SMP host and guest? Does reducing CPUs to 1 chang= e > to picture? Oddly enough, putting my host into UniProcessor mode is making L1 realmode simulation awfully slow. That also happens when binding kvm o= n a single hardware thread like this: hwloc-bind pu:0 kvm ... but not when binding kvm on the two threads of the same core like this: hwloc-bind core:0 kvm ... =2E.. > > Here is a sample of trace-cmd output dump: the same kind of pattern > > repeats over and over, with EXTERNAL_INTERRUPT happening mostly > > every other microsecond: > >=20 > > qemu-system-x86-9752 [003] 4106.187755: kvm_exit: re= ason EXTERNAL_INTERRUPT rip 0xffffffffa02848b1 info 0 800000f6 > > qemu-system-x86-9752 [003] 4106.187756: kvm_entry: vc= pu 0 > > qemu-system-x86-9752 [003] 4106.187757: kvm_exit: re= ason EXTERNAL_INTERRUPT rip 0xffffffffa02848b1 info 0 800000f6 > > qemu-system-x86-9752 [003] 4106.187758: kvm_entry: vc= pu 0 > > qemu-system-x86-9752 [003] 4106.187759: kvm_exit: re= ason EXTERNAL_INTERRUPT rip 0xffffffffa02848b1 info 0 800000f6 > > qemu-system-x86-9752 [003] 4106.187760: kvm_entry: vc= pu 0 Turning into UniProcessor mode however dropped them, but the slowness is still there. So they are probably actually not the source of the issue. I'm actually wondering whether they weren't simply coming from the tracing engine itself: I see some irq_work_queue calls from kernel/trace/ring_buffer.c and kernel/events/core.c. > You may want to turn on more trace events, if not all, to possibly se= e > what Linux does then. With the EXTERNAL_INTERRUPT mostly away, I mostly get this over and ove= r: qemu-system-x86-2138 [000] 247.558705: kvm_exit: reaso= n MSR_READ rip 0xffffffff81050a82 info 0 0 native_read_msr_safe qemu-system-x86-2138 [000] 247.558705: kvm_msr: msr_r= ead 1d9 =3D 0x0 qemu-system-x86-2138 [000] 247.558705: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558706: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558706: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558706: kvm_exit: reaso= n VMRESUME rip 0xffffffffa03058ae info 0 0 vmx_vcpu_run qemu-system-x86-2138 [000] 247.558711: kvm_mmu_get_page: [FAIL= ED TO PARSE] mmu_valid_gen=3D0x26 gfn=3D248173 role=3D114692 root_count= =3D0 unsync=3D0 created=3D0 qemu-system-x86-2138 [000] 247.558712: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558712: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558712: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558712: kvm_exit: reaso= n IO_INSTRUCTION rip 0xc0109769 info a10040 0 gnumach accesses the PIC qemu-system-x86-2138 [000] 247.558713: kvm_nested_vmexit: rip: = 0x00000000c0109769 reason: IO_INSTRUCTION ext_inf1: 0x0000000000a10040 = ext_inf2: 0x0000000000000000 ext_int: 0x00000000 ext_int_err: 0x0000000= 0 qemu-system-x86-2138 [000] 247.558713: kvm_nested_vmexit_inject: r= eason: IO_INSTRUCTION ext_inf1: 0x0000000000a10040 ext_inf2: 0x00000000= 00000000 ext_int: 0x00000000 ext_int_err: 0x00000000 qemu-system-x86-2138 [000] 247.558718: kvm_mmu_get_page: [FAIL= ED TO PARSE] mmu_valid_gen=3D0x26 gfn=3D0 role=3D122884 root_count=3D0 = unsync=3D0 created=3D0 qemu-system-x86-2138 [000] 247.558718: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558719: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558719: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558719: kvm_exit: reaso= n VMREAD rip 0xffffffffa0305956 info 0 0 vmx_vcpu_run qemu-system-x86-2138 [000] 247.558720: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558720: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558720: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558721: kvm_exit: reaso= n VMREAD rip 0xffffffffa030596f info 0 0 vmx_vcpu_run qemu-system-x86-2138 [000] 247.558721: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558721: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558721: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558722: kvm_exit: reaso= n VMREAD rip 0xffffffffa02fb333 info 0 0 vmx_read_l1_tsc qemu-system-x86-2138 [000] 247.558722: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558722: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558722: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558723: kvm_exit: reaso= n VMREAD rip 0xffffffffa02fb54a info 0 0 vmx_handle_external_intr qemu-system-x86-2138 [000] 247.558723: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558724: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558724: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558724: kvm_exit: reaso= n VMREAD rip 0xffffffffa02ffe5f info 0 0 handle_io qemu-system-x86-2138 [000] 247.558725: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558725: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558725: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558726: kvm_exit: reaso= n VMREAD rip 0xffffffffa02fcce5 info 0 0 vmx_cache_reg qemu-system-x86-2138 [000] 247.558726: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558726: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558726: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558727: kvm_exit: reaso= n VMREAD rip 0xffffffffa02ffa2e info 0 0 skip_emulated_instruction qemu-system-x86-2138 [000] 247.558727: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558727: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558727: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558728: kvm_exit: reaso= n VMREAD rip 0xffffffffa02fb81a info 0 0 vmx_set_interrupt_shadow qemu-system-x86-2138 [000] 247.558728: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558728: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558728: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558729: kvm_exit: reaso= n VMREAD rip 0xffffffffa02fb270 info 0 0 vmx_get_rflags qemu-system-x86-2138 [000] 247.558730: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558730: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558730: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558730: kvm_exit: reaso= n VMREAD rip 0xffffffffa02fcbf5 info 0 0 vmx_interrupt_allowed qemu-system-x86-2138 [000] 247.558731: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558731: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558731: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558734: kvm_exit: reaso= n VMWRITE rip 0xffffffffa02fb7db info 0 0 vmx_get_cpl qemu-system-x86-2138 [000] 247.558735: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558735: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558735: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558736: kvm_exit: reaso= n VMWRITE rip 0xffffffffa02fb7db info 0 0 vmx_get_cpl qemu-system-x86-2138 [000] 247.558736: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558736: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558736: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558737: kvm_exit: reaso= n VMWRITE rip 0xffffffffa02fb7db info 0 0 vmx_get_cpl qemu-system-x86-2138 [000] 247.558737: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558737: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558737: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558738: kvm_exit: reaso= n VMWRITE rip 0xffffffffa02fb7db info 0 0 vmx_get_cpl qemu-system-x86-2138 [000] 247.558738: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558738: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558739: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558739: kvm_exit: reaso= n VMWRITE rip 0xffffffffa02fb7db info 0 0 vmx_get_cpl qemu-system-x86-2138 [000] 247.558740: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558740: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558740: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558740: kvm_exit: reaso= n MSR_READ rip 0xffffffff81050a82 info 0 0 native_read_msr_safe qemu-system-x86-2138 [000] 247.558741: kvm_msr: msr_r= ead 1d9 =3D 0x0 qemu-system-x86-2138 [000] 247.558741: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558741: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558741: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558741: kvm_exit: reaso= n VMRESUME rip 0xffffffffa03058ae info 0 0 vmx_vcpu_run qemu-system-x86-2138 [000] 247.558746: kvm_mmu_get_page: [FAIL= ED TO PARSE] mmu_valid_gen=3D0x26 gfn=3D248173 role=3D114692 root_count= =3D0 unsync=3D0 created=3D0 qemu-system-x86-2138 [000] 247.558747: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558747: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558747: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558748: kvm_exit: reaso= n IO_INSTRUCTION rip 0xc01095f5 info 210040 0 qemu-system-x86-2138 [000] 247.558748: kvm_nested_vmexit: rip: = 0x00000000c01095f5 reason: IO_INSTRUCTION ext_inf1: 0x0000000000210040 = ext_inf2: 0x0000000000000000 ext_int: 0x00000000 ext_int_err: 0x0000000= 0 qemu-system-x86-2138 [000] 247.558749: kvm_nested_vmexit_inject: r= eason: IO_INSTRUCTION ext_inf1: 0x0000000000210040 ext_inf2: 0x00000000= 00000000 ext_int: 0x00000000 ext_int_err: 0x00000000 qemu-system-x86-2138 [000] 247.558753: kvm_mmu_get_page: [FAIL= ED TO PARSE] mmu_valid_gen=3D0x26 gfn=3D0 role=3D122884 root_count=3D0 = unsync=3D0 created=3D0 qemu-system-x86-2138 [000] 247.558754: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558754: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558754: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558755: kvm_exit: reaso= n VMREAD rip 0xffffffffa0305956 info 0 0 vmx_vcpu_run qemu-system-x86-2138 [000] 247.558755: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558756: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558756: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558756: kvm_exit: reaso= n VMREAD rip 0xffffffffa030596f info 0 0 vmx_vcpu_run qemu-system-x86-2138 [000] 247.558757: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558757: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558757: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558757: kvm_exit: reaso= n VMREAD rip 0xffffffffa02fb333 info 0 0 vmx_read_l1_tsc qemu-system-x86-2138 [000] 247.558758: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558758: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558758: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558759: kvm_exit: reaso= n VMREAD rip 0xffffffffa02fb54a info 0 0 vmx_handle_external_intr qemu-system-x86-2138 [000] 247.558759: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558759: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558759: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558760: kvm_exit: reaso= n VMREAD rip 0xffffffffa02ffe5f info 0 0 handle_io qemu-system-x86-2138 [000] 247.558760: rcu_utilization: Start= context switch qemu-system-x86-2138 [000] 247.558760: rcu_utilization: End c= ontext switch qemu-system-x86-2138 [000] 247.558760: kvm_entry: vcpu = 0 qemu-system-x86-2138 [000] 247.558761: kvm_exit: reaso= n VMREAD rip 0xffffffffa02fcce5 info 0 0 vmx_cache_reg When running the same kind of operation with non-nested KVM, I get this kind of trace: qemu-system-x86-3667 [000] 1399.213498: kvm_exit: reaso= n IO_INSTRUCTION rip 0x801090c8 info 210040 0 qemu-system-x86-3667 [000] 1399.213498: kvm_pio: pio_w= rite at 0x21 size 1 count 1 val 0xff qemu-system-x86-3667 [000] 1399.213499: rcu_utilization: Start= context switch qemu-system-x86-3667 [000] 1399.213499: rcu_utilization: End c= ontext switch qemu-system-x86-3667 [000] 1399.213499: kvm_entry: vcpu = 0 qemu-system-x86-3667 [000] 1399.213500: kvm_exit: reaso= n IO_INSTRUCTION rip 0x801090d1 info a10040 0 qemu-system-x86-3667 [000] 1399.213500: kvm_pio: pio_w= rite at 0xa1 size 1 count 1 val 0xff=20 qemu-system-x86-3667 [000] 1399.213500: rcu_utilization: Start= context switch qemu-system-x86-3667 [000] 1399.213501: rcu_utilization: End c= ontext switch qemu-system-x86-3667 [000] 1399.213501: kvm_entry: vcpu = 0 qemu-system-x86-3667 [000] 1399.213501: kvm_exit: reaso= n IO_INSTRUCTION rip 0x80108f5d info 210040 0 qemu-system-x86-3667 [000] 1399.213501: kvm_pio: pio_w= rite at 0x21 size 1 count 1 val 0x68=20 qemu-system-x86-3667 [000] 1399.213502: rcu_utilization: Start= context switch qemu-system-x86-3667 [000] 1399.213502: rcu_utilization: End c= ontext switch qemu-system-x86-3667 [000] 1399.213502: kvm_entry: vcpu = 0 i.e. just one kvm_exit per guest IO instruction, not 18 like above, are those really expected? Samuel