Skip site navigation (1)Skip section navigation (2)
Date:      Fri, 05 Jun 2009 19:00:18 +0400
From:      Menshikov Konstantin <kostjn@peterhost.ru>
Cc:        freebsd-hackers@freebsd.org
Subject:   Re: Inline function (difficult  debug)
Message-ID:  <4A293302.5040306@peterhost.ru>
In-Reply-To: <200906050938.25706.jhb@freebsd.org>
References:  <4A2792B7.5010006@peterhost.ru> <200906040749.17206.jhb@freebsd.org> <4A27C5E8.7020902@peterhost.ru> <200906050938.25706.jhb@freebsd.org>

next in thread | previous in thread | raw e-mail | index | archive | help
John Baldwin wrote:
> On Thursday 04 June 2009 9:02:32 am 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.
>>>>     
>
>
> Where did you get the pointer values from?  I meant doing 'frame 17', 'p 
> i', 'p *lock', 'p *lock1', 'p *lock2'
>
>   

Excuse I has not understood you.
Disable optimization -O0, disable inline function.
I`m get new backtrace
#0  doadump () at /usr/src/sys/kern/kern_shutdown.c:244
#1  0xffffffff801c58fc in db_fncall_generic (addr=-2142879744, 
rv=0xffffffffac0f9d88, nargs=0, args=0xffffffffac0f9d90)
    at /usr/src/sys/ddb/db_command.c:516
#2  0xffffffff801c5805 in db_fncall (dummy1=-2136396608, dummy2=0, 
dummy3=-1408262592,
    dummy4=0xffffffffac0f9e30 "`\224\224\200ЪЪЪЪЪЪЪЪ\r") at 
/usr/src/sys/ddb/db_command.c:568
#3  0xffffffff801c5546 in db_command (last_cmdp=0xffffffff809d14c0, 
cmd_table=0x0, dopager=1)
    at /usr/src/sys/ddb/db_command.c:413
#4  0xffffffff801c5644 in db_command_loop () at 
/usr/src/sys/ddb/db_command.c:466
#5  0xffffffff801c81e9 in db_trap (type=3, code=0) at 
/usr/src/sys/ddb/db_main.c:228
#6  0xffffffff8049d629 in kdb_trap (type=3, code=0, 
tf=0xffffffffac0fa0f0) at /usr/src/sys/kern/subr_kdb.c:524
#7  0xffffffff807180d2 in trap (frame=0xffffffffac0fa0f0) at 
/usr/src/sys/amd64/amd64/trap.c:538
#8  0xffffffff806f7cee in calltrap () at 
/usr/src/sys/amd64/amd64/exception.S:209
#9  0xffffffff8049d0c5 in breakpoint () at cpufunc.h:63
#10 0xffffffff8049d0b2 in kdb_enter_why (why=0xffffffff807c9140 
"witness", msg=0xffffffff807c97f0 "witness_checkorder")
    at /usr/src/sys/kern/subr_kdb.c:315
#11 0xffffffff804b3db8 in witness_checkorder (lock=0xffffffff809fb8b0, 
flags=9,
    file=0xffffffff807aeb30 "/usr/src/sys/dev/syscons/syscons.c", 
line=2519) at /usr/src/sys/kern/subr_witness.c:1126
#12 0xffffffff80453ead in _mtx_lock_spin_flags (m=0xffffffff809fb8b0, 
opts=0,
    file=0xffffffff807aeb30 "/usr/src/sys/dev/syscons/syscons.c", 
line=2519) at /usr/src/sys/kern/kern_mutex.c:227
#13 0xffffffff803a0d4d in sc_puts (scp=0xffffffff809fb760, 
buf=0xffffffffac0fa337 "a`╥\237\200ЪЪЪЪ\200д)\001", len=1)
    at /usr/src/sys/dev/syscons/syscons.c:2519
#14 0xffffffff8039f063 in sc_cnputc (cd=0xffffffff80949460, c=97) at 
/usr/src/sys/dev/syscons/syscons.c:1561
#15 0xffffffff804cf82f in cnputc (c=97) at /usr/src/sys/kern/tty_cons.c:632
#16 0xffffffff804a0864 in putcons (c=97, ap=0xffffffffac0fa6b0) at 
/usr/src/sys/kern/subr_prf.c:372
#17 0xffffffff804a09a4 in putchar (c=97, arg=0xffffffffac0fa6b0) at 
/usr/src/sys/kern/subr_prf.c:413
#18 0xffffffff804a0ee9 in kvprintf (fmt=0xffffffff807c9911 "cquiring 
duplicate lock of same type: \"%s\"\n",
    func=0xffffffff804a0920 <putchar>, arg=0xffffffffac0fa6b0, radix=10, 
ap=0xffffffffac0fa6e0)
    at /usr/src/sys/kern/subr_prf.c:599
#19 0xffffffff804a07a4 in printf (fmt=0xffffffff807c9910 "acquiring 
duplicate lock of same type: \"%s\"\n")
    at /usr/src/sys/kern/subr_prf.c:314
#20 0xffffffff804b374e in witness_checkorder (lock=0xffffffff80a13448, 
flags=9,
    file=0xffffffff807c7a38 "/usr/src/sys/kern/subr_sleepqueue.c", 
