head at r334204, Bad link elm in callout_process()

[Andriy Gapon]

Has anyone else seen this panic?
Any suspect commits?
Any suggestion on analyzing the problem?
Thanks!

panic: Bad link elm 0xfffffe004bfed798 next->prev != elm
cpuid = 0
time = 1527257839
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame 0xfffffe00413be770
vpanic() at vpanic+0x1a3/frame 0xfffffe00413be7d0
panic() at panic+0x43/frame 0xfffffe00413be830
callout_process() at callout_process+0x30d/frame 0xfffffe00413be8b0
handleevents() at handleevents+0x1a5/frame 0xfffffe00413be8f0
timercb() at timercb+0x254/frame 0xfffffe00413be940
lapic_handle_timer() at lapic_handle_timer+0xa7/frame 0xfffffe00413be980
Xtimerint() at Xtimerint+0xa5/frame 0xfffffe00413be980
--- interrupt, rip = 0xffffffff811cf8d6, rsp = 0xfffffe00413bea50, rbp =
0xfffffe00413bea50 ---
acpi_cpu_c1() at acpi_cpu_c1+0x6/frame 0xfffffe00413bea50
acpi_cpu_idle() at acpi_cpu_idle+0x2ee/frame 0xfffffe00413beaa0
cpu_idle_acpi() at cpu_idle_acpi+0x3f/frame 0xfffffe00413beac0
cpu_idle() at cpu_idle+0x95/frame 0xfffffe00413beae0
sched_idletd() at sched_idletd+0x517/frame 0xfffffe00413bebb0
fork_exit() at fork_exit+0x84/frame 0xfffffe00413bebf0
fork_trampoline() at fork_trampoline+0xe/frame 0xfffffe00413bebf0
--- trap 0, rip = 0, rsp = 0, rbp = 0 ---
KDB: enter: panic

(kgdb) bt
#0  kdb_enter (why=0xffffffff812f802e "panic", msg=<optimized out>) at
/usr/devel/svn/head/sys/kern/subr_kdb.c:479
#1  0xffffffff80b93390 in vpanic (fmt=<optimized out>, ap=0xfffffe00413be810) at
/usr/devel/svn/head/sys/kern/kern_shutdown.c:852
#2  0xffffffff80b93423 in panic (fmt=0xffffffff81df35b8 <cnputs_mtx>
"\362\315+\201\377\377\377\377") at /usr/devel/svn/head/sys/kern/kern_shutdown.c:790
#3  0xffffffff80bab86d in callout_process (now=8718488703935) at
/usr/devel/svn/head/sys/kern/kern_timeout.c:562
#4  0xffffffff8119a205 in handleevents (now=8718488703935, fake=0) at
/usr/devel/svn/head/sys/kern/kern_clocksource.c:217
#5  0xffffffff8119a984 in timercb (et=0xffffffff81feb1d8 <lapic_et>,
arg=<optimized out>) at /usr/devel/svn/head/sys/kern/kern_clocksource.c:361
#6  0xffffffff811d9097 in lapic_handle_timer (frame=0xfffffe00413be990) at
/usr/devel/svn/head/sys/x86/x86/local_apic.c:1308
#7  <signal handler called>
#8  acpi_cpu_c1 () at /usr/devel/svn/head/sys/x86/x86/cpu_machdep.c:137
#9  0xffffffff804602ee in acpi_cpu_idle (sbt=<optimized out>) at
/usr/devel/svn/head/sys/dev/acpica/acpi_cpu.c:1187
#10 0xffffffff811cfeff in cpu_idle_acpi (sbt=178798794) at
/usr/devel/svn/head/sys/x86/x86/cpu_machdep.c:430
#11 0xffffffff811cffa5 in cpu_idle (busy=0) at
/usr/devel/svn/head/sys/x86/x86/cpu_machdep.c:578
#12 0xffffffff80bc28d7 in sched_idletd (dummy=<optimized out>) at
/usr/devel/svn/head/sys/kern/sched_ule.c:2832
#13 0xffffffff80b524c4 in fork_exit (callout=0xffffffff80bc23c0 <sched_idletd>,
arg=0x0, frame=0xfffffe00413bec00) at /usr/devel/svn/head/sys/kern/kern_fork.c:1039
#14 <signal handler called>
(kgdb) fr 3
#3  0xffffffff80bab86d in callout_process (now=8718488703935) at
/usr/devel/svn/head/sys/kern/kern_timeout.c:562
562     }
(kgdb) i loc
first = 8719562445759
firstb = 519662
nowb = 519662
lookahead = <optimized out>
last = 8720629104640
lastb = 519789
cc = 0xffffffff82011980 <cc_cpu>
max = 8720629104640
tmp = <optimized out>
tmpn = <optimized out>
tmp_max = <optimized out>
sc = <optimized out>

