Solaris学习笔记(6)

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: 8005003b < pg,wp,ne,et,ts,mp,pe > cr4: 6f0 < xmme,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

/*
* 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把当时的线程唤醒：

http://src.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/uts/common/disp/thread.c#1161

void
setrun(kthread_t * t)
{
thread_lock(t);
setrun_locked(t);
thread_unlock(t);
}

对本例来说，就是把调用过cv_timedwait,处于sleep状态的线程唤醒：

http://src.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/uts/common/disp/thread.c#1099

/*
* 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机制出了问题。

关于callout队列

那么，系统callout机制是否工作正常呢？

首先看调用cv_timedwait不能超时返回的线程：

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 ()

检查系统全局的callout队列，正如我们之前发现的，这个线程对应的callout表项已经严重过期了：

> ::callout ! grep fffffe80044e5c80
setrun fffffe80044e5c80 3ffffffffffe1a80 1036d (T - 33730 )

其中T-33730表示已经过期了33730个tick。

用mdb打印出所有callout表项，我们发现，系统中有过期的表项还有很多，用wc算一下，有2573个。

> ::callout
FUNCTION ARGUMENT ID TIME
sigalarm2proc ffffffff9569aae0 7fffffffffffc010
144a1 (T - 17038 )
sigalarm2proc ffffffff91bb7510 7fffffffffffe010
14484 (T - 17067 )
sigalarm2proc ffffffff9569c380 7fffffffffffc020
144a1 (T - 17038 )
sigalarm2proc ffffffff95428d48 7fffffffffffc030
144a1 (T - 17038 )
sigalarm2proc ffffffff91bb8db0 7fffffffffffe030
14483 (T - 17068 )
sigalarm2proc ffffffff9542b238 7fffffffffffc040
144a1 (T - 17038 )
.....................[snipped].................................... ................................

> ::callout ! grep " T- " | wc - l
2573

看来callout机制似乎失灵了，这也是导致cv_timedwait的不工作的直接原因。

下面我们就看一下callout到底出了什么问题。这还得从callout的代码开始看起。

首先，系统在每个tick执行时钟中断处理时进入clock例程，这个例程会调用callout_schedule来处理全局的callout队列：

http://src.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/uts/common/os/clock.c#692

static void
clock( void )
{
..........................
..........................
..........................

/*
* Schedule timeout() requests if any are due at this time.
*/
callout_schedule();

在callout_schedule里，会循环遍历所有调出表，把调出表的入口传递给callout_schedule_1：

/*
* Schedule callouts for all callout tables. Called by clock() on each tick.
*/

void
callout_schedule( void )
{
int f, t;

if (cpr_stop_callout)
return ;

for (t = 0 ; t < CALLOUT_NTYPES; t ++ )
for (f = 0 ; f < callout_fanout; f ++ )
callout_schedule_1(callout_table[CALLOUT_TABLE(t, f)]);
}

而在callout_schedule_1会遍历给定调出表中的调出项，选择用两种不同的方式执行callout_execute。

http://src.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/uts/common/os/callout.c#295

/*
* Schedule any callouts that are due on or before this tick.
*/
static void
callout_schedule_1(callout_table_t * ct)
{
callout_t * cp;
clock_t curtime, runtime;

mutex_enter( & ct -> ct_lock);
ct -> ct_curtime = curtime = lbolt;
while (((runtime = ct -> ct_runtime) - curtime) <= 0 ) {
for (cp = ct -> ct_lbhash[CALLOUT_LBHASH(runtime)];
cp != NULL; cp = cp -> c_lbnext) {
if (cp -> c_runtime != runtime ||
(cp -> c_xid & CALLOUT_EXECUTING))
continue ;
mutex_exit( & ct -> ct_lock);
if (ct -> ct_taskq == NULL)
softcall(( void ( * )( void * ))callout_execute, ct);
else
( void ) taskq_dispatch(ct -> ct_taskq,
(task_func_t * )callout_execute, ct,
KM_NOSLEEP);
return ;
}
ct -> ct_runtime ++ ;
}
mutex_exit( & ct -> ct_lock);
}

总结下来callout队列的执行通常是经过如下code path:

1. softcall

clock -> callout_schedule -> callout_schedule_1 ->通过softcall产生一个PIL为1的软中断执行callout_execute

2. taskq

clock -> callout_schedule -> callout_schedule_1 ->通过dipatch一个独立的taskq线程来执行callout_execute

下面看看callout_execute的实现：

http: // src.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/uts/common/os/callout.c#241