line=232) at /usr/src/sys/kern/subr_witness.c:948
#21 0xffffffff80453ead in _mtx_lock_spin_flags (m=0xffffffff80a13448, 
opts=0,
    file=0xffffffff807c7a38 "/usr/src/sys/kern/subr_sleepqueue.c", 
line=232) at /usr/src/sys/kern/kern_mutex.c:227
#22 0xffffffff804a8472 in sleepq_lock (wchan=0xffffffff809fc8a0) at 
/usr/src/sys/kern/subr_sleepqueue.c:232
#23 0xffffffff80470175 in wakeup (ident=0xffffffff809fc8a0) at 
/usr/src/sys/kern/kern_synch.c:341
#24 0xffffffff806cf110 in kick_proc0 () at /usr/src/sys/vm/vm_glue.c:761
#25 0xffffffff8046aa16 in tdsigwakeup (td=0xffffff000172a000, sig=14, 
action=0x2, intrval=4)
    at /usr/src/sys/kern/kern_sig.c:2422
#26 0xffffffff8046a5d1 in do_tdsignal (p=0xffffff0001727000, 
td=0xffffff000172a000, sig=14, ksi=0xffffff00017dfd68)
    at /usr/src/sys/kern/kern_sig.c:2292
#27 0xffffffff80469d48 in tdsignal (p=0xffffff0001727000, td=0x0, 
sig=14, ksi=0xffffff00017dfd68)
    at /usr/src/sys/kern/kern_sig.c:2029
#28 0xffffffff80469cd9 in psignal_event (p=0xffffff0001727000, 
sigev=0xffffff00017dfcd8, ksi=0xffffff00017dfd68)
    at /usr/src/sys/kern/kern_sig.c:2017
#29 0xffffffff8047c036 in itimer_fire (it=0xffffff00017dfca8) at 
/usr/src/sys/kern/kern_time.c:1419
#30 0xffffffff8047be84 in realtimer_expire (arg=0xffffff00017dfca8) at 
/usr/src/sys/kern/kern_time.c:1396
#31 0xffffffff8047c9a6 in softclock (dummy=0x0) at 
/usr/src/sys/kern/kern_timeout.c:274
#32 0xffffffff8043c057 in ithread_execute_handlers 
(p=0xffffff0001105000, ie=0xffffff000110c000)
---Type <return> to continue, or q <return> to quit---
    at /usr/src/sys/kern/kern_intr.c:1088
#33 0xffffffff8043c28f in ithread_loop (arg=0xffffff00010ecbe0) at 
/usr/src/sys/kern/kern_intr.c:1175
#34 0xffffffff8043a3d7 in fork_exit (callout=0xffffffff8043c1d0 
<ithread_loop>, arg=0xffffff00010ecbe0,
    frame=0xffffffffac0fac80) at /usr/src/sys/kern/kern_fork.c:804
#35 0xffffffff806f80be in fork_trampoline () at 
/usr/src/sys/amd64/amd64/exception.S:455


Frame 20
(kgdb) f 20
#20 0xffffffff804b374e in witness_checkorder (lock=0xffffffff80a13448, 
flags=9,
    file=0xffffffff807c7a38 "/usr/src/sys/kern/subr_sleepqueue.c", 
line=232) at /usr/src/sys/kern/subr_witness.c:948
948            printf("acquiring duplicate lock of same type: \"%s\"\n",
(kgdb) p *lock
$1 = {lo_name = 0xffffffff807c7a20 "sleepq chain", lo_type = 
0xffffffff807c7a20 "sleepq chain", lo_flags = 720896,
  lo_witness_data = {lod_list = {stqe_next = 0xffffffff80a251a0}, 
lod_witness = 0xffffffff80a251a0}}
(kgdb) p *lock1
$2 = {li_lock = 0xffffffff80a12db8, li_file = 0xffffffff807c22f5 
"/usr/src/sys/kern/kern_sig.c", li_line = 2291,
  li_flags = 65536}
(kgdb) p *lock2
$3 = {li_lock = 0xffffffff80a10d40, li_file = 0xffffff0001105000 
"xT\020\001", li_line = 0, li_flags = 0}
(kgdb) p i
$4 = -2139345904


Frame 11
(kgdb) f 11
#11 0xffffffff804b3db8 in witness_checkorder (lock=0xffffffff809fb8b0, 
flags=9,
    file=0xffffffff807aeb30 "/usr/src/sys/dev/syscons/syscons.c", 
line=2519) at /usr/src/sys/kern/subr_witness.c:1126
1126            kdb_enter_why(KDB_WHY_WITNESS, __func__);
(kgdb) p *lock
$6 = {lo_name = 0xffffffff807aebc5 "scrlock", lo_type = 
0xffffffff807aebc5 "scrlock", lo_flags = 8585216,
  lo_witness_data = {lod_list = {stqe_next = 0xffffffff80a25320}, 
lod_witness = 0xffffffff80a25320}}
(kgdb) p *lock1
$7 = {li_lock = 0xffffffff80a12db8, li_file = 0xffffffff807c22f5 
"/usr/src/sys/kern/kern_sig.c", li_line = 2291,
  li_flags = 65536}
(kgdb) p *lock2
$8 = {li_lock = 0xffffff0001727030, li_file = 0xffffffff807c22f5 
"/usr/src/sys/kern/kern_sig.c", li_line = 2176,
  li_flags = 65536}
(kgdb) p i
$9 = -1

Thanks.



Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?4A293302.5040306>