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  " <unknown> "  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  - / 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 
* =  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

相关文档:

Solaris学习笔记(5)
Solaris学习笔记(4)
Solaris学习笔记(3)
Solaris学习笔记(2)
Solaris学习笔记(1)
X86汇编语言学习手记(3)

X86汇编语言学习手记(2)
X86汇编语言学习手记(1)


Technorati Tag: OpenSolaris
Technorati Tag: Solaris

评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值