/*
* Do the actual work of executing callouts. This routine is called either
* by a taskq_thread (normal case), or by softcall (realtime case).
*/
static void
callout_execute(callout_table_t * ct)
{
callout_t * cp;
callout_id_t xid;
clock_t runtime;
timestruc_t now;
int64_t hresms;

mutex_enter( & ct -> ct_lock);
....[snipped]..............
cp -> c_executor = curthread;
cp -> c_xid = xid |= CALLOUT_EXECUTING;
mutex_exit( & ct -> ct_lock);
DTRACE_PROBE1(callout__start, callout_t * , cp);
( * cp -> c_func)(cp -> c_arg);
DTRACE_PROBE1(callout__end, callout_t * , cp);
mutex_enter( & ct -> ct_lock);
....[snipped]..............
mutex_exit( & ct -> ct_lock);
}

我们看到，在callout_execute执行中会用到mutex_enter(&ct->ct_lock)来保证互斥访问 callout表项的内容，但在执行真正的定时器函数时，它会调用mutex_exit(&ct->ct_lock)释放掉锁。因此，可以有多个taskq线程或者软中断并发执行调出函数，而不会相互影响。

此前，我没仔细看callout_execute的代码，犯了一个严重错误，幸好有朋友指出，在这里再次表示谢意。希望之前的错误没有误导大家。

回过头来看线程fffffe80000ddc80的调用栈，显然它是由e1000g驱动调用timeout(9F)注册的e1000g_LocalTimer函数，而且callout_execute是由单独的taskq线程执行的：

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 ()

这个线程执行过程中，又因为等待一个读写锁而睡眠，我们前面分析出这个锁的所有者是fffffe80044e5c80，它因为调用cv_timedwait而睡眠等待它被callout机制来唤醒：

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 ()

而cv_timedwait是通过realtime_timeout注册callout表项的，这意味着，callout_execute要通过softcall机制来执行，进而调用到setrun函数唤醒该线程。

而我们已经知道，fffffe80044e5c80调用cv_timedwait后从未返回，而且已经严重过期：

> ::callout ! grep fffffe80044e5c80
setrun fffffe80044e5c80 3ffffffffffe1a80 1036d (T - 33730 )

那么，为什么会这样呢？很自然，我们需要了解softcall是如何实现的。

关于softcall

http://cvs.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/uts/common/os/softint.c#103

/*
* Call function func with argument arg
* at some later time at software interrupt priority
*/
void
softcall( void ( * func)( void * ), void * arg)
{
softcall_t * sc;

/*
* protect against cross-calls
*/
mutex_enter( & softcall_lock);
/* coalesce identical softcalls */
for (sc = softhead; sc != 0 ; sc = sc -> sc_next) {
if (sc -> sc_func == func && sc -> sc_arg == arg) {
mutex_exit( & softcall_lock);
return ;
}
}

if ((sc = softfree) == 0 )
panic( " too many softcalls " );
softfree = sc -> sc_next;
sc -> sc_func = func;
sc -> sc_arg = arg;
sc -> sc_next = 0 ;

if (softhead) {
softtail -> sc_next = sc;
softtail = sc;
mutex_exit( & softcall_lock);
} else {
softhead = softtail = sc;
if (softcall_state == SOFT_DRAIN)
/*
* softint is already running; no need to
* raise a siron. Due to lock protection of
* softhead / softcall state, we know
* that softint() will see the new addition to
* the softhead queue.
*/
mutex_exit( & softcall_lock);
else {
softcall_state = SOFT_PEND;
mutex_exit( & softcall_lock);
siron();
}
}
}

可以看到，softcall会把需要执行的函数放入一个内核全局的队列并交由系统处理，softhead指针可以访问这个队列：

http://cvs.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/uts/common/os/softint.c#73

static softcall_t softcalls[NSOFTCALLS], * softhead, * softtail, * softfree;

从源代码里，我们看到，全局变量softcall_state用来标识当前softcall队列的状态，首次排队时，队列状态会被置为待处理态，SOFT_PEND。然后调用一个siron()来在CPU上产生一个软中断。

其中，softcall_state的状态定义如下：

http://cvs.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/uts/common/os/softint.c#60

/*
* Defined states for softcall processing.
*/
#define SOFT_IDLE 0x01 /* no processing is needed */
#define SOFT_PEND 0x02 /* softcall list needs processing */
#define SOFT_DRAIN 0x04 /* the list is being processed */

下面我们就用mdb遍历这个队列，发现队列中有2个待执行的callout_execute调用：

>* softhead::list softcall_t sc_next | ::print softcall_t
{
sc_func = callout_execute
sc_arg = 0xffffffff80219000
sc_next = softcalls + 0x1290
}
{
sc_func = callout_execute
sc_arg = 0xffffffff80216000
sc_next = 0
}

