Date: Thu, 29 Sep 2005 21:55:07 +0100 (BST) From: Robert Watson <rwatson@FreeBSD.org> To: threads@FreeBSD.org Subject: Re: freebsd-5.4-stable panics (fwd) Message-ID: <20050929215152.D34322@fledge.watson.org>
next in thread | raw e-mail | index | archive | help
[-- Attachment #1 --]
The attached message and debugging information suggests that a thread in
an incompletely initialized state (td->td_ksegrp == NULL) is being hooked
up to a process, and that fill_kinfo_thread() is pretty sure this will
never happen (it assumes that td_ksegrp != NULL). I've suggested a
work-around of skipping threads with td_ksegrp == NULL in the calling
function, but this raises a general question about the invariants of the
KSE/thread/... code during thread initialization. Should a thread hooked
up to a process thread list ever have a td_ksegrp of NULL? Once a thread
has a KSE group that is non-NULL, will it ever change such that monitoring
code needs to worry? Is kern_proc.c making assumptions that are too
strong, or do we just have a nasty SMP race here and some locking work is
needed? The remainder of the thread can be found on the -hackers list,
but the key points are:
- Shows up on quad-processor systems running 6.x
- Multi-threaded apps are doing lots of network I/O
- Occurs while running top under high load
Thanks,
Robert N M Watson
---------- Forwarded message ----------
Date: Thu, 29 Sep 2005 16:17:57 -0400 (EDT)
From: Rob Watt <rob@hudson-trading.com>
To: Robert Watson <rwatson@FreeBSD.org>
Cc: Rob Watt <rob@hudson-trading.com>, Jason Carroll <jason@hudson-trading.com>,
freebsd-hackers@FreeBSD.org, freebsd-amd64@FreeBSD.org,
mikep@hudson-trading.com
Subject: Re: freebsd-5.4-stable panics
On Thu, 29 Sep 2005, Robert Watson wrote:
> Could you dump the contents of *td and *td->td_proc for me? I'm quite
> interested to know what the value in td->td_proc->p_state is, among other
> things. If I could also have you generate a dump of the KSE group
> structures in td->td_proc->p_ksegrps and the threads in
> td->td_proc->p_threads.
I've attached a file with many of the values you have asked for. We
looked at some of the threads referenced by td->td_proc->p_threads, but we
weren't sure we were walking the list correctly. Do you have any tips for
walking those thread lists?
>
> Could you tell me if the program named by p->p_comm is linked against a
> threading library? If it's a custom app, you may already know, and if
> not, you can run ldd on the application to see what it is linked against.
>
The programs named by p->p_comm is linked against the pthreads library.
> Depending on how much time you have available, it might make sense for me
> to grab from you a copy of your source tree, compiled kernel with debug
> symbols, and core dump.
We can upload the source, kernel etc somewhere, but uncompressed that is
about 5G of data. What is the best way to get that to you?
Thanks.
-
Rob Watt
[-- Attachment #2 --]
[GDB will not be able to debug user-mode threads: /usr/lib/libthread_db.so: Undefined symbol "ps_pglobal_lookup"]
GNU gdb 6.1.1 [FreeBSD]
Copyright 2004 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB. Type "show warranty" for details.
This GDB was configured as "amd64-marcel-freebsd".
Unread portion of the kernel message buffer:
kernel trap 12 with interrupts disabled
Fatal trap 12: page fault while in kernel mode
cpuid = 3; apic id = 03
fault virtual address = 0x48
fault code = supervisor read, page not present
instruction pointer = 0x8:0xffffffff802b897a
stack pointer = 0x10:0xffffffffb62d8490
frame pointer = 0x10:0xffffffffb62d84f0
code segment = base 0x0, limit 0xfffff, type 0x1b
= DPL 0, pres 1, long 1, def32 0, gran 1
processor eflags = resume, IOPL = 0
current process = 29810 (top)
Locked vnodes
0xffffff003a4bc9b0: tag ufs, type VREG
usecount 1, writecount 1, refcount 8069 mountedhere 0
flags ()
v_object 0xffffff00cfb5fd20 ref 0 pages 32268
lock type ufs: EXCL (count 1) by thread 0xffffff00731af4c0 (pid 29809)
ino 20466699, on dev aacd0s1e
Process 29810 (top) thread 0xffffff004affcbe0 (100097)
exclusive sleep mutex process lock r = 0 (0xffffff004aa9f0c0) locked @ /usr/src/sys/kern/kern_proc.c:890
shared sx allproc r = 0 (0xffffffff806434e0) locked @ /usr/src/sys/kern/kern_proc.c:229
exclusive sx sysctl lock r = 0 (0xffffffff80643d00) locked @ /usr/src/sys/kern/kern_sysctl.c:1342
exclusive sleep mutex Giant r = 0 (0xffffffff80643360) locked @ /usr/src/sys/kern/kern_sysctl.c:1280
Process 25057 (dataplay) thread 0xffffff00156fb260 (100091)
exclusive sleep mutex inp (udpinp) r = 0 (0xffffff00a826b938) locked @ /usr/src/sys/netinet/udp_usrreq.c:762
Dumping 3759 MB (2 chunks)
chunk 0: 1MB (155 pages) ... ok
chunk 1: 3759MB (962288 pages) 3743 3727 3711 3695 3679 3663 3647 3631 3615 3599 3583 3567 3551 3535 3519 3503 3487 3471 3455 3439 3423 3407 3391 3375 3359 3343 3327 3311 3295 3279 3263 3247 3231 3215 3199 3183 3167 3151 3135 3119 3103 3087 3071 3055 3039 3023 3007 2991 2975 2959 2943 2927 2911 2895 2879 2863 2847 2831 2815 2799 2783 2767 2751 2735 2719 2703 2687 2671 2655 2639 2623 2607 2591 2575 2559 2543 2527 2511 2495 2479 2463 2447 2431 2415 2399 2383 2367 2351 2335 2319 2303 2287 2271 2255 2239 2223 2207 2191 2175 2159 2143 2127 2111 2095 2079 2063 2047 2031 2015 1999 1983 1967 1951 1935 1919 1903 1887 1871 1855 1839 1823 1807 1791 1775 1759 1743 1727 1711 1695 1679 1663 1647 1631 1615 1599 1583 1567 1551 1535 1519 1503 1487 1471 1455 1439 1423 1407 1391 1375 1359 1343 1327 1311 1295 1279 1263 1247 1231 1215 1199 1183 1167 1151 1135 1119 1103 1087 1071 1055 1039 1023 1007 991 975 959 943 927 911 895 879 863 847 831 815 799 783 767 751 735 719 703 687 671 655 639 623 607 591 575 559 543 527 511 495 479 463 447 431 415 399 383 367 351 335 319 303 287 271 255 239 223 207 191 175 159 143 127 111 95 79 63 47 31 15
#0 doadump () at pcpu.h:172
172 pcpu.h: No such file or directory.
in pcpu.h
(kgdb) bt
#0 doadump () at pcpu.h:172
#1 0xffffffff801976b1 in db_fncall (dummy1=0, dummy2=0, dummy3=0, dummy4=0x0)
at /usr/src/sys/ddb/db_command.c:489
#2 0xffffffff80197b05 in db_command_loop () at /usr/src/sys/ddb/db_command.c:349
#3 0xffffffff80199973 in db_trap (type=-1238531456, code=0) at /usr/src/sys/ddb/db_main.c:221
#4 0xffffffff802db9be in kdb_trap (type=12, code=0, tf=0xffffffff805e1f00)
at /usr/src/sys/kern/subr_kdb.c:473
#5 0xffffffff8042c1be in trap_fatal (frame=0xffffffffb62d83e0, eva=18446742975456201696)
at /usr/src/sys/amd64/amd64/trap.c:656
#6 0xffffffff8042c6f3 in trap (frame=
{tf_rdi = 0, tf_rsi = 0, tf_rdx = 299, tf_rcx = 938728, tf_r8 = 25059, tf_r9 = 3296, tf_rax = 0, tf_rbx = 0, tf_rbp = -1238530832, tf_r10 = 1, tf_r11 = 4294967294, tf_r12 = -1238530800, tf_r13 = 6, tf_r14 = -1098258976768, tf_r15 = -1097847467424, tf_trapno = 12, tf_addr = 72, tf_flags = -1097727869784, tf_err = 0, tf_rip = -2144630406, tf_cs = 8, tf_rflags = 65559, tf_rsp = -1238530912, tf_ss = 16})
at /usr/src/sys/amd64/amd64/trap.c:241
#7 0xffffffff8041a0eb in calltrap () at /usr/src/sys/amd64/amd64/exception.S:168
#8 0xffffffff802b897a in fill_kinfo_thread (td=0xffffff0063311260, kp=0xffffffffb62d8510)
at /usr/src/sys/kern/kern_proc.c:733
#9 0xffffffff802b9286 in sysctl_out_proc (p=0xffffff004aa9f000, req=0xffffffffb62d8a20, flags=0)
at /usr/src/sys/kern/kern_proc.c:886
#10 0xffffffff802b95c1 in sysctl_kern_proc (oidp=0x0, arg1=0x0, arg2=299, req=0xffffffffb62d8a20)
at /usr/src/sys/kern/kern_proc.c:1075
#11 0xffffffff802c7d20 in sysctl_root (oidp=0x0, arg1=0x0, arg2=0, req=0xffffffffb62d8a20)
at /usr/src/sys/kern/kern_sysctl.c:1248
#12 0xffffffff802c819c in userland_sysctl (td=0xffffff004affcbe0, name=0xffffffffb62d8af0, namelen=3,
old=0x596000, oldlenp=0x7fffffffe4f8, inkernel=0, new=0x0, newlen=0, retval=0xffffffffb62d8ae8, flags=0)
at /usr/src/sys/kern/kern_sysctl.c:1347
#13 0xffffffff802c832d in __sysctl (td=0xffffff004affcbe0, uap=0xffffffffb62d8bc0)
at /usr/src/sys/kern/kern_sysctl.c:1282
#14 0xffffffff8042cf62 in syscall (frame=
{tf_rdi = 140737488348512, tf_rsi = 3, tf_rdx = 5857280, tf_rcx = 140737488348408, tf_r8 = 0, tf_r9 = 0, tf_rax = 202, tf_rbx = 5853184, tf_rbp = 0, tf_r10 = 1, tf_r11 = 514, tf_r12 = 140737488348512, tf_r13 = 1407---Type <return> to continue, or q <return> to quit---q
Quit
) at /usr/src/sys/amd64/amd64/trap.c:797
#15 0xffffffff8041a288 in Xfast_syscall () at /usr/src/sys/amd64/amd64/exception.S:270
#16 0x00000008009fdadc in ?? ()
Previous frame inner to this frame (corrupt stack?)
(kgdb) frame 8
#8 0xffffffff802b897a in fill_kinfo_thread (td=0xffffff0063311260, kp=0xffffffffb62d8510)
at /usr/src/sys/kern/kern_proc.c:733
733 kg = td->td_ksegrp;
(kgdb) l
728 }
729 } else {
730 kp->ki_stat = SIDL;
731 }
732
733 kg = td->td_ksegrp;
734
735 /* things in the KSE GROUP */
736 kp->ki_estcpu = kg->kg_estcpu;
737 kp->ki_slptime = kg->kg_slptime;
(kgdb) p *td
$1 = {td_proc = 0xffffff004aa9f000, td_ksegrp = 0x0, td_plist = {tqe_next = 0xffffff00b4798000,
tqe_prev = 0xffffff00a97ae010}, td_kglist = {tqe_next = 0xffffff00b4798000,
tqe_prev = 0xffffff00a97ae020}, td_slpq = {tqe_next = 0x0, tqe_prev = 0xffffff001fac7c10}, td_lockq = {
tqe_next = 0xffffff00a97ae000, tqe_prev = 0xffffffffb6797a70}, td_runq = {tqe_next = 0x0,
tqe_prev = 0xffffffff80608180}, td_selq = {tqh_first = 0x0, tqh_last = 0xffffff00633112c0},
td_sleepqueue = 0xffffff00382b0400, td_turnstile = 0xffffff00c1712900, td_umtxq = 0xffffff00d1207080,
td_tid = 100253, td_flags = 16777216, td_inhibitors = 0, td_pflags = 128, td_dupfd = 0, td_wchan = 0x0,
td_wmesg = 0x0, td_lastcpu = 2 '\002', td_oncpu = 2 '\002', td_owepreempt = 0 '\0', td_locks = 0,
td_blocked = 0x0, td_ithd = 0x0, td_lockname = 0x0, td_contested = {lh_first = 0x0}, td_sleeplocks = 0x0,
td_intr_nesting_level = 0, td_pinned = 0, td_mailbox = 0x0, td_ucred = 0xffffff00ad18f200,
td_standin = 0x0, td_upcall = 0x0, td_sticks = 0, td_uuticks = 0, td_usticks = 0, td_intrval = 0,
td_oldsigmask = {__bits = {0, 0, 0, 0}}, td_sigmask = {__bits = {4294967295, 4294967295, 4294967295,
4294967295}}, td_siglist = {__bits = {0, 0, 0, 0}}, td_generation = 14, td_sigstk = {ss_sp = 0x0,
ss_size = 0, ss_flags = 0}, td_kflags = 0, td_xsig = 0, td_profil_addr = 0, td_profil_ticks = 0,
td_base_pri = 182 '\uffff', td_priority = 182 '\uffff', td_pcb = 0xffffffffb68dcd10, td_state = TDS_INACTIVE,
td_retval = {1, 29309280}, td_slpcallout = {c_links = {sle = {sle_next = 0x0}, tqe = {tqe_next = 0x0,
tqe_prev = 0xffffff001fac7d80}}, c_time = 55907602, c_arg = 0xffffff0063311260,
c_func = 0xffffffff802e32a0 <sleepq_timeout>, c_mtx = 0x0, c_flags = 16}, td_frame = 0xffffffffb68dcc40,
td_kstack_obj = 0xffffff0087f93d20, td_kstack = 18446744072477315072, td_kstack_pages = 4,
td_altkstack_obj = 0x0, td_altkstack = 0, td_altkstack_pages = 0, td_critnest = 1, td_md = {
md_spinlock_count = 1, md_saved_flags = 582}, td_sched = 0xffffff0063311488}
(kgdb) p *td->td_proc
$2 = {p_list = {le_next = 0xffffff00b5908340, le_prev = 0xffffff00b4200340}, p_ksegrps = {
tqh_first = 0xffffff00b5be5240, tqh_last = 0xffffff004aa9e5a8}, p_threads = {
tqh_first = 0xffffff006f872000, tqh_last = 0xffffff004256f270}, p_suspended = {tqh_first = 0x0,
tqh_last = 0xffffff004aa9f030}, p_ucred = 0xffffff00ad18f200, p_fd = 0xffffff00a39fea00, p_fdtol = 0x0,
p_stats = 0xffffff0032155800, p_limit = 0xffffff00a2cb1a00, p_sigacts = 0xffffff006a51f000,
p_flag = 49282, p_sflag = 1, p_state = PRS_NORMAL, p_pid = 25059, p_hash = {le_next = 0x0,
le_prev = 0xffffffff80a3df18}, p_pglist = {le_next = 0xffffff00b5908340, le_prev = 0xffffff00b42003d0},
p_pptr = 0xffffff00e37e29c0, p_sibling = {le_next = 0xffffff00b4200340, le_prev = 0xffffff00b59083e8},
p_children = {lh_first = 0x0}, p_mtx = {mtx_object = {lo_class = 0xffffffff806053f0,
lo_name = 0xffffffff804a41ce "process lock", lo_type = 0xffffffff804a41ce "process lock",
lo_flags = 4390912, lo_list = {tqe_next = 0xffffff004aa9f400, tqe_prev = 0xffffff004adbaaa0},
lo_witness = 0xffffffff80660e60}, mtx_lock = 18446742975456201698, mtx_recurse = 0}, p_oppid = 0,
p_vmspace = 0xffffff00b06a4880, p_swtime = 3296, p_realtimer = {it_interval = {tv_sec = 0, tv_usec = 0},
it_value = {tv_sec = 0, tv_usec = 0}}, p_rux = {rux_runtime = {sec = 299, frac = 17316481205223904824},
rux_uticks = 3914, rux_sticks = 35042, rux_iticks = 0, rux_uu = 30135424, rux_su = 269802135,
rux_iu = 1}, p_crux = {rux_runtime = {sec = 0, frac = 0}, rux_uticks = 0, rux_sticks = 0,
rux_iticks = 0, rux_uu = 0, rux_su = 0, rux_iu = 0}, p_profthreads = 0, p_maxthrwaits = 0,
p_traceflag = 0, p_tracevp = 0x0, p_tracecred = 0x0, p_textvp = 0xffffff00b60a21f0, p_siglist = {__bits = {
0, 0, 0, 0}}, p_lock = 1 '\001', p_sigiolst = {slh_first = 0x0}, p_sigparent = 20, p_sig = 0,
p_code = 0, p_stops = 0, p_stype = 0, p_step = 0 '\0', p_pfsflags = 0 '\0', p_nlminfo = 0x0,
p_aioinfo = 0x0, p_singlethread = 0x0, p_suspcount = 0, p_xthread = 0x0, p_boundary_count = 0,
p_procscopegrp = 0x0, p_magic = 3203398350,
p_comm = "cqsfeed\0006\000\000\000\000\000\000\000\000\000\000", p_pgrp = 0xffffff00a0f6f380,
p_sysent = 0xffffffff80625c80, p_args = 0xffffff005dcabd80, p_cpulimit = 9223372036854775807,
p_nice = 0 '\0', p_xstat = 0, p_klist = {kl_list = {slh_first = 0x0},
kl_lock = 0xffffffff802a15f0 <knlist_mtx_lock>, kl_unlock = 0xffffffff802a1610 <knlist_mtx_unlock>,
kl_locked = 0xffffffff802a1630 <knlist_mtx_locked>, kl_lockarg = 0xffffff004aa9f0c0}, p_numthreads = 6,
p_numksegrps = 2, p_md = <incomplete type>, p_itcallout = {c_links = {sle = {sle_next = 0x0}, tqe = {
tqe_next = 0x0, tqe_prev = 0x0}}, c_time = 0, c_arg = 0x0, c_func = 0, c_mtx = 0x0, c_flags = 16},
p_acflag = 0, p_ru = 0x0, p_peers = 0x0, p_leader = 0xffffff004aa9f000, p_emuldata = 0x0, p_label = 0x0,
p_sched = 0xffffff004aa9f340}
(kgdb) p td->td_proc->p_ksegrps
$6 = {tqh_first = 0xffffff00b5be5240, tqh_last = 0xffffff004aa9e5a8}
(kgdb) p *td->td_proc->p_ksegrps.tqh_first
$8 = {kg_proc = 0xffffff004aa9f000, kg_ksegrp = {tqe_next = 0xffffff004aa9e5a0,
tqe_prev = 0xffffff004aa9f010}, kg_threads = {tqh_first = 0xffffff004256f260,
tqh_last = 0xffffff004256f280}, kg_runq = {tqh_first = 0x0, tqh_last = 0xffffff00b5be5268},
kg_upcalls = {tqh_first = 0xffffff00ae416cc0, tqh_last = 0xffffff00ae416cc0}, kg_estcpu = 0,
kg_slptime = 2, kg_numupcalls = 1, kg_upsleeps = 0, kg_completed = 0x0, kg_nextupcall = 0,
kg_upquantum = 0, kg_pri_class = 3 '\003', kg_user_pri = 180 '\uffff', kg_numthreads = 1,
kg_sched = 0xffffff00b5be52b8}
(kgdb) p *td->td_proc->p_ksegrps.tqh_first.kg_ksegrp.tqe_next
$9 = {kg_proc = 0xffffff004aa9f000, kg_ksegrp = {tqe_next = 0x0, tqe_prev = 0xffffff00b5be5248},
kg_threads = {tqh_first = 0xffffff006f872000, tqh_last = 0xffffff00b4798020}, kg_runq = {tqh_first = 0x0,
tqh_last = 0xffffff004aa9e5c8}, kg_upcalls = {tqh_first = 0xffffff00ae416d20,
tqh_last = 0xffffff00a9ffd780}, kg_estcpu = 91, kg_slptime = 0, kg_numupcalls = 4, kg_upsleeps = 3,
kg_completed = 0x0, kg_nextupcall = 26598341, kg_upquantum = 20, kg_pri_class = 3 '\003',
kg_user_pri = 182 '\uffff', kg_numthreads = 5, kg_sched = 0xffffff004aa9e618}
(kgdb) p *td->td_proc->p_ksegrps.tqh_last
$10 = (struct ksegrp *) 0x0
(kgdb) p td->td_proc->p_threads
$20 = {tqh_first = 0xffffff006f872000, tqh_last = 0xffffff004256f270}
(kgdb) p *td->td_proc->p_threads.tqh_first
$21 = {td_proc = 0xffffff004aa9f000, td_ksegrp = 0xffffff004aa9e5a0, td_plist = {
tqe_next = 0xffffff00b5bef260, tqe_prev = 0xffffff004aa9f020}, td_kglist = {
tqe_next = 0xffffff00b5bef260, tqe_prev = 0xffffff004aa9e5b8}, td_slpq = {tqe_next = 0xffffff00b5bef260,
tqe_prev = 0xffffff003f8a7750}, td_lockq = {tqe_next = 0x0, tqe_prev = 0xffffffffb68dca70}, td_runq = {
tqe_next = 0x0, tqe_prev = 0xffffff004aa9e5c8}, td_selq = {tqh_first = 0x0,
tqh_last = 0xffffff006f872060}, td_sleepqueue = 0x0, td_turnstile = 0xffffff002f895380,
td_umtxq = 0xffffff00ae2b2000, td_tid = 100285, td_flags = 16777224, td_inhibitors = 2, td_pflags = 136,
td_dupfd = 0, td_wchan = 0xffffff004aa9e5f8, td_wmesg = 0xffffffff804a2871 "kserel", td_lastcpu = 0 '\0',
td_oncpu = 255 '\uffff', td_owepreempt = 0 '\0', td_locks = 0, td_blocked = 0x0, td_ithd = 0x0,
td_lockname = 0x0, td_contested = {lh_first = 0x0}, td_sleeplocks = 0x0, td_intr_nesting_level = 0,
td_pinned = 0, td_mailbox = 0x0, td_ucred = 0xffffff00ad18f200, td_standin = 0xffffff002fe59720,
td_upcall = 0xffffff00a9ffd840, td_sticks = 0, td_uuticks = 0, td_usticks = 0, td_intrval = 0,
td_oldsigmask = {__bits = {0, 0, 0, 0}}, td_sigmask = {__bits = {4294901503, 4294967295, 4294967295,
4294967295}}, td_siglist = {__bits = {0, 0, 0, 0}}, td_generation = 3, td_sigstk = {ss_sp = 0x0,
ss_size = 0, ss_flags = 0}, td_kflags = 1, td_xsig = 0, td_profil_addr = 0, td_profil_ticks = 0,
td_base_pri = 104 'h', td_priority = 104 'h', td_pcb = 0xffffffffb6823d10, td_state = TDS_INHIBITED,
td_retval = {0, 5950976}, td_slpcallout = {c_links = {sle = {sle_next = 0xffffff00b5bef400}, tqe = {
tqe_next = 0xffffff00b5bef400, tqe_prev = 0xffffffff99b98150}}, c_time = 26605835,
c_arg = 0xffffff006f872000, c_func = 0xffffffff802e32a0 <sleepq_timeout>, c_mtx = 0x0, c_flags = 22},
td_frame = 0xffffffffb6823c40, td_kstack_obj = 0xffffff00d36d0b60, td_kstack = 18446744072476557312,
td_kstack_pages = 4, td_altkstack_obj = 0x0, td_altkstack = 0, td_altkstack_pages = 0, td_critnest = 1,
td_md = {md_spinlock_count = 1, md_saved_flags = 582}, td_sched = 0xffffff006f872228}
(kgdb)
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20050929215152.D34322>