Re: [PATCH] smp/call: Detect stuck CSD locks

[Chris J Arges <chris.j.arges@canonical.com>]

On Mon, Apr 13, 2015 at 08:14:51AM +0200, Ingo Molnar wrote:
<snip> 
> > FYI, I'm working on getting better data at the moment and here is my approach:
> > * For the L0 kernel:
> >  - In arch/x86/kvm/lapic.c, I enabled 'apic_debug' to get more output (and print
> >    the addresses of various useful structures)
> >  - Setup crash to live dump kvm_lapic structures and associated registers for
> >    both vCPUs
> 
> It would also be nice to double check the stuck vCPU's normal CPU 
> state: is it truly able to receive interrupts? (IRQ flags are on, or 
> is it sitting in the idle loop, etc.?)
> 
> If the IRQ flag (in EFLAGS) is off then the vCPU is not able to 
> receive interrupts, regardless of local APIC state.
> 
> > * For the L1 kernel:
> >  - Dump a stacktrace when we detect a lockup.
> >  - Detect a lockup and try to not alter the state.
> >  - Have a reliable signal such that the L0 hypervisor can dump the lapic
> >    structures and registers when csd_lock_wait detects a softlockup.
> 
> I'd also suggest adding a printk() to IPI receipt, to make sure it's 
> not the CSD code that is not getting called into after the IPI resend 
> attempt. To make sure you only get messages after the CPU got stuck, 
> add a 'locked_up' flag that signals this, and only print the messages 
> if the lockup scenario is happening.
> 
> I'd do it by adding something like this to 
> kernel/smp.c::generic_smp_call_function_single_interrupt():
> 
> 	if (csd_locked_up)
> 		printk("CSD: Function call IPI callback on CPU#%d\n", raw_smp_processor_id());
> 
> Having this message in place would ensure that the IPI indeed did not 
> get generated on the stuck vCPU. (Because we'd not get this message.)
> 
> Thanks,
> 
> 	Ingo

Ingo,

Below are the patches and data I've gathered from the reproducer. My methodology
was as described previously; however I used gdb on the qemu process in order to
breakpoint L1 once we've detected the hang. This made dumping the kvm_lapic
structures on L0 more reliable.

Thanks,
--chris j arges

--

* L0 patch (against Ubuntu-3.13.x w/ b6b8a1451fc40412c57d1):

diff --git a/arch/x86/kvm/lapic.c b/arch/x86/kvm/lapic.c
index f52e300..4d96638 100644
--- a/arch/x86/kvm/lapic.c
+++ b/arch/x86/kvm/lapic.c
@@ -54,8 +54,7 @@
 
 #define APIC_BUS_CYCLE_NS 1
 
-/* #define apic_debug(fmt,arg...) printk(KERN_WARNING fmt,##arg) */
-#define apic_debug(fmt, arg...)
+#define apic_debug(fmt,arg...) printk(KERN_WARNING fmt,##arg)
 
 #define APIC_LVT_NUM			6
 /* 14 is the version for Xeon and Pentium 8.4.8*/
@@ -539,9 +538,6 @@ static void apic_update_ppr(struct kvm_lapic *apic)
 	else
 		ppr = isrv & 0xf0;
 
-	apic_debug("vlapic %p, ppr 0x%x, isr 0x%x, isrv 0x%x",
-		   apic, ppr, isr, isrv);
-
 	if (old_ppr != ppr) {
 		apic_set_reg(apic, APIC_PROCPRI, ppr);
 		if (ppr < old_ppr)
@@ -865,10 +861,10 @@ static void apic_send_ipi(struct kvm_lapic *apic)
 
 	trace_kvm_apic_ipi(icr_low, irq.dest_id);
 
-	apic_debug("icr_high 0x%x, icr_low 0x%x, "
+	apic_debug("apic_send_ipi-> kvm 0x%x vcpu 0x%x apic 0x%x icr_high 0x%x, icr_low 0x%x, "
 		   "short_hand 0x%x, dest 0x%x, trig_mode 0x%x, level 0x%x, "
 		   "dest_mode 0x%x, delivery_mode 0x%x, vector 0x%x\n",
-		   icr_high, icr_low, irq.shorthand, irq.dest_id,
+		   apic->vcpu->kvm, apic->vcpu, apic, icr_high, icr_low, irq.shorthand, irq.dest_id,
 		   irq.trig_mode, irq.level, irq.dest_mode, irq.delivery_mode,
 		   irq.vector);
 
* L1 patch (against latest v4.0):

diff --git a/kernel/smp.c b/kernel/smp.c
index f38a1e6..df75d3d 100644
--- a/kernel/smp.c
+++ b/kernel/smp.c
@@ -98,22 +98,67 @@ void __init call_function_init(void)
 	register_cpu_notifier(&hotplug_cfd_notifier);
 }
 
+/* Locking timeout in ms: */
+#define CSD_LOCK_TIMEOUT (2*1000ULL)
+
+/* Print this ID in every printk line we output, to be able to easily sort them apart: */
+static int csd_bug_count;
+static int csd_locked_up = 0;
+
 /*
  * csd_lock/csd_unlock used to serialize access to per-cpu csd resources
  *
  * For non-synchronous ipi calls the csd can still be in use by the
  * previous function call. For multi-cpu calls its even more interesting
  * as we'll have to ensure no other cpu is observing our csd.
+ *
+ * ( The overhead of deadlock detection is not a big problem, this is a
+ *   cpu_relax() loop that is actively wasting CPU cycles to poll for
+ *   completion. )
  */
-static void csd_lock_wait(struct call_single_data *csd)
+static void csd_lock_wait(struct call_single_data *csd, int cpu)
 {
-	while (csd->flags & CSD_FLAG_LOCK)
+	int bug_id = 0;
+	u64 ts0, ts1, ts_delta;
+
+	ts0 = sched_clock()/1000000;
+
+	if (unlikely(!csd_bug_count)) {
+		csd_bug_count++;
+		printk("csd: CSD deadlock debugging initiated!\n");
+	}
+
+	while (csd->flags & CSD_FLAG_LOCK) {
+		ts1 = sched_clock()/1000000;
+
+		ts_delta = ts1-ts0;
+		if (unlikely(ts_delta >= CSD_LOCK_TIMEOUT)) { /* Uh oh, it took too long. Why? */
+
+			bug_id = csd_bug_count;
+			csd_bug_count++;
+
+			ts0 = ts1; /* Re-start the timeout detection */
+
+			printk("csd: Detected non-responsive CSD lock (#%d) on CPU#%02d, waiting %Ld.%03Ld secs for CPU#%02d\n",
+				bug_id, raw_smp_processor_id(), ts_delta/1000ULL, ts_delta % 1000ULL, cpu);
+			if (cpu >= 0) {
+				/*printk("csd: Re-sending CSD lock (#%d) IPI from CPU#%02d to CPU#%02d\n", bug_id, raw_smp_processor_id(), cpu);
+				arch_send_call_function_single_ipi(cpu);
+				*/
+				csd_locked_up = 1;
+				panic("csd_lock_wait");
+			}
+			//dump_stack();
+		}
 		cpu_relax();
+	}
+	if (unlikely(bug_id))
+		printk("csd: CSD lock (#%d) got unstuck on CPU#%02d, CPU#%02d released the lock after all. Phew!\n", bug_id, raw_smp_processor_id(), cpu);
 }
 
 static void csd_lock(struct call_single_data *csd)
 {
-	csd_lock_wait(csd);
+	csd_lock_wait(csd, -1);
 	csd->flags |= CSD_FLAG_LOCK;
 
 	/*
@@ -191,7 +236,7 @@ static int generic_exec_single(int cpu, struct call_single_data *csd,
 		arch_send_call_function_single_ipi(cpu);
 
 	if (wait)
-		csd_lock_wait(csd);
+		csd_lock_wait(csd, cpu);
 
 	return 0;
 }
@@ -204,6 +249,9 @@ static int generic_exec_single(int cpu, struct call_single_data *csd,
  */
 void generic_smp_call_function_single_interrupt(void)
 {
+	if (csd_locked_up)
+		printk("CSD: Function call IPI callback on CPU#%d\n", raw_smp_processor_id());
+
 	flush_smp_call_function_queue(true);
 }
 
@@ -446,7 +494,7 @@ void smp_call_function_many(const struct cpumask *mask,
 			struct call_single_data *csd;
 
 			csd = per_cpu_ptr(cfd->csd, cpu);
-			csd_lock_wait(csd);
+			csd_lock_wait(csd, cpu);
 		}
 	}
 }

* L1 Kernel Log leading up to crash, I set the timeout for 2s.

[  177.324317] kvm [1671]: vcpu0 disabled perfctr wrmsr: 0xc1 data 0xffff
[  227.645275] csd: Detected non-responsive CSD lock (#1) on CPU#00, waiting 2.000 secs for CPU#01
[  227.687193] Kernel panic - not syncing: csd_lock_wait

Note: the L0 log mostly was available just to let me know which address the
kvm_lapic structures had. I wasn't able to grab this log in this run.

* Crash dump backtrace from L1:

crash> bt -a
PID: 26     TASK: ffff88013a4f1400  CPU: 0   COMMAND: "ksmd"
 #0 [ffff88013a5039f0] machine_kexec at ffffffff8109d3ec
 #1 [ffff88013a503a50] crash_kexec at ffffffff8114a763
 #2 [ffff88013a503b20] panic at ffffffff818068e0
 #3 [ffff88013a503ba0] csd_lock_wait at ffffffff8113f1e4
 #4 [ffff88013a503bf0] generic_exec_single at ffffffff8113f2d0
 #5 [ffff88013a503c60] smp_call_function_single at ffffffff8113f417
 #6 [ffff88013a503c90] smp_call_function_many at ffffffff8113f7a4
 #7 [ffff88013a503d20] flush_tlb_page at ffffffff810b3bf9
 #8 [ffff88013a503d50] ptep_clear_flush at ffffffff81205e5e
 #9 [ffff88013a503d80] try_to_merge_with_ksm_page at ffffffff8121a445
#10 [ffff88013a503e00] ksm_scan_thread at ffffffff8121ac0e
#11 [ffff88013a503ec0] kthread at ffffffff810df0fb
#12 [ffff88013a503f50] ret_from_fork at ffffffff8180fc98

PID: 1674   TASK: ffff8800ba4a9e00  CPU: 1   COMMAND: "qemu-system-x86"
 #0 [ffff88013fd05e20] crash_nmi_callback at ffffffff81091521
 #1 [ffff88013fd05e30] nmi_handle at ffffffff81062560
 #2 [ffff88013fd05ea0] default_do_nmi at ffffffff81062b0a
 #3 [ffff88013fd05ed0] do_nmi at ffffffff81062c88
 #4 [ffff88013fd05ef0] end_repeat_nmi at ffffffff81812241
    [exception RIP: vmx_vcpu_run+992]
    RIP: ffffffff8104cef0  RSP: ffff88013940bcb8  RFLAGS: 00000082
    RAX: 0000000080000202  RBX: ffff880139b30000  RCX: ffff880139b30000
    RDX: 0000000000000200  RSI: ffff880139b30000  RDI: ffff880139b30000
    RBP: ffff88013940bd28   R8: 00007fe192b71110   R9: 00007fe192b71140
    R10: 00007fff66407d00  R11: 00007fe1927f0060  R12: 0000000000000000
    R13: 0000000000000001  R14: 0000000000000001  R15: 0000000000000000
    ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
--- <NMI exception stack> ---
 #5 [ffff88013940bcb8] vmx_vcpu_run at ffffffff8104cef0
 #6 [ffff88013940bcf8] vmx_handle_external_intr at ffffffff81040c18
 #7 [ffff88013940bd30] kvm_arch_vcpu_ioctl_run at ffffffff8101b5ad
 #8 [ffff88013940be00] kvm_vcpu_ioctl at ffffffff81007894
 #9 [ffff88013940beb0] do_vfs_ioctl at ffffffff81253190
#10 [ffff88013940bf30] sys_ioctl at ffffffff81253411
#11 [ffff88013940bf80] system_call_fastpath at ffffffff8180fd4d
    RIP: 00007ff6f80f5337  RSP: 00007ff6ed833bd8  RFLAGS: 00000246
    RAX: ffffffffffffffda  RBX: ffffffff8180fd4d  RCX: 00007ff6f80f5337
    RDX: 0000000000000000  RSI: 000000000000ae80  RDI: 0000000000000010
    RBP: 00007ff6ffa7c430   R8: 0000000000000000   R9: 00000000ffffffff
    R10: 00000000000fed00  R11: 0000000000000246  R12: 00007ff6fe195240
    R13: 0000000000000000  R14: 0000000000000001  R15: 0000000000000000
    ORIG_RAX: 0000000000000010  CS: 0033  SS: 002b

* Looking at call_single_queue, CPU[1] has <flush_tlb_func>:

crash> p call_single_queue
PER-CPU DATA TYPE:
  struct llist_head call_single_queue;
PER-CPU ADDRESSES:
  [0]: ffff88013fc16540
  [1]: ffff88013fd16540
crash> list -s call_single_data 0xffff88013fc16540
ffff88013fc16540
struct call_single_data {
  llist = {
    next = 0x0
  }, 
  func = 0x0, 
  info = 0x0, 
  flags = 0
}
crash> list -s call_single_data 0xffff88013fd16540
ffff88013fd16540
struct call_single_data {
  llist = {
    next = 0xffff88013a503c08
  }, 
  func = 0x0, 
  info = 0x0, 
  flags = 0
}
ffff88013a503c08
struct call_single_data {
  llist = {
    next = 0x0
  }, 
  func = 0xffffffff810b37d0 <flush_tlb_func>, 
  info = 0xffff88013a503d00, 
  flags = 3
}

* Using a script as follows once I find out the addresses of the kvm_lapic
structures:

mod -S /usr/lib/debug/lib/modules > /dev/null                
p *(struct kvm_lapic *)${apic0}                              
rd ${regs0} 512 | grep -v '0000000000000000 0000000000000000'
p *(struct kvm_lapic *)${apic1}                              
rd ${regs1} 512 | grep -v '0000000000000000 0000000000000000'

* Normal dump of kvm_lapic structure and registers for each vCPU on L1 (before
the hang):

$1 = {
  base_address = 4276092928, 
  dev = {
    ops = 0xffffffffa01dc890 <apic_mmio_ops>
  }, 
  lapic_timer = {
    timer = {
      node = {
        node = {
          __rb_parent_color = 18446612183461255480, 
          rb_right = 0x0, 
          rb_left = 0x0
        }, 
        expires = {
          tv64 = 170867881314366
        }
      }, 
      _softexpires = {
        tv64 = 170867881314366
      }, 
      function = 0xffffffffa01c5f80 <apic_timer_fn>, 
      base = 0xffff880bff20d1a0, 
      state = 1, 
      start_pid = 13304, 
      start_site = 0xffffffff8108edd8 <hrtimer_start+24>, 
      start_comm = "qemu-system-x86"
    }, 
    period = 199816048, 
    timer_mode_mask = 131072, 
    tscdeadline = 0, 
    pending = {
      counter = 0
    }
  }, 
  divide_count = 16, 
  vcpu = 0xffff880be7443f00, 
  irr_pending = false, 
  isr_count = 0, 
  highest_isr_cache = -1, 
  regs = 0xffff880be91e6000, 
  vapic_addr = 0, 
  vapic_cache = {
    generation = 0, 
    gpa = 0, 
    hva = 0, 
    len = 0, 
    memslot = 0x0
  }, 
  pending_events = 0, 
  sipi_vector = 0
}
ffff880be91e6030:  0000000001050014 0000000000000000   ................
ffff880be91e60d0:  0000000000000001 0000000000000000   ................
ffff880be91e60e0:  00000000ffffffff 0000000000000000   ................
ffff880be91e60f0:  00000000000001ff 0000000000000000   ................
ffff880be91e6190:  000000000e200000 0000000000000000   .. .............
ffff880be91e6300:  00000000000000fd 0000000000000000   ................
ffff880be91e6310:  0000000000000001 0000000000000000   ................
ffff880be91e6320:  00000000000000ef 0000000000000000   ................
ffff880be91e6330:  0000000000010000 0000000000000000   ................
ffff880be91e6340:  0000000000010000 0000000000000000   ................
ffff880be91e6350:  0000000000010700 0000000000000000   ................
ffff880be91e6360:  0000000000000400 0000000000000000   ................
ffff880be91e6370:  00000000000000fe 0000000000000000   ................
ffff880be91e6380:  0000000000be8f37 0000000000000000   7...............
ffff880be91e63e0:  0000000000000003 0000000000000000   ................

020	Local APIC ID Register		= 0x0000000000000000
030	Local APIC Version Register	= 0x0000000001050014
0d0	Logical Destination Register	= 0x0000000000000001
0e0	Destination Format Register	= 0x00000000ffffffff
0f0	Spurious Interrupt Vector Reg	= 0x00000000000001ff
190	Trigger Mode Reg (TMR); 63:32	= 0x000000000e200000
300	Interrupt Cmd Reg (ICR); 0-31	= 0x00000000000000fd
310	Interrupt Cmd Reg (ICR); 32-63	= 0x0000000000000001
320	LVT Timer Register		= 0x00000000000000ef
330	LVT Thermal Sensor Register	= 0x0000000000010000
340	LVT Perf Mon Counter Reg	= 0x0000000000010000
350	LVT LINT0 Register		= 0x0000000000010700
360	LVT LINT1 Register		= 0x0000000000000400
370	LVT Error Register		= 0x00000000000000fe
380	Initial Count Reg (for Timer)	= 0x0000000000be8f37
3e0	Divide Cfg Reg (for Timer)	= 0x0000000000000003

$2 = {
  base_address = 4276092928, 
  dev = {
    ops = 0xffffffffa01dc890 <apic_mmio_ops>
  }, 
  lapic_timer = {
    timer = {
      node = {
        node = {
          __rb_parent_color = 18446612183483367104, 
          rb_right = 0x0, 
          rb_left = 0x0
        }, 
        expires = {
          tv64 = 170868457351683
        }
      }, 
      _softexpires = {
        tv64 = 170868457351683
      }, 
      function = 0xffffffffa01c5f80 <apic_timer_fn>, 
      base = 0xffff880bff26d1a0, 
      state = 1, 
      start_pid = 13305, 
      start_site = 0xffffffff8108edd8 <hrtimer_start+24>, 
      start_comm = "qemu-system-x86"
    }, 
    period = 955895056, 
    timer_mode_mask = 131072, 
    tscdeadline = 0, 
    pending = {
      counter = 0
    }
  }, 
  divide_count = 16, 
  vcpu = 0xffff880be7440000, 
  irr_pending = false, 
  isr_count = 0, 
  highest_isr_cache = -1, 
  regs = 0xffff880be78c1000, 
  vapic_addr = 0, 
  vapic_cache = {
    generation = 0, 
    gpa = 0, 
    hva = 0, 
    len = 0, 
    memslot = 0x0
  }, 
  pending_events = 0, 
  sipi_vector = 154
}
ffff880be78c1020:  0000000001000000 0000000000000000   ................
ffff880be78c1030:  0000000001050014 0000000000000000   ................
ffff880be78c10d0:  0000000000000002 0000000000000000   ................
ffff880be78c10e0:  00000000ffffffff 0000000000000000   ................
ffff880be78c10f0:  00000000000001ff 0000000000000000   ................
ffff880be78c1300:  00000000000000fd 0000000000000000   ................
ffff880be78c1320:  00000000000000ef 0000000000000000   ................
ffff880be78c1330:  0000000000010000 0000000000000000   ................
ffff880be78c1340:  0000000000010400 0000000000000000   ................
ffff880be78c1350:  0000000000010700 0000000000000000   ................
ffff880be78c1360:  0000000000010400 0000000000000000   ................
ffff880be78c1370:  00000000000000fe 0000000000000000   ................
ffff880be78c1380:  00000000038f9cd1 0000000000000000   ................
ffff880be78c13e0:  0000000000000003 0000000000000000   ................

020	Local APIC ID Register		= 0x0000000001000000
030	Local APIC Version Register	= 0x0000000001050014
0d0	Logical Destination Register	= 0x0000000000000002
0e0	Destination Format Register	= 0x00000000ffffffff
0f0	Spurious Interrupt Vector Reg	= 0x00000000000001ff
190	Trigger Mode Reg (TMR); 63:32	= 0x0000000000000000
300	Interrupt Cmd Reg (ICR); 0-31	= 0x00000000000000fd
310	Interrupt Cmd Reg (ICR); 32-63	= 0x0000000000000000
320	LVT Timer Register		= 0x00000000000000ef
330	LVT Thermal Sensor Register	= 0x0000000000010000
340	LVT Perf Mon Counter Reg	= 0x0000000000010400
350	LVT LINT0 Register		= 0x0000000000010700
360	LVT LINT1 Register		= 0x0000000000010400
370	LVT Error Register		= 0x00000000000000fe
380	Initial Count Reg (for Timer)	= 0x00000000038f9cd1
3e0	Divide Cfg Reg (for Timer)	= 0x0000000000000003

* Dump of kvm_lapic structure and registers for each vCPU on L1 when crash is
detected.

Note, I used qemu to trap on when we detect the hang in csd_lock_wait. This way
we should preserve the registers as they exist when we've detected the lockup.

$1 = {
  base_address = 4276092928, 
  dev = {
    ops = 0xffffffffa01dc890 <apic_mmio_ops>
  }, 
  lapic_timer = {
    timer = {
      node = {
        node = {
          __rb_parent_color = 18446612172786658320, 
          rb_right = 0xffff880bff24dce0, 
          rb_left = 0x0
        }, 
        expires = {
          tv64 = 170996305305003
        }
      }, 
      _softexpires = {
        tv64 = 170996305305003
      }, 
      function = 0xffffffffa01c5f80 <apic_timer_fn>, 
      base = 0xffff880bff24d1a0, 
      state = 0, 
      start_pid = 13304, 
      start_site = 0xffffffff8108edd8 <hrtimer_start+24>, 
      start_comm = "qemu-system-x86"
    }, 
    period = 3995184, 
    timer_mode_mask = 131072, 
    tscdeadline = 0, 
    pending = {
      counter = 1
    }
  }, 
  divide_count = 16, 
  vcpu = 0xffff880be7443f00, 
  irr_pending = false, 
  isr_count = 0, 
  highest_isr_cache = -1, 
  regs = 0xffff880be91e6000, 
  vapic_addr = 0, 
  vapic_cache = {
    generation = 0, 
    gpa = 0, 
    hva = 0, 
    len = 0, 
    memslot = 0x0
  }, 
  pending_events = 0, 
  sipi_vector = 0
}
ffff880be91e6030:  0000000001050014 0000000000000000   ................
ffff880be91e60d0:  0000000000000001 0000000000000000   ................
ffff880be91e60e0:  00000000ffffffff 0000000000000000   ................
ffff880be91e60f0:  00000000000001ff 0000000000000000   ................
ffff880be91e6190:  000000000e200000 0000000000000000   .. .............
ffff880be91e6300:  00000000000000fb 0000000000000000   ................
ffff880be91e6310:  0000000000000001 0000000000000000   ................
ffff880be91e6320:  00000000000000ef 0000000000000000   ................
ffff880be91e6330:  0000000000010000 0000000000000000   ................
ffff880be91e6340:  0000000000010000 0000000000000000   ................
ffff880be91e6350:  0000000000010700 0000000000000000   ................
ffff880be91e6360:  0000000000000400 0000000000000000   ................
ffff880be91e6370:  00000000000000fe 0000000000000000   ................
ffff880be91e6380:  000000000003cf63 0000000000000000   c...............
ffff880be91e63e0:  0000000000000003 0000000000000000   ................

020	Local APIC ID Register		= 0x0000000000000000
030	Local APIC Version Register	= 0x0000000001050014
0d0	Logical Destination Register	= 0x0000000000000001
0e0	Destination Format Register	= 0x00000000ffffffff
0f0	Spurious Interrupt Vector Reg	= 0x00000000000001ff
190	Trigger Mode Reg (TMR); 63:32	= 0x000000000e200000
300	Interrupt Cmd Reg (ICR); 0-31	= 0x00000000000000fb
310	Interrupt Cmd Reg (ICR); 32-63	= 0x0000000000000001
320	LVT Timer Register		= 0x00000000000000ef
330	LVT Thermal Sensor Register	= 0x0000000000010000
340	LVT Perf Mon Counter Reg	= 0x0000000000010000
350	LVT LINT0 Register		= 0x0000000000010700
360	LVT LINT1 Register		= 0x0000000000000400
370	LVT Error Register		= 0x00000000000000fe
380	Initial Count Reg (for Timer)	= 0x000000000003cf63
3e0	Divide Cfg Reg (for Timer)	= 0x0000000000000003

$2 = {
  base_address = 4276092928, 
  dev = {
    ops = 0xffffffffa01dc890 <apic_mmio_ops>
  }, 
  lapic_timer = {
    timer = {
      node = {
        node = {
          __rb_parent_color = 18446612172786662160, 
          rb_right = 0x0, 
          rb_left = 0x0
        }, 
        expires = {
          tv64 = 170994304769720
        }
      }, 
      _softexpires = {
        tv64 = 170994304769720
      }, 
      function = 0xffffffffa01c5f80 <apic_timer_fn>, 
      base = 0xffff880bff20d1a0, 
      state = 0, 
      start_pid = 13305, 
      start_site = 0xffffffff8108edd8 <hrtimer_start+24>, 
      start_comm = "qemu-system-x86"
    }, 
    period = 3422832, 
    timer_mode_mask = 131072, 
    tscdeadline = 0, 
    pending = {
      counter = 0
    }
  }, 
  divide_count = 16, 
  vcpu = 0xffff880be7440000, 
  irr_pending = true, 
  isr_count = 1, 
  highest_isr_cache = 251, 
  regs = 0xffff880be78c1000, 
  vapic_addr = 0, 
  vapic_cache = {
    generation = 0, 
    gpa = 0, 
    hva = 0, 
    len = 0, 
    memslot = 0x0
  }, 
  pending_events = 0, 
  sipi_vector = 154
}
ffff880be78c1020:  0000000001000000 0000000000000000   ................
ffff880be78c1030:  0000000001050014 0000000000000000   ................
ffff880be78c10a0:  00000000000000f0 0000000000000000   ................
ffff880be78c10d0:  0000000000000002 0000000000000000   ................
ffff880be78c10e0:  00000000ffffffff 0000000000000000   ................
ffff880be78c10f0:  00000000000001ff 0000000000000000   ................
ffff880be78c1170:  0000000008000000 0000000000000000   ................
ffff880be78c1250:  0000000000020000 0000000000000000   ................
ffff880be78c1260:  0000000000000002 0000000000000000   ................
ffff880be78c1270:  0000000000008000 0000000000000000   ................
ffff880be78c1300:  00000000000000fd 0000000000000000   ................
ffff880be78c1320:  00000000000000ef 0000000000000000   ................
ffff880be78c1330:  0000000000010000 0000000000000000   ................
ffff880be78c1340:  0000000000010400 0000000000000000   ................
ffff880be78c1350:  0000000000010700 0000000000000000   ................
ffff880be78c1360:  0000000000010400 0000000000000000   ................
ffff880be78c1370:  00000000000000fe 0000000000000000   ................
ffff880be78c1380:  00000000000343a7 0000000000000000   .C..............
ffff880be78c13e0:  0000000000000003 0000000000000000   ................

020	Local APIC ID Register		= 0x0000000001000000
030	Local APIC Version Register	= 0x0000000001050014
0a0	Processor Priority Reg (PPR)	= 0x00000000000000f0	*
0d0	Logical Destination Register	= 0x0000000000000002
0e0	Destination Format Register	= 0x00000000ffffffff
0f0	Spurious Interrupt Vector Reg	= 0x00000000000001ff
170	In-Service Reg (ISR); 255:224	= 0x0000000008000000	*
190	Trigger Mode Reg (TMR); 63:32	= 0x0000000000000000
250	Intr Req Reg (IRR); 191:160	= 0x0000000000020000	*
260	Intr Req Reg (IRR); 223:192	= 0x0000000000000002	*
270	Intr Req Reg (IRR); 255:224	= 0x0000000000008000	*
300	Interrupt Cmd Reg (ICR); 0-31	= 0x00000000000000fd
310	Interrupt Cmd Reg (ICR); 32-63	= 0x0000000000000000
320	LVT Timer Register		= 0x00000000000000ef
330	LVT Thermal Sensor Register	= 0x0000000000010000
340	LVT Perf Mon Counter Reg	= 0x0000000000010400
350	LVT LINT0 Register		= 0x0000000000010700
360	LVT LINT1 Register		= 0x0000000000010400
370	LVT Error Register		= 0x00000000000000fe
380	Initial Count Reg (for Timer)	= 0x00000000000343a7
3e0	Divide Cfg Reg (for Timer)	= 0x0000000000000003