Chinaunix
标题:
Solaris学习笔记(6)上 - 07年9月修订版
[打印本页]
作者:
Solaris12
时间:
2007-03-11 14:12
标题:
Solaris学习笔记(6)上 - 07年9月修订版
Solaris学习笔记(6) － 07年9月修订版
作者: Badcoffee
Email:
blog.oliver@gmail.com
Blog:
http://blog.csdn.net/yayong
2007年9月
本文介绍使用kmdb和mdb调试Solaris内核的基本方法，kmdb和mdb是Solaris默认安装的内核模块调试器，可以用于调试和定位内核模块及驱动程序发生的错误。本文仅用于学习交流目的，错误再所难免，如果有勘误或疑问请与作者联系。
本文首次发布于07年3月，此后因网友发现错误而修订于07年9月。在此感谢细心网友指出我的错误。
关键词：
mdb/kmdb/panic/hang/crashdump/dump/kernel/debug/Solaris/OpenSolaris
系统panic和hang是内核开发人员常遇到的两个问题。在Solaris学习笔记(5)中，我们对一个panic做出了简单分析，可以看到，通过系统panic线程的调用栈信息，通过检查函数的入口参数，我们可以比较快速的定位引起panic内核模块，并做深入分析。但是系统hang的问题有时会更复杂一些，通常，我们会尝试在系统hang发生时，强制系统产生一个crash dump，通过检查当时内核的状态来定位问题。
系统hang的分类
1. 死锁(deadlock)问题
死锁问题，通常会导致操作系统无法正常调度系统内核线程；因此，通过对调度队列(dispatch queue)及相关内核线程的状态和这些线程持有锁的检查，通常可以定位问题的发生，描绘出系统是如何发生死锁的。
2. 系统资源耗尽
系统资源耗尽也是引起系统hang的原因之一，因此，对系统的CPU，物理内存，slab子系统的检查往往是定位此类问题的关键。
3. 硬件问题
硬件引起的问题往往令人难以琢磨，不幸的是，在开发中，尤其是系统软件的开发，我们经常会遇到此类问题。当我们排除问题不属于前面描述的两类时，往往要考虑硬件问题。
关于Sparc系统
在Sparc系统上，当系统hang发生时，即便我们不再启动时加载kmdb，我们也可以通过进入OBP，通过sync命令来产生一个crashdump, 然后再用mdb对这个crash dump进行事后分析：
Type 'go' to resume
{1} ok sync
panic[cpu1]/thread=2a10037fcc0: sync initiated
sched: software trap 0x7f
pid=0, pc=0xf0046ac0, sp=0xede4f3c1, tstate=0x8800001400, context=0x0
g1-g7: 134167c, 1, 5, 18f5c90, 0, eddc1190, 1343d4c
00000000fedd3cd0 unix:sync_handler+138 (180c000, 0, 1, 109e000, 1, 1818800)
%l0-3: 0000000001863d80 0000000001863c00 000000000000017f 000000000185a000
%l4-7: 0000000000000000 0000000001853400 0000000000000003 0000000001814400
00000000fedd3da0 unix:vx_handler+80 (fad99478, 1822138, 0, 2928, 1822240, f0057d3d)
%l0-3: 0000000001822240 0000000000000000 0000000000000001 0000000000000001
%l4-7: 0000000001815000 00000000f0000000 0000000001000000 000000000101dde4
00000000fedd3e50 unix:callback_handler+20 (fad99478, fff6a280, 0, 0, 0, 0)
%l0-3: 0000000000000016 00000000fedd3701 00000000f0000000 00000000fff78000
%l4-7: 00000000f0046a68 0000000000000000 0000000000000000 00000000fff657a8
syncing file systems... done
dumping to /dev/dsk/c0t0d0s1, offset 214827008, content: kernel
100% done: 51986 pages dumped, compression ratio 4.20, dump succeeded
关于x86系统
在x86下，由于没有OBP的支持，因此只有引导时加载kmdb，才可以在系统hang时通过激活kmdb来产生crashdump；在Solaris x86上设置和激活kmdb的方法，在Solaris学习笔记(5)已经给出过，在此就不再赘述。
案例分析
问题描述：
一个同事正在尝试改进Solaris的Intel千兆网卡驱动(e1000g)，在新编译出版本上运行测试时，系统hang频繁发生，并且可以通过运行相同的测试重现该问题。
对于可以稳定重现的此类问题，即便在不了解root cause的情况下，通过查看新修改的代码，不断的修改－重试，总能定位到出问题的代码。
但是，无疑这需要耗费很多时间，并且整个过程是痛苦和索然无味的，而且也许你解决了问题，但是不知道问题的本质。
现在让我们用更理性更符合逻辑的方式来分析和解决这个问题。
1. Enable kmdb － 过程略，方法详见Solaris学习笔记(5)
2. 加载新驱动，运行测试来重现这个系统hang － 过程略
3. 系统hang再次发生，在console上激活kmdb，产生一个crashdump - 过程略，方法详见Solaris学习笔记(5)
4. 系统重启后，用mdb检查crashdump文件，过程如下：
在dumpadm(1M)指示的路径下，用mdb打开序号最新的文件：
> mdb 3
Loading modules: [ unix krtld genunix specfs dtrace cpu.AuthenticAMD.15 uppc pcplusmp scsi_vhci ufs ip hook neti sctp arp
usba nca lofs zfs random nfs sppp crypto ptm ]
检查系统缓冲区，看是否能得到与网卡驱动或者系统hang相关的信息：
> ::msgbuf
MESSAGE
pcplusmp: pci1000,30 (mpt) instance 0 vector 0x1b ioapic 0x3 intin 0x3 is bound to cpu 0
..........................................................
..........................................................
..........................................................
panic[cpu1]/thread=fffffe8000401c80:
BAD TRAP: type=e (#pf Page fault) rp=fffffe800043dd70 addr=0 occurred in module "" due to a NULL pointer dereference
sched:
#pf Page fault
Bad kernel fault at addr=0x0
pid=0, pc=0x0, sp=0xfffffe800043de68, eflags=0x10046
cr0: 8005003bpg,wp,ne,et,ts,mp,pe> cr4: 6f0xmme,fxsr,pge,mce,pae,pse>
cr2: 0 cr3: f8f4000 cr8: c
rdi: 286 rsi: 2000 rdx: 3f8
rcx: 11 r8: fffffffffbcc9eb0 r9: ffffffff82e46000
rax: 0 rbx: 0 rbp: fffffe800043de70
r10: fffffffffbc4c3c0 r11: 290818a385a r12: 0
r13: ffffffff82751480 r14: ffffffff82e5a080 r15: 0
fsb: ffffffff80000000 gsb: ffffffff82e46000 ds: 43
es: 43 fs: 0 gs: 1c3
trp: e err: 10 rip: 0
cs: 28 rfl: 10046 rsp: fffffe800043de68
ss: 30
fffffe800043dc50 unix:die+c8 ()
fffffe800043dd60 unix:trap+12ec ()
fffffe800043dd70 unix:cmntrap+140 ()
fffffe800043de70 0 ()
fffffe800043de80 genunix:kdi_dvec_enter+10 ()
fffffe800043deb0 unix:debug_enter+37 ()
fffffe800043dee0 unix:abort_sequence_enter+35 ()
fffffe800043df40 asy:async_rxint+24d ()
fffffe800043df90 asy:asyintr+c7 ()
fffffe800043dff0 unix:av_dispatch_autovect+7b ()
fffffe8000401b30 unix:cmnint+155 ()
fffffe8000401c40 unix:cpu_halt+c5 ()
fffffe8000401c60 unix:idle+116 ()
fffffe8000401c70 unix:thread_start+8 ()
syncing file systems...
done
dumping to /dev/dsk/c1t0d0s1, offset 429719552, content: kernel
本例中::msgbuf的输出中并没有找到什么有价值的信息，如e1000g驱动的错误消息，或者内核的错误消息；由于系统panic是我们通过kmdb强制产生的，因此调用栈的信息并不像分析panic时那样是非常重要的，而且，在本例中毫无用处，可以从调用栈看到，我们的console时重定向到串口设备上的，因此才会出现asy驱动的名字。
接着我们检查调度队列，来看看在CPU上和dispatch queue上的线程状态：
> ::cpuinfo -v
ID ADDR FLG NRUN BSPL PRI RNRN KRNRN SWITCH THREAD PROC
0 fffffffffbc27730 1f 1 6 169 no no t-3 fffffe80000bfc80 sched
| | |
RUNNING | +--> PIL THREAD
READY | 10 fffffe80000bfc80
QUIESCED | 6 fffffe80000b9c80
EXISTS |
ENABLE +--> PRI THREAD PROC
99 fffffe80000d1c80 sched
ID ADDR FLG NRUN BSPL PRI RNRN KRNRN SWITCH THREAD PROC
1 fffffffffbc2f260 1b 1 0 -1 no no t-17 fffffe8000401c80 (idle)
| |
RUNNING +--> PRI THREAD PROC
READY 60 fffffe80044d9c80 sched
EXISTS
ENABLE
系统中有两个CPU，我们先检查CPU 0相关的线程，共3个，状态如下：
fffffe80000bfc80 － 在CPU上正在运行，panic时，运行了3个tick，它的PIL是10，应该是时钟中断线程；
fffffe80000b9c80 － 该线程PIL是6，是中断线程，状态不明；
fffffe80000d1c80 － 是内核线程，调度优先级为99，在dispatch queue上，等待被CPU 0调度；
首先，我们检查正在CPU 0上运行的线程的状态：
> fffffe80000bfc80::thread -i
ADDR STATE FLG PFLG SFLG PRI EPRI PIL INTR
fffffe80000bfc80 onproc 9 0 3 169 0 10 fffffe8000005c80
状态是onproc，果然是正在运行，用::findstack可以查看这个线程的调用栈：
> fffffe80000bfc80::findstack -v
stack pointer for thread fffffe80000bfc80: fffffe80000bf8e0
fffffe80000bf930 apic_intr_enter+0xc7(fffffffffbc27730, f)
fffffe80000bf940 _interrupt+0x13b()
fffffe80000bfa60 pc_rtcget+0xe3(fffffe80000bfa80)
fffffe80000bfac0 pc_tod_get+0x13()
fffffe80000bfae0 tod_get+0x11()
fffffe80000bfb50 clock+0x737()
fffffe80000bfc00 cyclic_softint+0xc9(fffffffffbc27730, 1)
fffffe80000bfc10 cbe_softclock+0x1a()
fffffe80000bfc60 av_dispatch_softvect+0x5f(a)
fffffe80000bfc70 dosoftint+0x32()
可以看出，它的确是时钟中断线程，clock函数是实际上solaris时钟中断线程需要执行的一个函数。
接着查看fffffe80000b9c80，这个线程的PIL是6，因为网卡的中断线程PIL就是6，所以很有可能它就是我们的网卡中断线程：
> fffffe80000b9c80::thread -i
ADDR STATE FLG PFLG SFLG PRI EPRI PIL INTR
fffffe80000b9c80 sleep 9 0 3 165 0 6 n/a
> fffffe80000b9c80::findstack -v
stack pointer for thread fffffe80000b9c80: fffffe80000b9a70
[ fffffe80000b9a70 resume_from_intr+0xbb() ]
fffffe80000b9ab0 swtch+0x9f()
fffffe80000b9b50 turnstile_block+0x76b(ffffffff93338a00, 1, ffffffff82f76288, fffffffffbc05908, 0, 0)
fffffe80000b9bb0 rw_enter_sleep+0x1de(ffffffff82f76288, 1)
fffffe80000b9c00 e1000g_intr+0x94(ffffffff82f76000)
fffffe80000b9c60 av_dispatch_autovect+0x7b(1b)
fffffe80000b9c70 intr_thread+0x50()
果然，e1000g_intr告诉我们，这是e1000g网卡驱动的中断处理例程，即ISR。
在接下来检查第3个线程前，我们在网卡驱动函数的调用栈中，发现了一个有趣的信息，那就是这个网卡中断在尝试获得一个rwlock(读写锁)未果，最后睡眠了：
e1000g_intr －> rw_enter_sleep -> turnstile_block -> swtch
rw_enter_sleep则告诉我们它尝试获得rwlock失败；
turnstile_block告诉我们它被置入turnstile队列，即一种特殊的sleep queue；
swtch函数，告诉我们它已经完成上下文切换；
上面就是典型的尝试获得rwlock未果而睡眠的调用栈；
查看OpenSolaris的源代码，可以知道，turnstile_block的第三个参数就是rwlock的地址：
http://src.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/uts/common/os/turnstile.c#turnstile_block
int
turnstile_block(turnstile_t *ts, int qnum, void *sobj, sobj_ops_t *sobj_ops,
kmutex_t *mp, lwp_timer_t *lwptp)
{
....................
}
那么，我们就可以用turnstile_block的第三个参数的地址来检查rwlock的状态：
> ffffffff82f76288::rwlock
ADDR OWNER/COUNT FLAGS WAITERS
ffffffff82f76288 READERS=1 B011 ffffffff838470c0 (W)
| | fffffe800027bc80 (R)
WRITE_WANTED -------+| fffffe80000ddc80 (R)
HAS_WAITERS --------+ fffffe80000b9c80 (R)
可以看到，有4个内核线程阻塞在这个rwlock上，其中1个写者和3个读者，所以WRITE_WANTED和HAS_WAITERS位都置1了，并且最重要的是，该rwlock的具体类型是读锁，因为在OWNER/COUNT域的值是拥有锁的读者数，即READERS=1，这表明这是一个读锁；如果是写锁，那么OWNER/COUNT就应该是拥有写锁的内核线程地址；
我们可以查看阻塞在该rwlock上的4个线程的调用栈，它们全都和e1000g驱动有关：
> ffffffff82f76288::walk blocked |::findstack -v
stack pointer for thread fffffe80000b9c80: fffffe80000b9a70
[ fffffe80000b9a70 resume_from_intr+0xbb() ]
fffffe80000b9ab0 swtch+0x9f()
fffffe80000b9b50 turnstile_block+0x76b(ffffffff93338a00, 1, ffffffff82f76288, fffffffffbc05908, 0, 0)
fffffe80000b9bb0 rw_enter_sleep+0x1de(ffffffff82f76288, 1)
fffffe80000b9c00 e1000g_intr+0x94(ffffffff82f76000)
fffffe80000b9c60 av_dispatch_autovect+0x7b(1b)
fffffe80000b9c70 intr_thread+0x50()
stack pointer for thread fffffe80000ddc80: fffffe80000dd9d0
[ fffffe80000dd9d0 _resume_from_idle+0xf8() ]
fffffe80000dda10 swtch+0x167()
fffffe80000ddab0 turnstile_block+0x76b(ffffffff93338a00, 1, ffffffff82f76288, fffffffffbc05908, 0, 0)
fffffe80000ddb10 rw_enter_sleep+0x1de(ffffffff82f76288, 1)
fffffe80000ddb40 e1000g_tx_cleanup+0x56(ffffffff82f76000)
fffffe80000ddb80 e1000g_LocalTimer+0x19(ffffffff82f76000)
fffffe80000ddbd0 callout_execute+0xb1(ffffffff80a3e000)
fffffe80000ddc60 taskq_thread+0x1a7(ffffffff826be7a0)
fffffe80000ddc70 thread_start+8()
stack pointer for thread fffffe800027bc80: fffffe800027b1a0
[ fffffe800027b1a0 _resume_from_idle+0xf8() ]
fffffe800027b1e0 swtch+0x167()
fffffe800027b280 turnstile_block+0x76b(ffffffff93338a00, 1, ffffffff82f76288, fffffffffbc05908, 0, 0)
fffffe800027b2e0 rw_enter_sleep+0x1de(ffffffff82f76288, 1)
fffffe800027b320 e1000g_m_tx+0x3f(ffffffff82f76000, ffffffff9054d540)
fffffe800027b340 dls_tx+0x1d(ffffffff82f2ebe8, ffffffff9054d540)
fffffe800027b370 dld_tx_single+0x2a(ffffffff83a75888, ffffffff9054d540)
fffffe800027b400 proto_unitdata_req+0x1a0(ffffffff83a75888, ffffffff9ad3c970, ffffffff9ad3f780)
fffffe800027b420 dld_proto+0x84(ffffffff83a75888, ffffffff9ad3f780)
fffffe800027b460 dld_wput+0xe2(ffffffff894ab138, ffffffff9ad3f780)
fffffe800027b4d0 putnext+0x22b(ffffffff8ed2de10, ffffffff9ad3f780)
fffffe800027b5a0 ar_xmit+0x2d3(ffffffff84eef8e8, 1, 800, 4, ffffffff83717840, ffffffff9a09046c, ffffffff837177f0,
ffffffff9a090468
, ffffffff837177f0)
fffffe800027b620 ar_query_xmit+0xf2(ffffffff8ed2c798, ffffffff8ed25bd8)
fffffe800027b690 ar_entry_query+0x361(ffffffff894abd10, ffffffff9a099240)
fffffe800027b6d0 ar_cmd_dispatch+0x12e(ffffffff894abd10, ffffffff9a099240)
fffffe800027b790 ar_rput+0x62c(ffffffff894abd10, ffffffff9a099240)
fffffe800027b800 putnext+0x22b(ffffffff894ac7e8, ffffffff9a099240)
fffffe800027b940 ip_newroute+0xf4e(ffffffff919c2110, ffffffffab8dbb80, f603000b, 0, ffffffff9187e000, 0)
fffffe800027ba00 ip_output+0xc7b(ffffffff9187e000, ffffffffab8dbb80, ffffffff919c2110, 2)
fffffe800027bad0 tcp_send_data+0x174(ffffffff9187e200, ffffffff919c2110, ffffffffab8dbb80)
fffffe800027bb20 tcp_timer+0x942(ffffffff9187e000)
fffffe800027bb60 tcp_timer_handler+0x37(ffffffff9187e000, ffffffff919085f8, ffffffff82e8bf00)
fffffe800027bbf0 squeue_drain+0x1e0(ffffffff82e8bf00, 2, af62fce930)
fffffe800027bc60 squeue_worker+0x10e(ffffffff82e8bf00)
fffffe800027bc70 thread_start+8()
stack pointer for thread ffffffff838470c0: fffffe8000a38890
[ fffffe8000a38890 _resume_from_idle+0xf8() ]
fffffe8000a388d0 swtch+0x167()
fffffe8000a38970 turnstile_block+0x76b(0, 0, ffffffff82f76288, fffffffffbc05908, 0, 0)
fffffe8000a389d0 rw_enter_sleep+0x16b(ffffffff82f76288, 0)
fffffe8000a38a40 e1000g_m_stat+0x44(ffffffff82f76000, 3e8, fffffe8000a38a68)
fffffe8000a38a80 mac_stat_get+0x73(ffffffff83318a88, 3e8)
fffffe8000a38ad0 i_dls_stat_update+0x67(ffffffff894b4640, 0)
fffffe8000a38ca0 read_kstat_data+0x142(fffffe8000a38e9c, 80c8b80, 100001)
fffffe8000a38ce0 kstat_ioctl+0x4a(5a00000000, 4b02, 80c8b80, 100001, ffffffff9067d858, fffffe8000a38e9c)
fffffe8000a38d20 cdev_ioctl+0x48(5a00000000, 4b02, 80c8b80, 100001, ffffffff9067d858, fffffe8000a38e9c)
fffffe8000a38d60 spec_ioctl+0x86(ffffffff82f48880, 4b02, 80c8b80, 100001, ffffffff9067d858, fffffe8000a38e9c)
fffffe8000a38dc0 fop_ioctl+0x37(ffffffff82f48880, 4b02, 80c8b80, 100001, ffffffff9067d858, fffffe8000a38e9c)
fffffe8000a38ec0 ioctl+0x16b(4, 4b02, 80c8b80)
fffffe8000a38f10 sys_syscall32+0x101()
那么，现在的问题是，这样的情况是否正常呢？是否它们和系统hang有关呢？
我们知道，Linux的中断处理函数中是只能用自旋锁的，中断处理函数阻塞将会导致灾难。
和Linux不同，Solaris的中断服务是由中断线程来完成的，中断线程中可以阻塞并睡眠；因此，到目前为止，似乎没有什么异常。
但是，考虑死锁的情况，如果拥有该rwlock的线程因为某种原因而无法释放该锁，那么这4个线程就永远无法得到执行，这样肯定就不是正常情况了。
因此，我们需要找到这个rwlock的拥有者，检查它的状态是否正确。
寻找锁的拥有者
我们把系统内所有内核线程的栈全部得到，并保存到一个临时文件中：
>::log -e /tmp/a.log
>::threadlist -v
>::log -d
然后，用vi打开这个临时文件a.log，查找包含e1000g的所有线程。
在a.log里一共有5个e1000g线程，其中4个是阻塞在那个rwlock上的线程，剩下的唯一1个的调用栈如下：
stack pointer for thread fffffe80044e5c80: fffffe80044e5880
[ fffffe80044e5880 _resume_from_idle+0xf8() ]
fffffe80044e58c0 swtch+0x167()
fffffe80044e5930 cv_timedwait+0xcf(ffffffff82f76390, ffffffff82f76388, 1036d)
fffffe80044e59c0 cv_timedwait_sig+0x2cc(ffffffff82f76390, ffffffff82f76388, 1036d)
fffffe80044e5a70 e1000g_send+0x136(ffffffff82f76370, ffffffffac2fce40)
fffffe80044e5ab0 e1000g_m_tx+0x6f(ffffffff82f76000, ffffffffa21f8180)
fffffe80044e5ad0 dls_tx+0x1d(ffffffff82f2ec80, ffffffffa21f8180)
fffffe80044e5b20 dld_wsrv+0xcc(ffffffff894acb70)
fffffe80044e5b50 runservice+0x42(ffffffff894acb70)
fffffe80044e5b80 queue_service+0x42(ffffffff894acb70)
fffffe80044e5bc0 stream_service+0x73(ffffffff83905740)
fffffe80044e5c60 taskq_d_thread+0xbb(ffffffff833af820)
fffffe80044e5c70 thread_start+8()
那么这个线程是否是那个rwlock的唯一读者呢？如果手头有代码的话，那就容易验证了；只需要看一下e1000g_m_tx的源代码和上面的调用栈既可以知道了；可惜手头没有源代码，只能看反汇编的代码了：
> e1000g_m_tx::dis
e1000g_m_tx: pushq %rbp
e1000g_m_tx+1: movq %rsp,%rbp
e1000g_m_tx+4: subq $0x10,%rsp
e1000g_m_tx+8: pushq %r12
e1000g_m_tx+0xa: pushq %r13
e1000g_m_tx+0xc: pushq %r14
e1000g_m_tx+0xe: pushq %r15
e1000g_m_tx+0x10: movq %rdi,-0x8(%rbp)
e1000g_m_tx+0x14: movq %rsi,-0x10(%rbp)
e1000g_m_tx+0x18: movq %rsi,%r13
e1000g_m_tx+0x1b: movq %rdi,%r14
e1000g_m_tx+0x1e: movq %r14,%r15
e1000g_m_tx+0x21: addq $0x370,%r15
e1000g_m_tx+0x28: movq %r14,%rdi
e1000g_m_tx+0x2b: addq $0x288,%rdi
e1000g_m_tx+0x32: movq %rdi,%r12
e1000g_m_tx+0x35: movl $0x1,%esi
e1000g_m_tx+0x3a: call +0xb2ce471 rw_enter>
e1000g_m_tx+0x3f: cmpl $0x0,0x238(%r14)
e1000g_m_tx+0x47: jne +0xb e1000g_m_tx+0x54>
e1000g_m_tx+0x49: movq %r13,%rdi
e1000g_m_tx+0x4c: call +0xb4b7e1f freemsgchain>
e1000g_m_tx+0x51: xorq %r13,%r13
e1000g_m_tx+0x54: testq %r13,%r13
e1000g_m_tx+0x57: je +0x28 e1000g_m_tx+0x81>
e1000g_m_tx+0x59: movq 0x0(%r13),%r14
e1000g_m_tx+0x5d: xorq %r8,%r8
e1000g_m_tx+0x60: movq %r8,0x0(%r13)
e1000g_m_tx+0x64: movq %r15,%rdi
e1000g_m_tx+0x67: movq %r13,%rsi
e1000g_m_tx+0x6a: call +0x31 e1000g_send>
e1000g_m_tx+0x6f: testl %eax,%eax
e1000g_m_tx+0x71: je +0xa e1000g_m_tx+0x7d>
e1000g_m_tx+0x73: movq %r14,%r13
e1000g_m_tx+0x76: testq %r14,%r14
e1000g_m_tx+0x79: jne -0x22 e1000g_m_tx+0x59>
e1000g_m_tx+0x7b: jmp +0x4 e1000g_m_tx+0x81>
e1000g_m_tx+0x7d: movq %r14,0x0(%r13)
e1000g_m_tx+0x81: movq %r12,%rdi
e1000g_m_tx+0x84: call +0xb2ce4a7 rw_exit>
e1000g_m_tx+0x89: movq %r13,%rax
e1000g_m_tx+0x8c: popq %r15
e1000g_m_tx+0x8e: popq %r14
e1000g_m_tx+0x90: popq %r13
e1000g_m_tx+0x92: popq %r12
e1000g_m_tx+0x94: leave
e1000g_m_tx+0x95: ret
显然，e1000g_m_tx在调用e1000g_send时，已经执行过rw_enter了，而该线程却阻塞在cv_timedwait上，状态是sleep:
> fffffe80044e5c80::thread -i
ADDR STATE FLG PFLG SFLG PRI EPRI PIL INTR
fffffe80044e5c80 sleep 8 0 3 60 0 0 n/a
那么这个线程有可能被唤醒执行吗？如果可以的话，死锁就不应该发生。这就需要进一步检查这个线程的状态。
关于cv_timedwait
Kernel Functions for Drivers condvar(9F)
NAME
condvar, cv_init, cv_destroy, cv_wait, cv_signal,
cv_broadcast, cv_wait_sig, cv_timedwait, cv_timedwait_sig -
condition variable routines
SYNOPSIS
#include sys/ksynch.h>
..................................................
..................................................
..................................................
clock_t cv_timedwait(kcondvar_t *cvp, kmutex_t *mp, clock_t timeout);
clock_t cv_timedwait_sig(kcondvar_t *cvp, kmutex_t *mp, clock_t timeout);
timeout A time, in absolute ticks since boot, when
cv_timedwait() or cv_timedwait_sig() should
return.
可以看到，cv_timedwait的第3个参数就是就是时间参数，从前面的调用栈里，就可以找到，是1036d；
到了这个时间，cv_timedwait就应该返回，线程也就被唤醒；那么，时间到了吗？我们查看一下：
> fffffe80044e5c80::thread -d
ADDR DISPTIME BOUND PR
fffffe80044e5c80 1036c -1 0
> 1036d-1036c=D
1
> *lbolt=X
18a4f
> 18a4f-1036c=D
34531
可以看到，线程fffffe80044e5c80的DISPTIME是1036c，一个tick后就应该被唤醒，可是系统并没有被唤醒，在我们强制系统crashdump时，滴答值，即lbolt，已经累加到18a4f，也就是过了规定时间后的34531个tick，线程仍旧在sleep。
这就意味着，fffffe80044e5c80永远也不会被唤醒，那么其它4个阻塞在rwlock的线程也永远不会被唤醒；我们记得其中之一就是中断线程，那么e1000g驱动就永远不会相应网卡中断了。显然，这已经是bug了；
可是，为什么cv_timedwait没有按照手册上规定的行为工作呢？
感兴趣的话，就看内核源代码。
cv_timedwait调用realtime_timeout在内核的callout table注册一项，在指定的时间上注册执行setrun函数，该函数的参数就是调用cv_timedwait的线程，即当前内核线程的指针kthread_t:
http://src.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/uts/common/os/condvar.c#199
[/url]
/*
* Same as cv_wait except the thread will unblock at 'tim'
* (an absolute time) if it hasn't already unblocked.
*
* Returns the amount of time left from the original 'tim' value
* when it was unblocked.
*/
clock_t
cv_timedwait(kcondvar_t *cvp, kmutex_t *mp, clock_t tim)
{
kthread_t *t = curthread;
timeout_id_t id;
clock_t timeleft;
int signalled;
if (panicstr)
return (-1);
timeleft = tim - lbolt;
if (timeleft 0)
return (-1);
id = realtime_timeout((void (*)(void *))setrun, t, timeleft);
thread_lock(t); /* lock the thread */
cv_block((condvar_impl_t *)cvp);
thread_unlock_nopreempt(t);
mutex_exit(mp);
if ((tim - lbolt) 0) /* allow for wrap */
setrun(t);
swtch();
注册在callout table中的setrun函数会到期执行，就调用setrun_locked把当时的线程唤醒：
[url=http://src.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/uts/common/disp/thread.c#1161]
http://src.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/uts/common/disp/thread.c#1161
[/url]
void
setrun(kthread_t *t)
{
thread_lock(t);
setrun_locked(t);
thread_unlock(t);
}
对本例来说，就是把调用过cv_timedwait,处于sleep状态的线程唤醒：
[url=http://src.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/uts/common/disp/thread.c#1099]
http://src.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/uts/common/disp/thread.c#1099
[/url]
/*
* Set the thread running; arrange for it to be swapped in if necessary.
*/
void
setrun_locked(kthread_t *t)
{
ASSERT(THREAD_LOCK_HELD(t));
if (t->t_state == TS_SLEEP) {
/*
* Take off sleep queue.
*/
SOBJ_UNSLEEP(t->t_sobj_ops, t);
因此函数cv_timedwait的实现机制是依赖于Solaris内核callout队列机制，如果cv_timedwait没有按照手册上规定的行为工作，则很有可能是因为callout机制出了问题。
本文来自ChinaUnix博客，如果查看原文请点：
[url]http://blog.chinaunix.net/u/768/showart_256928.html
欢迎光临 Chinaunix (http://bbs.chinaunix.net/)
Powered by Discuz! X3.2