On Tue, 22 Aug 2023, Sean Christopherson wrote: > > Here is the whole log with 500,000+ lines over 5 minutes of recording, it > > was first stuck on one vcpu for most of the time, and toward the end it > > was stuck on a different VCPU: > > > > The file starts with 555,596 occurances of vcpu=ffff9964cdc48000 and is > > then followed by 31,784 occurances of vcpu=ffff9934ed50c680. As you can > > see in the file, they are not interleaved: > > > > https://www.linuxglobal.com/out/handle_ept_violation.log2 > > > > # awk '{print $3}' handle_ept_violation.log2 |uniq -c > > 555596 vcpu=ffff9964cdc48000 > > 31784 vcpu=ffff9934ed50c680 > > Hrm, but the address range being invalidated is changing. Without seeing the > guest RIP, or even a timestamp, it's impossible to tell if the vCPU is well and > truly stuck or if it's just getting thrashed so hard by NUMA balancing or KSM > that it looks stuck. > > Drat. > > > > Below is another bpftrace program that will hopefully shrink the > > > haystack to the point where we can find something via code inspection. > > > > Ok thanks, we'll give it a try. > > Try this version instead. It's more comprehensive and more precise, e.g. should > only trigger on the guest being 100% stuck, and also fixes a PID vs. TID goof. > > Note! Enable trace_kvm_exit before/when running this to ensure KVM grabs the guest RIP > from the VMCS. Without that enabled, RIP from vcpu->arch.regs[16] may be stale. Ok, we got a 740MB log, zips down to 25MB if you would like to see the whole thing, it is here: http://linuxglobal.com/out/handle_ept_violation-v2.log.gz For brevity, here is a sample of each 100,000th line: # zcat handle_ept_violation-v2.log.gz | perl -lne '!($n++%100000) && print' Attaching 3 probes... 00:30:31:347560 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (375972 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:32:047769 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (706308 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:32:746729 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (1039825 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:33:447298 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (1375881 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:34:160967 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (1715243 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:34:882187 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (2060501 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:35:597351 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (2402485 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:36:323613 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (2749250 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:37:039834 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (3090704 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:37:775801 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (3444375 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:38:564075 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (3824996 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:39:320611 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (4186268 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:40:006544 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (4514744 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:40:708219 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (4850395 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:41:424570 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (5195103 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:42:147032 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (5543824 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:42:878845 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (5887371 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:43:590424 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (6234881 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:44:308041 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (6581426 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:45:039868 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (6925844 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:45:773678 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (7278195 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:46:507469 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (7634480 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:47:252621 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (7997426 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:47:935297 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (8323684 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:48:626000 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (8654836 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:49:344852 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (8991281 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:50:239769 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (9414664 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:50:940747 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (9755243 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:51:666992 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (10101607 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:52:383241 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (10433521 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:53:105012 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (10785355 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:53:867494 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (11149981 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:54:632045 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (11515349 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:55:403662 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (11882055 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:56:182540 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (12251134 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:56:915633 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (12596230 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:57:658496 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (12939661 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:58:395829 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (13290046 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 00:30:59:186697 tid[553909] pid[553848] stuck @ rip ffffffff80094a41 (13670748 hits), gpa = 294a41, hva = 7efc5b094000 : MMU seq = 8000b139, in-prog = 0, start = 7efc6e10f000, end = 7efc6e110000 ... @same[553909]: 14142928 -- Eric Wheeler > > struct kvm_page_fault { > const u64 addr; > const u32 error_code; > const bool prefetch; > > const bool exec; > const bool write; > const bool present; > const bool rsvd; > const bool user; > > const bool is_tdp; > const bool nx_huge_page_workaround_enabled; > > bool huge_page_disallowed; > u8 max_level; > > u8 req_level; > > u8 goal_level; > > u64 gfn; > > struct kvm_memory_slot *slot; > > u64 pfn; > unsigned long hva; > bool map_writable; > }; > > kprobe:kvm_faultin_pfn > { > $vcpu = (struct kvm_vcpu *)arg0; > $kvm = $vcpu->kvm; > $rip = $vcpu->arch.regs[16]; > > if (@last_rip[tid] == $rip) { > @same[tid]++ > } else { > @same[tid] = 0; > } > @last_rip[tid] = $rip; > > if (@same[tid] > 1000) { > $fault = (struct kvm_page_fault *)arg1; > $hva = -1; > $flags = 0; > > if ($fault->slot != 0) { > $hva = $fault->slot->userspace_addr + > (($fault->gfn - $fault->slot->base_gfn) << 12); > $flags = $fault->slot->flags; > } > > printf("%s tid[%u] pid[%u] stuck @ rip %lx (%lu hits), gpa = %lx, hva = %lx : MMU seq = %lx, in-prog = %lx, start = %lx, end = %lx\n", > strftime("%H:%M:%S:%f", nsecs), tid, pid, $rip, @same[tid], $fault->addr, $hva, > $kvm->mmu_invalidate_seq, $kvm->mmu_invalidate_in_progress, > $kvm->mmu_invalidate_range_start, $kvm->mmu_invalidate_range_end); > } > } > > kprobe:make_mmio_spte > { > if (@same[tid] > 1000) { > $vcpu = (struct kvm_vcpu *)arg0; > $rip = $vcpu->arch.regs[16]; > > printf("%s tid[%u] pid[%u] stuck @ rip %lx made it to make_mmio_spte()\n", > strftime("%H:%M:%S:%f", nsecs), tid, pid, $rip); > } > } > > kprobe:make_spte > { > if (@same[tid] > 1000) { > $vcpu = (struct kvm_vcpu *)arg0; > $rip = $vcpu->arch.regs[16]; > > printf("%s tid[%u] pid[%u] stuck @ rip %lx made it to make_spte()\n", > strftime("%H:%M:%S:%f", nsecs), tid, pid, $rip); > } > } >
