Date: Thu, 04 Jun 2009 17:54:04 +0400 From: Menshikov Konstantin <kostjn@peterhost.ru> To: freebsd-hackers@freebsd.org Subject: Re: Inline function (difficult debug) Message-ID: <4A27D1FC.1020408@peterhost.ru> In-Reply-To: <4A27C5E8.7020902@peterhost.ru> References: <4A2792B7.5010006@peterhost.ru> <200906040749.17206.jhb@freebsd.org> <4A27C5E8.7020902@peterhost.ru>
next in thread | previous in thread | raw e-mail | index | archive | help
Menshikov Konstantin wrote:
> John Baldwin wrote:
>> On Thursday 04 June 2009 5:24:07 am Menshikov Konstantin wrote:
>>
>>> Hi.
>>> My system FreeBSD 7.1 RELEASE periodically freeze.
>>>
>>> I`m compiling kernel with WITNESS and get backtrace.
>>>
>>> #0 doadump () at pcpu.h:195
>>> #1 0xffffffff801a899c in db_fncall (dummy1=Variable "dummy1" is not
>>> available.
>>> ) at /usr/src/sys/ddb/db_command.c:516
>>> #2 0xffffffff801a8ecf in db_command (last_cmdp=0xffffffff80825688,
>>> cmd_table=0x0, dopager=1)
>>> at /usr/src/sys/ddb/db_command.c:413
>>> #3 0xffffffff801a90e0 in db_command_loop () at
>>> /usr/src/sys/ddb/db_command.c:466
>>> #4 0xffffffff801aaa19 in db_trap (type=Variable "type" is not
>>> available.
>>> ) at /usr/src/sys/ddb/db_main.c:228
>>> #5 0xffffffff803d5e55 in kdb_trap (type=3, code=0,
>>> tf=0xffffffffabf284c0) at /usr/src/sys/kern/subr_kdb.c:524
>>> #6 0xffffffff8059a0e5 in trap (frame=0xffffffffabf284c0) at
>>> /usr/src/sys/amd64/amd64/trap.c:538
>>> #7 0xffffffff8057f60e in calltrap () at
>>> /usr/src/sys/amd64/amd64/exception.S:209
>>> #8 0xffffffff803d602d in kdb_enter_why (why=0xffffffff80628137
>>> "witness", msg=0xa <Address 0xa out of bounds>)
>>> at cpufunc.h:63
>>> #9 0xffffffff803e70c3 in witness_checkorder (lock=Variable "lock" is
>>> not available.
>>> ) at /usr/src/sys/kern/subr_witness.c:1126
>>> #10 0xffffffff8039e341 in _mtx_lock_spin_flags
>>> (m=0xffffffff8084fad0, opts=0, file=dwarf2_read_address: Corrupted
>>> DWARF expression.
>>> ) at /usr/src/sys/kern/kern_mutex.c:227
>>> #11 0xffffffff80319838 in sc_puts (scp=0xffffffff8084f980,
>>> buf=0xffffffffabf286a7 "a@\az\200ЪЪЪЪ", len=1)
>>> at /usr/src/sys/dev/syscons/syscons.c:2519
>>> #12 0xffffffff8031b3da in sc_cnputc (cd=Variable "cd" is not available.
>>> ) at /usr/src/sys/dev/syscons/syscons.c:1561
>>> #13 0xffffffff803f9d89 in cnputc (c=97) at
>>> /usr/src/sys/kern/tty_cons.c:632
>>> #14 0xffffffff803d993b in putchar (c=97, arg=Variable "arg" is not
>>> available.
>>> ) at /usr/src/sys/kern/subr_prf.c:421
>>> #15 0xffffffff803d7f22 in kvprintf (fmt=0xffffffff80628b89 "cquiring
>>> duplicate lock of same type: \"%s\"\n",
>>> func=0xffffffff803d98d0 <putchar>, arg=0xffffffffabf28890, radix=10,
>>> ap=Variable "ap" is not available.
>>> ) at /usr/src/sys/kern/subr_prf.c:674
>>> #16 0xffffffff803d9384 in printf (fmt=Variable "fmt" is not available.
>>> ) at /usr/src/sys/kern/subr_prf.c:314
>>> #17 0xffffffff803e705d in witness_checkorder
>>> (lock=0xffffffff808668f8, flags=0,
>>> file=0xffffffff80626cf8 "/usr/src/sys/kern/subr_sleepqueue.c",
>>> line=232) at /usr/src/sys/kern/subr_witness.c:948
>>> #18 0xffffffff8039e341 in _mtx_lock_spin_flags
>>> (m=0xffffffff808668f8, opts=0, file=dwarf2_read_address: Corrupted
>>> DWARF expression.
>>> ) at /usr/src/sys/kern/kern_mutex.c:227
>>> #19 0xffffffff803b2271 in wakeup (ident=0xffffffff80850ac0) at
>>> /usr/src/sys/kern/kern_synch.c:341
>>> #20 0xffffffff803aed95 in tdsignal (p=0xffffff00017978f0,
>>> td=0xffffff000146a6e0, sig=14, ksi=Variable "ksi" is not available.
>>> )
>>> at /usr/src/sys/kern/kern_sig.c:2292
>>> #21 0xffffffff803ba2de in realitexpire (arg=Variable "arg" is not
>>> available.
>>> ) at /usr/src/sys/kern/kern_time.c:669
>>> #22 0xffffffff803bbe1a in softclock (dummy=Variable "dummy" is not
>>> available.
>>> ) at /usr/src/sys/kern/kern_timeout.c:274
>>> #23 0xffffffff8038c120 in ithread_loop (arg=0xffffff00010ebc00) at
>>> /usr/src/sys/kern/kern_intr.c:1088
>>> #24 0xffffffff8038978a in fork_exit (callout=0xffffffff8038c040
>>> <ithread_loop>, arg=0xffffff00010ebc00,
>>> frame=0xffffffffabf28c80) at /usr/src/sys/kern/kern_fork.c:804
>>> #25 0xffffffff8057f9de in fork_trampoline () at
>>> /usr/src/sys/amd64/amd64/exception.S:455
>>>
>>> But file /usr/src/sys/kern/kern_sig.c:2292
>>> hasn`t run function wake up on string 2292
>>> I`m think, what compiler use inline function, therefore code and
>>> trace differ.
>>> Tell me please, how compile kernel without any inline function.
>>>
>>
>> makeoptions DEBUG="-g -fno-inline"
>>
>> However. I think you already have enough information to debug this.
>> Can you go to frame 17 and do an 'l'? I think the two things you
>> want to print out are "i", "*lock", "*lock1", and "*lock2".
>>
>>
> Unfortunately, the kernel is not compiled with an option-fno-inline.
> cc -c -O2 -frename-registers -pipe -fno-strict-aliasing -std=c99 -g
> -fno-inline -Wall -Wredundant-decls -Wnested-externs
> -Wstrict-prototypes -Wmissing-prototypes -Wpointer-arith -Winline
> -Wcast-qual -Wundef -Wno-pointer-sign -fformat-extensions -nostdinc
> -I. -I/usr/src/sys -I/usr/src/sys/contrib/altq -D_KERNEL
> -DHAVE_KERNEL_OPTION_HEADERS -include opt_global.h -fno-common
> -finline-limit=8000 --param inline-unit-growth=100 --param
> large-function-growth=1000 -fno-omit-frame-pointer -mcmodel=kernel
> -mno-red-zone -mfpmath=387 -mno-sse -mno-sse2 -mno-mmx -mno-3dnow
> -msoft-float -fno-asynchronous-unwind-tables -ffreestanding -Werror
> /usr/src/sys/cam/cam_periph.c
> cc1: warnings being treated as errors
> /usr/src/sys/cam/cam_periph.c: In function 'scsi_extract_sense':
> /usr/src/sys/cam/scsi/scsi_all.h:1215: warning: function
> 'scsi_extract_sense' can never be inlined because it is suppressed
> using -fno-inline
>
> I`m try build with -O0 options.
>
> lock in frame 17
> (kgdb) print {struct mtx} 0xffffffff808668f8
> $4 = {lock_object = {lo_name = 0xffffffff806270eb "sleepq chain",
> lo_type = 0xffffffff806270eb "sleepq chain",
> lo_flags = 720896, lo_witness_data = {lod_list = {stqe_next =
> 0xffffffff808793e0}, lod_witness = 0xffffffff808793e0}},
> mtx_lock = 4, mtx_recurse = 0}
> next in list
> (kgdb) print {struct mtx} 0xffffffff808793e0
> $5 = {lock_object = {lo_name = 0xffffffff806270eb "sleepq chain",
> lo_type = 0xffffffff807e8860 "\031\006b\200ЪЪЪЪ\n",
> lo_flags = 2156368928, lo_witness_data = {lod_list = {stqe_next =
> 0xffffffff80879420},
> lod_witness = 0xffffffff80879420}}, mtx_lock =
> 18446744071571216096, mtx_recurse = 2153913763}
> (kgdb) print {struct mtx} 0xffffffff80879420
> next
> $6 = {lock_object = {lo_name = 0xffffffff806205df "process slock",
> lo_type = 0xffffffff807e8860 "\031\006b\200ЪЪЪЪ\n",
> lo_flags = 2156368992, lo_witness_data = {lod_list = {stqe_next =
> 0xffffffff80879460},
> lod_witness = 0xffffffff80879460}}, mtx_lock =
> 18446744071571216160, mtx_recurse = 2153889520}
>
> As far as I understand, 2 times are requested blocking of one class.
> Besides, too great values mtx_recurse it is wrong.
>
Sorry, I was mistaken.
thread spin lock.
$35 = {lock_object = {lo_name = 0xffffffff806270eb "sleepq chain",
lo_type = 0xffffffff806270eb "sleepq chain",
lo_flags = 720896, lo_witness_data = {lod_list = {stqe_next =
0xffffffff808793e0}, lod_witness = 0xffffffff808793e0}},
mtx_lock = 4, mtx_recurse = 0}
(kgdb) print {struct witness} 0xffffffff808793e0
$36 = {w_name = 0xffffffff806270eb "sleepq chain", w_class =
0xffffffff807e8860, w_list = {stqe_next = 0xffffffff80879420},
w_typelist = {stqe_next = 0xffffffff80879420}, w_children =
0xffffffff808b96e0,
w_file = 0xffffffff80621da3 "/usr/src/sys/kern/kern_sig.c", w_line =
2291, w_level = 0, w_refcount = 129,
w_Giant_squawked = 0 '\0', w_other_squawked = 1 '\001',
w_same_squawked = 1 '\001', w_displayed = 0 '\0'}
next struct witness
proc spin lock
(kgdb) print {struct proc} 0xffffff00013a4478
$55 = {p_list = {le_next = 0xffffff00013a7000, le_prev =
0xffffff0001416000}, p_threads = {tqh_first = 0xffffff000144e370,
tqh_last = 0xffffff000144e380}, p_upcalls = {tqh_first = 0x0,
tqh_last = 0xffffff00013a4498}, p_slock = {lock_object = {
lo_name = 0xffffffff806205df "process slock", lo_type =
0xffffffff806205df "process slock", lo_flags = 720896,
lo_witness_data = {lod_list = {stqe_next = 0xffffffff80879420},
lod_witness = 0xffffffff80879420}},
mtx_lock = 18446742974215689072, mtx_recurse = 0}...
$56 = {w_name = 0xffffffff806205df "process slock", w_class =
0xffffffff807e8860, w_list = {
stqe_next = 0xffffffff80879460}, w_typelist = {stqe_next =
0xffffffff80879460}, w_children = 0xffffffff808b9720,
w_file = 0xffffffff8061bef0 "/usr/src/sys/kern/kern_clock.c", w_line =
281, w_level = 0, w_refcount = 431,
w_Giant_squawked = 0 '\0', w_other_squawked = 0 '\0', w_same_squawked
= 0 '\0', w_displayed = 0 '\0'}
If it is fair, while I do not know, where exactly a problem.
If you are ready to try to help, I can give a kernel and dump to memory.
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?4A27D1FC.1020408>