Date: Tue, 2 Feb 2010 19:44:00 +0300 From: pluknet <pluknet@gmail.com> To: freebsd-stable <freebsd-stable@freebsd.org> Subject: nmi_calltrap in siopoll() Message-ID: <a31046fc1002020844g2406e69al9b5987c38f643c4f@mail.gmail.com>
next in thread | raw e-mail | index | archive | help
Hi.
I've got NMI on an almost idle system - FreeBSD 7.2-R amd64.
I guess the reason may be in (hardware?) binary garbage
seen once in a while on serial port (loader, then ttyd0).
Ask me for more details.
Tracing command swi4: clock sio pid 20 tid 100011 td 0xffffff000144e370
cpustop_handler() at cpustop_handler+64
ipi_nmi_handler() at ipi_nmi_handler+48
trap() at trap+796
nmi_calltrap() at nmi_calltrap+8
--- trap 19, rip =3D 18446744071567390785, rsp =3D 18446744067267268592,
rbp =3D 18446744067267558272 ---
_mtx_lock_spin() at _mtx_lock_spin+113
siopoll() at siopoll+206
ithread_loop() at ithread_loop+384
fork_exit() at fork_exit+287
fork_trampoline() at fork_trampoline+14
--- trap 0, rip =3D 0, rsp =3D 18446744067267558704, rbp =3D 0 ---
(kgdb) thr 13
[Switching to thread 13 (Thread 100011)]#0 cpustop_handler () at atomic.h:=
264
264 atomic.h: No such file or directory.
in atomic.h
(kgdb) bt
#0 cpustop_handler () at atomic.h:264
#1 0xffffffff807ec400 in ipi_nmi_handler ()
at /usr/src/sys/amd64/amd64/mp_machdep.c:1144
#2 0xffffffff807fceec in trap (frame=3D0xfffffffe80028f40)
at /usr/src/sys/amd64/amd64/trap.c:198
#3 0xffffffff807e0aeb in nmi_calltrap ()
at /usr/src/sys/amd64/amd64/exception.S:427
#4 0xffffffff80513841 in _mtx_lock_spin (m=3D0xffffffff80bb3d00,
tid=3D18446742974219215728, opts=3DVariable "opts" is not available.
) at /usr/src/sys/kern/kern_mutex.c:474
#5 0xffffffff8082b96e in siopoll (dummy=3DVariable "dummy" is not availabl=
e.
) at /usr/src/sys/dev/sio/sio.c:1703
#6 0xffffffff804ff940 in ithread_loop (arg=3D0xffffff000142bac0)
at /usr/src/sys/kern/kern_intr.c:1088
#7 0xffffffff804fc1df in fork_exit (
callout=3D0xffffffff804ff7c0 <ithread_loop>, arg=3D0xffffff000142bac0,
frame=3D0xfffffffe8006fc80) at /usr/src/sys/kern/kern_fork.c:834
#8 0xffffffff807e0b5e in fork_trampoline ()
at /usr/src/sys/amd64/amd64/exception.S:455
#9 0x0000000000000000 in ?? ()
#10 0x0000000000000000 in ?? ()
#11 0x0000000000000001 in ?? ()
#12 0x0000000000000000 in ?? ()
#13 0x0000000000000000 in ?? ()
#14 0x0000000000000000 in ?? ()
---Type <return> to continue, or q <return> to quit---q
Quit
(kgdb) f 5
#5 0xffffffff8082b96e in siopoll (dummy=3DVariable "dummy" is not availabl=
e.
) at /usr/src/sys/dev/sio/sio.c:1703
1703 mtx_lock_spin(&sio_lock);
(kgdb) i loc
_tid =3D Variable "_tid" is not available.
(kgdb) list
1698 com_events -=3D incc;
1699 mtx_unlock_spin(&sio_lock);
1700 continue;
1701 }
1702 if (com->iptr !=3D com->ibuf) {
1703 mtx_lock_spin(&sio_lock);
1704 sioinput(com);
1705 mtx_unlock_spin(&sio_lock);
1706 }
1707 if (com->state & CS_CHECKMSR) {
(kgdb) p sio_lock
$1 =3D {lock_object =3D {lo_name =3D 0xffffffff80b15380 "sio",
lo_type =3D 0xffffffff80b15380 "sio", lo_flags =3D 458752, lo_witness_d=
ata =3D {
lod_list =3D {stqe_next =3D 0x0}, lod_witness =3D 0x0}},
mtx_lock =3D 18446742974219094608, mtx_recurse =3D 0}
(kgdb) p/x sio_lock->mtx_lock
$10 =3D 0xffffff0001430a50 # =3D=3D td for pid 17 tid 100008
Binary garbage is like below (not touching anything on k/board atm).
login:
FreeBSD/amd64 (ho
FreeBSD/amd64 (host) (ttyd0)
login: <<|=FE
FreeBSD
FreeBSD
FreeBS
FreeBSD
Free
FreeBSD/amd64 (host) (ttyd0)
login:
FreeBSD/amd64 (host) (ttyd0)
login:
FreeBSD
Free
FreeBS
FreeBSD
FreeBS
FreeBSD
FreeBSD
FreeBS
FreeBSD
FreeBS
FreeBSD
FreeBSD
FreeBS
FreeBSD
FreeBS=A0=A8H=C8=C9 M5
FreeBSD
FreeBS
FreeBSD
FreeBSD
FreeBS
FreeBSD
FreeBS=A0=A8H=C8=C9 M5
FreeBSD
FreeBS
FreeBSD
FreeB
FreeBSD/amd6
FreeBS
FreeBS
FreeBSD
FreeBSD
FreeBS
FreeBSD
FreeBS
FreeBSD
FreeBSD
FreeBS
FreeBSD
FreeBS=A0=A8H=C8=C9 M5
FreeBSD
FreeBS
FreeBSD
[..a little later..]
[root@host ~]# <<<<<<<<<<<><<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<8<<<<<8<<<<
<<<<<<<<<<<<<<<<<<<<<<<<<<<<<8<<<<<<<><
Other useful stuff.
(kgdb) f 4
#4 0xffffffff80513841 in _mtx_lock_spin (m=3D0xffffffff80bb3d00,
tid=3D18446742974219215728, opts=3DVariable "opts" is not available.
) at /usr/src/sys/kern/kern_mutex.c:474
474 while (m->mtx_lock !=3D MTX_UNOWNED) {
(kgdb) list
469 lock_profile_obtain_lock_failed(&m->lock_object,
&contested, &waittime);
470 while (!_obtain_lock(m, tid)) {
471
472 /* Give interrupts a chance while we spin. */
473 spinlock_exit();
474 while (m->mtx_lock !=3D MTX_UNOWNED) {
475 if (i++ < 10000000) {
476 cpu_spinwait();
477 continue;
478 }
(kgdb) f 3
#3 0xffffffff807e0aeb in nmi_calltrap ()
at /usr/src/sys/amd64/amd64/exception.S:427
427 call trap
Current language: auto; currently asm
(kgdb) list
422 swapgs
423 /* Note: this label is also used by ddb and gdb: */
424 nmi_calltrap:
425 FAKE_MCOUNT(TF_RIP(%rsp))
426 movq %rsp, %rdi
427 call trap
428 MEXITCOUNT
429 testl %ebx,%ebx
430 jz nmi_restoreregs
431 swapgs
(kgdb) f 2
#2 0xffffffff807fceec in trap (frame=3D0xfffffffe80028f40)
at /usr/src/sys/amd64/amd64/trap.c:198
198 if (ipi_nmi_handler() =3D=3D 0)
Current language: auto; currently c
(kgdb) list
193
194 #ifdef SMP
195 #ifdef STOP_NMI
196 /* Handler for NMI IPIs used for stopping CPUs. */
197 if (type =3D=3D T_NMI) {
198 if (ipi_nmi_handler() =3D=3D 0)
199 goto out;
200 }
201 #endif /* STOP_NMI */
202 #endif /* SMP */
db> bt
Tracing pid 17 tid 100008 td 0xffffff0001430a50
kdb_enter_why() at kdb_enter_why+0x3d
siointr1() at siointr1+0x2c5
siointr() at siointr+0x58
intr_execute_handlers() at intr_execute_handlers+0x8b
Xapic_isr1() at Xapic_isr1+0x7f
--- interrupt, rip =3D 0xffffffff807d8bd6, rsp =3D 0xfffffffe8005fb90, rbp
=3D 0xfffffffe8005fba0 ---
acpi_cpu_c1() at acpi_cpu_c1+0x6
acpi_cpu_idle() at acpi_cpu_idle+0x19c
sched_idletd() at sched_idletd+0x46
fork_exit() at fork_exit+0x11f
fork_trampoline() at fork_trampoline+0xe
--- trap 0, rip =3D 0, rsp =3D 0xfffffffe8005fd30, rbp =3D 0 ---
(kgdb) p (struct thread) *sio_lock->mtx_lock
$15 =3D {td_lock =3D 0xffffffff80b7bc40, td_proc =3D 0xffffff000142e478, td=
_plist =3D {
tqe_next =3D 0x0, tqe_prev =3D 0xffffff000142e488}, td_slpq =3D {tqe_ne=
xt =3D 0x0,
tqe_prev =3D 0x0}, td_lockq =3D {tqe_next =3D 0x0, tqe_prev =3D 0x0}, t=
d_selq =3D {
tqh_first =3D 0x0, tqh_last =3D 0x0}, td_sleepqueue =3D 0xffffff0001418=
c00,
td_turnstile =3D 0xffffff00012f9a00, td_umtxq =3D 0xffffff000142a380,
td_tid =3D 100008, td_sigqueue =3D {sq_signals =3D {__bits =3D {0, 0, 0, =
0}},
sq_kill =3D {__bits =3D {0, 0, 0, 0}}, sq_list =3D {tqh_first =3D 0x0,
tqh_last =3D 0xffffff0001430ae0}, sq_proc =3D 0xffffff000142e478,
sq_flags =3D 1}, td_flags =3D 65572, td_inhibitors =3D 0, td_pflags =3D=
0,
td_dupfd =3D 0, td_sqqueue =3D 0, td_wchan =3D 0x0, td_wmesg =3D 0x0,
td_lastcpu =3D 1 '\001', td_oncpu =3D 1 '\001', td_owepreempt =3D 0 '\0',
td_locks =3D 0, td_tsqueue =3D 0 '\0', td_blocked =3D 0x0, td_lockname =
=3D 0x0,
td_contested =3D {lh_first =3D 0x0}, td_sleeplocks =3D 0x0,
td_intr_nesting_level =3D 1, td_pinned =3D 0, td_mailbox =3D 0x0,
td_ucred =3D 0xffffff0001300e00, td_standin =3D 0x0, td_upcall =3D 0x0,
td_estcpu =3D 0, td_slptick =3D 0, td_ru =3D {ru_utime =3D {tv_sec =3D 0,
tv_usec =3D 0}, ru_stime =3D {tv_sec =3D 0, tv_usec =3D 0}, ru_maxrss=
=3D 0,
ru_ixrss =3D 0, ru_idrss =3D 0, ru_isrss =3D 0, ru_minflt =3D 0, ru_maj=
flt =3D 0,
ru_nswap =3D 0, ru_inblock =3D 0, ru_oublock =3D 0, ru_msgsnd =3D 0,
ru_msgrcv =3D 0, ru_nsignals =3D 0, ru_nvcsw =3D 6414, ru_nivcsw =3D 38=
607927},
td_runtime =3D 2179322361251400, td_pticks =3D 145105307, td_sticks =3D 7=
704049,
td_iticks =3D 0, td_uticks =3D 0, td_uuticks =3D 0, td_usticks =3D 0,
td_intrval =3D 0, td_oldsigmask =3D {__bits =3D {0, 0, 0, 0}}, td_sigmask=
=3D {
---Type <return> to continue, or q <return> to quit---
__bits =3D {0, 0, 0, 0}}, td_generation =3D 38614341, td_sigstk =3D {
ss_sp =3D 0x0, ss_size =3D 0, ss_flags =3D 0}, td_kflags =3D 0, td_xsig=
=3D 0,
td_profil_addr =3D 0, td_profil_ticks =3D 0, td_name =3D '\0' <repeats 19=
times>,
td_base_pri =3D 255 '=FF', td_priority =3D 255 '=FF', td_pri_class =3D 4 =
'\004',
td_user_pri =3D 180 '=B4', td_base_user_pri =3D 180 '=B4',
td_pcb =3D 0xfffffffe8005fd40, td_state =3D TDS_RUNNING, td_retval =3D {0=
, 0},
td_slpcallout =3D {c_links =3D {sle =3D {sle_next =3D 0x0}, tqe =3D {tqe_=
next =3D 0x0,
tqe_prev =3D 0x0}}, c_time =3D 0, c_arg =3D 0x0, c_func =3D 0, c_mt=
x =3D 0x0,
c_flags =3D 16}, td_frame =3D 0xfffffffe8005fc80,
td_kstack_obj =3D 0xffffff0001431740, td_kstack =3D 18446744067267477504,
td_kstack_pages =3D 4, td_altkstack_obj =3D 0x0, td_altkstack =3D 0,
td_altkstack_pages =3D 0, td_critnest =3D 2, td_md =3D {md_spinlock_count=
=3D 1,
md_saved_flags =3D 70}, td_sched =3D 0xffffff0001430d80, td_ar =3D 0x0,
td_syscalls =3D 0, td_incruntime =3D 115662355444194,
td_cpuset =3D 0xffffff0001424dc8, td_fpop =3D 0x0, td_dtrace =3D 0x0, td_=
errno =3D 0}
(kgdb) p (struct proc) *0xffffff000142e478
$16 =3D {p_list =3D {le_next =3D 0xffffff000142e8f0, le_prev =3D 0xffffff00=
014458f0},
p_threads =3D {tqh_first =3D 0xffffff0001430a50, tqh_last =3D 0xffffff000=
1430a60},
p_upcalls =3D {tqh_first =3D 0x0, tqh_last =3D 0xffffff000142e498}, p_slo=
ck =3D {
lock_object =3D {lo_name =3D 0xffffffff808da2a3 "process slock",
lo_type =3D 0xffffffff808da2a3 "process slock", lo_flags =3D 720896,
lo_witness_data =3D {lod_list =3D {stqe_next =3D 0x0}, lod_witness =
=3D 0x0}},
mtx_lock =3D 4, mtx_recurse =3D 0}, p_ucred =3D 0xffffff0001300e00,
p_fd =3D 0xffffff0001443400, p_fdtol =3D 0x0, p_stats =3D 0xffffff00012ff=
600,
p_limit =3D 0xffffff0001300c00, p_limco =3D {c_links =3D {sle =3D {sle_ne=
xt =3D 0x0},
tqe =3D {tqe_next =3D 0x0, tqe_prev =3D 0x0}}, c_time =3D 0, c_arg =
=3D 0x0,
c_func =3D 0, c_mtx =3D 0xffffff000142e590, c_flags =3D 0},
p_sigacts =3D 0xffffff000143e000, p_flag =3D 268435980, p_state =3D PRS_N=
ORMAL,
p_pid =3D 17, p_hash =3D {le_next =3D 0x0, le_prev =3D 0xfffffffe8021c088=
},
p_pglist =3D {le_next =3D 0xffffff000142e8f0, le_prev =3D 0xffffff0001445=
9d8},
p_pptr =3D 0xffffffff80b64640, p_sibling =3D {le_next =3D 0xffffff000142e=
8f0,
le_prev =3D 0xffffff00014459f0}, p_children =3D {lh_first =3D 0x0}, p_m=
tx =3D {
lock_object =3D {lo_name =3D 0xffffffff808da296 "process lock",
lo_type =3D 0xffffffff808da296 "process lock", lo_flags =3D 21168128,
lo_witness_data =3D {lod_list =3D {stqe_next =3D 0x0}, lod_witness =
=3D 0x0}},
mtx_lock =3D 4, mtx_recurse =3D 0}, p_ksi =3D 0x0, p_sigqueue =3D {sq_s=
ignals =3D {
__bits =3D {0, 0, 0, 0}}, sq_kill =3D {__bits =3D {0, 0, 0, 0}}, sq_l=
ist =3D {
tqh_first =3D 0x0, tqh_last =3D 0xffffff000142e5e8},
sq_proc =3D 0xffffff000142e478, sq_flags =3D 1}, p_oppid =3D 0,
---Type <return> to continue, or q <return> to quit---
p_vmspace =3D 0xffffffff80b64e00, p_swtick =3D 0, p_realtimer =3D {it_int=
erval =3D {
tv_sec =3D 0, tv_usec =3D 0}, it_value =3D {tv_sec =3D 0, tv_usec =3D=
0}}, p_ru =3D {
ru_utime =3D {tv_sec =3D 0, tv_usec =3D 0}, ru_stime =3D {tv_sec =3D 0,
tv_usec =3D 0}, ru_maxrss =3D 0, ru_ixrss =3D 0, ru_idrss =3D 0, ru_i=
srss =3D 0,
ru_minflt =3D 0, ru_majflt =3D 0, ru_nswap =3D 0, ru_inblock =3D 0,
ru_oublock =3D 0, ru_msgsnd =3D 0, ru_msgrcv =3D 0, ru_nsignals =3D 0,
ru_nvcsw =3D 0, ru_nivcsw =3D 0}, p_rux =3D {rux_runtime =3D 2063660005=
807206,
rux_uticks =3D 0, rux_sticks =3D 137401258, rux_iticks =3D 0, rux_uu =
=3D 0,
rux_su =3D 371936150861, rux_tu =3D 1034416043011}, p_crux =3D {rux_run=
time =3D 0,
rux_uticks =3D 0, rux_sticks =3D 0, rux_iticks =3D 0, rux_uu =3D 0, rux=
_su =3D 0,
rux_tu =3D 0}, p_profthreads =3D 0, p_exitthreads =3D 0, p_traceflag =
=3D 0,
p_tracevp =3D 0x0, p_tracecred =3D 0x0, p_textvp =3D 0x0, p_lock =3D 0 '\=
0',
p_sigiolst =3D {slh_first =3D 0x0}, p_sigparent =3D 20, p_sig =3D 0, p_co=
de =3D 0,
p_stops =3D 0, p_stype =3D 0, p_step =3D 0 '\0', p_pfsflags =3D 0 '\0',
p_nlminfo =3D 0x0, p_aioinfo =3D 0x0, p_singlethread =3D 0x0, p_suspcount=
=3D 0,
p_xthread =3D 0x0, p_boundary_count =3D 0, p_pendingcnt =3D 0, p_itimers =
=3D 0x0,
p_numupcalls =3D 0, p_upsleeps =3D 0, p_completed =3D 0x0, p_nextupcall =
=3D 0,
p_upquantum =3D 0, p_magic =3D 3203398350, p_osrel =3D 702000,
p_comm =3D "idle: cpu1\000\000\000\000\000\000\000\000\000",
p_pgrp =3D 0xffffffff80b65060, p_sysent =3D 0xffffffff80ad4d80, p_args =
=3D 0x0,
p_cpulimit =3D 9223372036854775807, p_nice =3D 0 '\0', p_fibnum =3D 0,
p_xstat =3D 0, p_klist =3D {kl_list =3D {slh_first =3D 0x0},
kl_lock =3D 0xffffffff804f65d0 <knlist_mtx_lock>,
---Type <return> to continue, or q <return> to quit---
kl_unlock =3D 0xffffffff804f5ff0 <knlist_mtx_unlock>,
kl_locked =3D 0xffffffff804f5fd0 <knlist_mtx_locked>,
kl_lockarg =3D 0xffffff000142e590}, p_numthreads =3D 1,
p_md =3D <incomplete type>, p_itcallout =3D {c_links =3D {sle =3D {sle_ne=
xt =3D 0x0},
tqe =3D {tqe_next =3D 0x0, tqe_prev =3D 0x0}}, c_time =3D 0, c_arg =
=3D 0x0,
c_func =3D 0, c_mtx =3D 0x0, c_flags =3D 16}, p_acflag =3D 1, p_peers =
=3D 0x0,
p_leader =3D 0xffffff000142e478, p_emuldata =3D 0x0, p_label =3D 0x0,
p_sched =3D 0xffffff000142e8f0, p_ktr =3D {stqh_first =3D 0x0,
stqh_last =3D 0xffffff000142e8d0}, p_mqnotifier =3D {lh_first =3D 0x0},
p_dtrace =3D 0x0}
db> show allpcpu
Current CPU: 1
cpuid =3D 0
curthread =3D 0xffffff00014306e0: pid 18 "idle: cpu0"
curpcb =3D 0xfffffffe80064d40
fpcurthread =3D none
idlethread =3D 0xffffff00014306e0: pid 18 "idle: cpu0"
cpuid =3D 1
curthread =3D 0xffffff0001430a50: pid 17 "idle: cpu1"
curpcb =3D 0xfffffffe8005fd40
fpcurthread =3D none
idlethread =3D 0xffffff0001430a50: pid 17 "idle: cpu1"
cpuid =3D 2
curthread =3D 0xffffff000143c000: pid 16 "idle: cpu2"
curpcb =3D 0xfffffffe8005ad40
fpcurthread =3D none
idlethread =3D 0xffffff000143c000: pid 16 "idle: cpu2"
cpuid =3D 3
curthread =3D 0xffffff000143c370: pid 15 "idle: cpu3"
curpcb =3D 0xfffffffe80055d40
fpcurthread =3D none
idlethread =3D 0xffffff000143c370: pid 15 "idle: cpu3"
cpuid =3D 4
curthread =3D 0xffffff000143c6e0: pid 14 "idle: cpu4"
curpcb =3D 0xfffffffe80050d40
fpcurthread =3D none
idlethread =3D 0xffffff000143c6e0: pid 14 "idle: cpu4"
cpuid =3D 5
curthread =3D 0xffffff000144e370: pid 20 "swi4: clock sio"
curpcb =3D 0xfffffffe8006fd40
fpcurthread =3D none
idlethread =3D 0xffffff000142f000: pid 13 "idle: cpu5"
cpuid =3D 6
curthread =3D 0xffffff000142f370: pid 12 "idle: cpu6"
curpcb =3D 0xfffffffe80046d40
fpcurthread =3D none
idlethread =3D 0xffffff000142f370: pid 12 "idle: cpu6"
cpuid =3D 7
curthread =3D 0xffffff000142f6e0: pid 11 "idle: cpu7"
curpcb =3D 0xfffffffe80041d40
fpcurthread =3D none
idlethread =3D 0xffffff000142f6e0: pid 11 "idle: cpu7"
--=20
wbr,
pluknet
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?a31046fc1002020844g2406e69al9b5987c38f643c4f>