From mboxrd@z Thu Jan 1 00:00:00 1970 From: Chris J Arges Subject: Re: kvm-unit-test failures Date: Tue, 02 Sep 2014 14:57:58 -0500 Message-ID: <54062146.9040609@canonical.com> References: <53FDDD3F.8050102@redhat.com> <1409150751-22763-1-git-send-email-chris.j.arges@canonical.com> <53FDF09F.4060007@redhat.com> <53FE4C7E.90201@canonical.com> <1018860798.37183509.1409177149937.JavaMail.zimbra@redhat.com> <5400BA22.9080704@canonical.com> <5400EB01.1080106@canonical.com> <540347AD.20308@redhat.com> Mime-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit Cc: kvm@vger.kernel.org To: Paolo Bonzini Return-path: Received: from youngberry.canonical.com ([91.189.89.112]:53771 "EHLO youngberry.canonical.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754137AbaIBT6D (ORCPT ); Tue, 2 Sep 2014 15:58:03 -0400 In-Reply-To: <540347AD.20308@redhat.com> Sender: kvm-owner@vger.kernel.org List-ID: On 08/31/2014 11:05 AM, Paolo Bonzini wrote: > Il 29/08/2014 23:05, Chris J Arges ha scritto: >> And indeed there is a condition where matched && already_matched are >> both true. In this case we don't zero or increment nr_vcpus_matched_tsc. >> Incrementing nr_vcpus_matched_tsc in that last else clause allows the >> test to pass; however this is identical to the logic before the patch. > > Can you please trace the test using trace-cmd > (http://www.linux-kvm.org/page/Tracing) and send the output? > > Paolo > Paolo, I have posted the trace data here: http://people.canonical.com/~arges/kvm/trace.dat.xz Here is the output from the actual test case: enabling apic enabling apic kvm-clock: cpu 0, msr 0x:44d4c0 kvm-clock: cpu 0, msr 0x:44d4c0 Wallclock test, threshold 5 Seconds get from host: 1409687073 Seconds get from kvmclock: 1409333034 Offset: -354039 offset too large! Check the stability of raw cycle ... Worst warp -354462672821748 Total vcpus: 2 Test loops: 10000000 Total warps: 1 Total stalls: 0 Worst warp: -354462672821748 Raw cycle is not stable Monotonic cycle test: Worst warp -354455286691490 Total vcpus: 2 Test loops: 10000000 Total warps: 1 Total stalls: 0 Worst warp: -354455286691490 Measure the performance of raw cycle ... Total vcpus: 2 Test loops: 10000000 TSC cycles: 1234719818 Measure the performance of adjusted cycle ... Total vcpus: 2 Test loops: 10000000 TSC cycles: 1234750103 I also enabled dynamic debugging on arch/x86/kvm/x86.c (on a separate run): [354558.460867] kvm_get_time_scale: base_khz 1000000 => 2593993, shift 2, mul 2785278775 [354558.461034] kvm: new tsc generation 1, clock 0 [354558.461812] kvm_get_time_scale: base_khz 1000000 => 2593993, shift 2, mul 2785278775 [354558.461846] kvm: matched tsc offset for 0 [354558.477542] kvm: matched tsc offset for 0 [354558.477614] kvm: matched tsc offset for 0 [354558.513729] kvm: matched tsc offset for 0 [354558.541724] kvm: matched tsc offset for 0 [354558.741532] kvm_get_time_scale: base_khz 2593993 => 1000000, shift -1, mul 3311471770 [354558.742551] kvm_get_time_scale: base_khz 2593993 => 1000000, shift -1, mul 3311471770 Also I ensured that this was reproducible with the latest qemu, and these results were gathered with the latest version as of today. Any other places to look into? --chris j arges