Re: Deadlock due to EPT_VIOLATION

[Eric Wheeler <kvm@lists.ewheeler.net>]

On Mon, 21 Aug 2023, Sean Christopherson wrote:
> On Mon, Aug 21, 2023, Eric Wheeler wrote:
> > On Fri, 18 Aug 2023, Eric Wheeler wrote:
> > > On Fri, 18 Aug 2023, Sean Christopherson wrote:
> > > > On Thu, Aug 17, 2023, Eric Wheeler wrote:
> > > > > On Thu, 17 Aug 2023, Sean Christopherson wrote:
> > > > > > > > kprobe:handle_ept_violation
> > > > > > > > {
> > > > > > > > 	printf("vcpu = %lx pid = %u MMU seq = %lx, in-prog = %lx, start = %lx, end = %lx\n",
> > > > > > > > 	       arg0, ((struct kvm_vcpu *)arg0)->pid->numbers[0].nr,
> > > > > > > > 	       ((struct kvm_vcpu *)arg0)->kvm->mmu_invalidate_seq,
> > > > > > > > 	       ((struct kvm_vcpu *)arg0)->kvm->mmu_invalidate_in_progress,
> > > > > > > > 	       ((struct kvm_vcpu *)arg0)->kvm->mmu_invalidate_range_start,
> > > > > > > > 	       ((struct kvm_vcpu *)arg0)->kvm->mmu_invalidate_range_end);
> > > > > > > > }
> > > > > > > > 
> > > > > > > > If you don't have BTF info, we can still use a bpf program, but to get at the
> > > > > > > > fields of interested, I think we'd have to resort to pointer arithmetic with struct
> > > > > > > > offsets grab from your build.
> > > > > > > 
> > > > > > > We have BTF, so hurray for not needing struct offsets!
> > 
> > We found a new sample in 6.1.38, right after a lockup, where _all_ log 
> > entries show inprog=1, in case that is interesting. Here is a sample, 
> > there are 500,000+ entries so let me know if you want the whole log.
> > 
> > To me, these are opaque numbers.  What do they represent?  What are you looking for in them?
> 
> inprog is '1' if there is an in-progress mmu_notifier invalidation at the time
> of the EPT violation.  start/end are the range that is being invalidated _if_
> there is an in-progress invalidation.  If a vCPU were stuck with inprog=1, then
> the most likely scenario is that there's an unpaired invalidation, i.e. something
> started an invalidation but never completed it.
> 
> seq is a sequence count that is incremented when an invalidation completes, e.g.
> if a vCPU was stuck and seq were constantly changing, then it would mean that
> the primary MMU is invalidating the same range over and over so quickly that the
> vCPU can't make forward progress.

Here is another one, I think you described exactly this: the vcpu is 
always the same, and the sequence increments, forever:

      1 ept[0] vcpu=ffff9964cdc48000 seq=80854227 inprog=1 start=7fa3183a3000 end=7fa3183a4000
      1 ept[0] vcpu=ffff9964cdc48000 seq=80854228 inprog=1 start=7fa3183a3000 end=7fa3183a4000
      1 ept[0] vcpu=ffff9964cdc48000 seq=80854229 inprog=1 start=7fa3183a4000 end=7fa3183a5000
      1 ept[0] vcpu=ffff9964cdc48000 seq=8085422a inprog=1 start=7fa3183a4000 end=7fa3183a5000
      1 ept[0] vcpu=ffff9964cdc48000 seq=8085422b inprog=1 start=7fa3183a8000 end=7fa3183a9000
      2 ept[0] vcpu=ffff9964cdc48000 seq=8085422d inprog=1 start=7fa3183a9000 end=7fa3183aa000
      1 ept[0] vcpu=ffff9964cdc48000 seq=8085422e inprog=1 start=7fa3183a9000 end=7fa3183aa000
      1 ept[0] vcpu=ffff9964cdc48000 seq=80854232 inprog=1 start=7fa3183ac000 end=7fa3183ad000
      1 ept[0] vcpu=ffff9964cdc48000 seq=80854233 inprog=1 start=7fa3183ad000 end=7fa3183ae000
      1 ept[0] vcpu=ffff9964cdc48000 seq=80854235 inprog=1 start=7fa3183ae000 end=7fa3183af000
      1 ept[0] vcpu=ffff9964cdc48000 seq=80854236 inprog=1 start=7fa3183ae000 end=7fa3183af000

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

> 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.

> Just a heads up, if we don't find a smoking gun, I likely won't be able 
> to help beyond high level guidance as we're approaching what I can do 
> with bpftrace without a significant time investment (which I can't 
> make).

I understand, I'm grateful for your help, whatever you can offer.

-Eric

> 
> ---
> struct kvm_page_fault {
> 	const gpa_t 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;
> 
> 	gfn_t gfn;
> 
> 	struct kvm_memory_slot *slot;
> 
> 	kvm_pfn_t pfn;
> 	unsigned long hva;
> 	bool map_writable;
> };
> 
> kprobe:handle_ept_violation
> {
> 	$vcpu = (struct kvm_vcpu *)arg0;
> 	$nr_handled = $vcpu->stat.pf_emulate + $vcpu->stat.pf_fixed + $vcpu->stat.pf_spurious;
> 
> 	if (($vcpu->stat.pf_taken / 5) > $nr_handled) {
> 		printf("PID = %u stuck, taken = %lu, emulated = %lu, fixed = %lu, spurious = %lu\n",
> 		       pid, $vcpu->stat.pf_taken, $vcpu->stat.pf_emulate, $vcpu->stat.pf_fixed, $vcpu->stat.pf_spurious);
> 	}
> }
> 
> kprobe:kvm_faultin_pfn
> {
> 	$vcpu = (struct kvm_vcpu *)arg0;
> 	$nr_handled = $vcpu->stat.pf_emulate + $vcpu->stat.pf_fixed + $vcpu->stat.pf_spurious;
> 
> 	if (($vcpu->stat.pf_taken / 5) > $nr_handled) {
> 		$fault = (struct kvm_page_fault *)arg1;
> 		$flags = 0;
> 
> 		if ($fault->slot != 0) {
> 			$flags = $fault->slot->flags;
> 		}
> 
> 		printf("PID = %u stuck, reached kvm_faultin_pfn(), slot = %lx, flags = %lx\n",
> 		       pid, arg1, $flags);
> 	}
> }
> 
> kprobe:make_mmio_spte
> {
> 	$vcpu = (struct kvm_vcpu *)arg0;
> 	$nr_handled = $vcpu->stat.pf_emulate + $vcpu->stat.pf_fixed + $vcpu->stat.pf_spurious;
> 
> 	if (($vcpu->stat.pf_taken / 5) > $nr_handled) {
> 		printf("PID %u stuck, reached make_mmio_spte()", pid);
> 	}
> }
> 
> kprobe:make_spte
> {
> 	$vcpu = (struct kvm_vcpu *)arg0;
> 	$nr_handled = $vcpu->stat.pf_emulate + $vcpu->stat.pf_fixed + $vcpu->stat.pf_spurious;
> 
> 	if (($vcpu->stat.pf_taken / 5) > $nr_handled) {
> 		printf("PID %u stuck, reached make_spte()", pid);
> 	}
> }
> 
>