(kgdb) p *cc
$2 = {
  cc_lock = {
    lock_object = {
      lo_name = 0xffffffff8131227d "callout",
      lo_flags = 720896,
      lo_data = 0,
      lo_witness = 0x0
    },
    mtx_lock = 18446735277670449152
  },
  cc_exec_entity = {{
      cc_curr = 0x0,
      cc_drain = 0x0,
      ce_migration_func = 0x0,
      ce_migration_arg = 0x0,
      ce_migration_cpu = 256,
      ce_migration_time = 0,
      ce_migration_prec = 0,
      cc_cancel = true,
      cc_waiting = false
    }, {
      cc_curr = 0x0,
      cc_drain = 0x0,
      ce_migration_func = 0x0,
      ce_migration_arg = 0x0,
      ce_migration_cpu = 256,
      ce_migration_time = 0,
      ce_migration_prec = 0,
      cc_cancel = false,
      cc_waiting = false
    }},
  cc_next = 0x0,
  cc_callout = 0xfffffe0003841000,
  cc_callwheel = 0xfffffe0003963000,
  cc_expireq = {
    tqh_first = 0xffffffff81af68c8 <vt_consdev+264>,
    tqh_last = 0xffffffff81af68c8 <vt_consdev+264>
  },
  cc_callfree = {
    slh_first = 0xfffffe00039622c0
  },
  cc_firstevent = 8718488678823,
  cc_lastscan = 8718488703935,
  cc_cookie = 0xfffff8000338fd00,
  cc_bucket = 28118,
  cc_inited = 1,
  cc_ktr_event_name = "callwheel cpu 0\000\000\000\000"
}

(kgdb) p cc->cc_callwheel[firstb & callwheelmask]
$4 = {
  lh_first = 0xfffffe004bfed798
}
(kgdb) p *$4.lh_first
$5 = {
  c_links = {
    le = {
      le_next = 0xffffffff81bb08c8 <dbgc>,
      le_prev = 0xfffffe0003999f70
    },
    sle = {
      sle_next = 0xffffffff81bb08c8 <dbgc>
    },
    tqe = {
      tqe_next = 0xffffffff81bb08c8 <dbgc>,
      tqe_prev = 0xfffffe0003999f70
    }
  },
  c_time = 8718482236373,
  c_precision = 26843543,
  c_arg = 0xfffffe004bfe9000,
  c_func = 0xffffffff8060cef0 <firewire_watchdog>,
  c_lock = 0x0,
  c_flags = 2,
  c_iflags = 20,
  c_cpu = 0
}

(kgdb) p *$4.lh_first->c_links.le.le_next
$6 = {
  c_links = {
    le = {
      le_next = 0x0,
      le_prev = 0xfffffe0003999f98
    },
    sle = {
      sle_next = 0x0
    },
    tqe = {
      tqe_next = 0x0,
      tqe_prev = 0xfffffe0003999f98
    }
  },
  c_time = 8718576725647,
  c_precision = 26843543,
  c_arg = 0x0,
  c_func = 0xffffffff8045bfa0 <dbg_print>,
  c_lock = 0x0,
  c_flags = 2,
  c_iflags = 20,
  c_cpu = 0
}

-- 
Andriy Gapon