> softcall_state / J
softcall_state:
softcall_state: 2

mdb读出当时队列状态是0x2，就是SOFT_PEND，待处理状态。

那么我们阻塞在cv_timedwait上的线程fffffe80044e5c80，是否属于这两个待处理的callout_execute之一呢？

sc_arg是callout_execute的参数，类型是callout_table_t，我们用mdb查看一下：

> 0xffffffff80219000 ::print callout_table_t
{
ct_lock = {
_opaque = [ 0 ]
}
ct_freelist = 0xffffffffad201c38
ct_curtime = 0x1872f
ct_runtime = 0x1036d
ct_taskq = 0
ct_short_id = 0x3ffffffffffe1a80
ct_long_id = 0x7ffffffffffd91a0
ct_idhash = [ 0 , 0xffffffffa40a9560 , 0xffffffffa40a9600 , 0xffffffffa40a9740 , 0xffffffffa40a9880 , 0xffffffffa40a9970 ,
0xffffffffa9383ce0 , 0xffffffffa40a9b50 , 0xffffffffa40a9c40 , 0xffffffffa40a9d30 , 0xffffffffa40a9e70 , 0xffffffffa409f068 ,
0xffffffffa409f108 , 0xffffffffa409f248 , 0xffffffffa409f338 , 0xffffffffa409f478 , 0xffffffffa409f568 , 0xffffffffa409f6a8 ,
0xffffffffa409f798 , 0xffffffffa409f888 , 0xffffffffa9383c90 , 0xffffffffa409fa68 , 0xffffffffa1a2e878 , 0xffffffffa409fb08 ,
0xffffffffacfbb4c8 , 0xffffffffa409fd38 , 0xffffffffa1a2eeb8 , 0xffffffffa40ba008 , 0xffffffffa40ba198 , 0xffffffffa40ba2d8 ,
0xffffffffa40ba3c8 , 0xffffffffa40ba4b8 , ... ]
ct_lbhash = [ 0 , 0 , 0 , 0 , 0xffffffffad188ca0 , 0 , 0 , 0 , 0 , 0 , 0 , 0 , 0 , 0xffffffff8ff5a658 , 0 , 0 , 0xffffffff8276e878 , 0 , 0 , 0 , 0 ,
0 , 0 , 0 , 0 , 0 , 0 , 0 , 0 , 0 , 0 , 0xffffffffad1d0528 , ... ]
}

非常的幸运，ct_short_id链表里的第一个项就是我们cv_timedwait注册的那个setrun的表项，我们不用再遍历整个链表了:)

> ::callout ! grep fffffe80044e5c80
setrun fffffe80044e5c80 3ffffffffffe1a80 1036d (T - 33730 )

看来，cv_timedwait没有按照预想原因返回的根源我们找到了，是softcall队列严重推迟引起的，而且，看起来softcall队列永远不可能继续被处理了。

那么为什么会这样呢？很自然我们想到要查看CPU的状态，因为softcall队列是软中断处理的，软中断线程的PIL一般是1，比一般线程的优先级都要高，除非CPU上有其它中断，否则应该会立即得到处理。

> ::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， CPU1是空闲的，而CPU0的BSPL是6，意味着6以下的中断都不能打断当前执行的线程，而这个BSPL正是网卡中断线程设置的，用来屏蔽低优先级中断。

因为我们的softcall队列保持了相当长的PEND状态，那就意味着似乎这些待处理的softcall被分配到CPU0上来执行。

是不是这样呢？我们可以用mdb检查CPU结构cpu_t中成员machcpu的状态，即可知到softcall被分配到了哪一个CPU上:

CPU0:

> fffffffffbc27d10::print struct machcpu mcpu_softinfo
{
mcpu_softinfo.st_pending = 0x416
}

CPU 1 :

> fffffffffbc2f840::print struct machcpu mcpu_softinfo
{
mcpu_softinfo.st_pending = 0x404
}

可以看到，CPU0上有PIL 1,2,4,10的中断待处理。CPU1有4和10待处理。其中PIL为1的中断就是处理softcall队列的软中断。
如果用mdb查看，该软中断处理函数是softlevel1，PIL是1：

> ::softint
ADDR PEND PIL ARG1 ARG2 ISR(s)
ffffffff8277a5c0 0 1 ffffffff8048da80 0 errorq_intr
fffffffffbc05ae8 0 1 0 0 softlevel1
ffffffff8277a4c0 0 2 ffffffff8048dd00 0 errorq_intr
fffffffffbc00070 0 2 0 0 cbe_low_level
ffffffff83a706c0 0 4 ffffffff90004d18 0 ghd_doneq_process
ffffffff8ed31880 0 4 ffffffff90004d18 0 ghd_timeout_softintr
ffffffff83946e00 0 4 ffffffff8f046c40 0 power_soft_intr
ffffffff83a70c00 0 4 ffffffff83b1b000 0 bge_chip_factotum
ffffffff83a70cc0 0 4 ffffffff83b1b000 0 bge_reschedule
ffffffff8277a2c0 0 4 0 0 asysoftintr
ffffffff82f4d100 0 9 ffffffff82f76370 0 e1000g_tx_softint_worker
ffffffff82f4df00 0 9 ffffffff82f86370 0 e1000g_tx_softint_worker
ffffffff833b3e80 0 9 ffffffff801af7e8 0 hcdi_soft_intr
ffffffff8277a000 0 9 ffffffff801afb68 0 hcdi_soft_intr
fffffffffbc00030 0 10 0 0 cbe_softclock

但实际上我们前面也知道，CPU0上的网卡中断线程fffffe80000b9c80已经睡眠在了读写锁上，而读写锁的主人fffffe80044e5c80，此刻却在callout队列中等待被唤醒来继续执行。
而callout的执行又依赖于CPU0能够处理softcall队列中callout_execute，但CPU0上的软中断已经被网卡中断线程fffffe80000b9c80通过BSPL屏蔽掉了。
此时，死锁已经发生，线程fffffe80000b9c80和fffffe80044e5c80永远的互相等待下去了。

当然，上述死锁条件的成立还得基于以下假设：

softcall一旦被分派，就不能重新调度到其它CPU上。本例中，即使CPU1空闲，也不能通过cross-call，或者叫处理器间中断来重新分配softcall队列的处理。

显然，这个假设似乎不合道理，如果真是这样的话，那可是内核的bug，我们的分析再次陷入困境。

因此，只好发邮件给OpenSolaris.org社区的code邮件列表了，终于，这个假设得到了确认，因为内核中这两个bug，我们的假设是成立的：

http://www.opensolaris.org/jive/thread.jspa?threadID=38081&tstart=30

http://www.opensolaris.org/jive/thread.jspa?threadID=38118&tstart=30

6292092 callout should not be blocked by interrupts from executing realtime timeouts
6540436 kpreempt() needs a more reliable way to generate level1 intr

如果上面两个内核的bug被修复，死锁还会发生吗？

答案不难得出：如果是SMP系统，大概不会发生了。但UP系统，单CPU，即便没有了上面两个bug，系统一样会死锁。

所以，这个死锁到底还是e1000g驱动的问题。好在这只是e1000g试验版本的一个错误，显然，我们在中断处理函数中引入读写锁是有问题的。

小结

1. 系统hang的root cause是e1000g的rwlock的不当使用，导致死锁的发生；

2. 关于callout

e1000g_LocalTimer显然是e1000g注册的定时器函数，但在这个函数中却试图使用一个rwlock，而导致了在 callout_execute调用中的睡眠。而我们知道，callout_execute睡眠会引起系统全局的callout table被锁住，callout机制无法使用；因此要避免在e1000g_LocalTimer中调用引起阻塞的代码或者函数；

3. Solaris Internal第二版的bug：

解决这个问题的事后，偶然发现Solaris Internal第二版的英文原版836页第17章图17.6存在一个bug。

这个图是关于rwlock的，其中关于读锁的图中，关于读者记数器的起始位，应该是3-31.63，而书上说是4。

这个可以从源代码中得到证实：
http://src.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/uts/common/os/rwlock.c#40

/*
* Big Theory Statement for readers/writer locking primitives.
*
* An rwlock provides exclusive access to a single thread ("writer") or
* concurrent access to multiple threads ("readers"). See rwlock(9F)
* for a full description of the interfaces and programming model.
* The rest of this comment describes the implementation.
*
* An rwlock is a single word with the following structure:
*
* ---------------------------------------------------------------------
* | OWNER (writer) or HOLD COUNT (readers) | WRLOCK | WRWANT | WAIT |
* ---------------------------------------------------------------------
* 63 / 31 .. 3 2 1 0

这我也从crashdump中得到了验证，检查读写锁实际的值，你会发现，是0xb, 其中第3位恰好是1，即只有1个reader。

> ffffffff82f76288::rwlock
ADDR OWNER/COUNT FLAGS WAITERS
ffffffff82f76288 READERS=1 B011 ffffffff838470c0 (W)
|| fffffe800027bc80 (R)
WRITE_WANTED -------+| fffffe80000ddc80 (R)
HAS_WAITERS --------+ fffffe80000b9c80 (R)
>
> ffffffff82f76288/J
0xffffffff82f76288: b
> ffffffff82f76288/R
0xffffffff82f76288: 1011