• 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, 15, 18f5c90, 0, eddc1190, 1343d4c

    00000000fedd3cd0 unix:sync_handler
    +138 (180c000, 01, 109e000, 11818800)
      
    %l0-3: 0000000001863d80 0000000001863c00 000000000000017f 000000000185a000
      
    %l4-70000000000000000 0000000001853400 0000000000000003 0000000001814400
    00000000fedd3da0 unix:vx_handler
    +80 (fad99478, 1822138029281822240, f0057d3d)
      
    %l0-30000000001822240 0000000000000000 0000000000000001 0000000000000001
      
    %l4-70000000001815000 00000000f0000000 0000000001000000 000000000101dde4
    00000000fedd3e50 unix:callback_handler
    +20 (fad99478, fff6a280, 0000)
      
    %l0-30000000000000016 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, 00)
      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, 00)
      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, 00)
      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, 00)
      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, 18004, 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(00, ffffffff82f76288, fffffffffbc05908, 00)
      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, 00)
      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 
    = [ 00xffffffffa40a95600xffffffffa40a96000xffffffffa40a97400xffffffffa40a98800xffffffffa40a9970
    0xffffffffa9383ce00xffffffffa40a9b500xffffffffa40a9c400xffffffffa40a9d300xffffffffa40a9e700xffffffffa409f068
    0xffffffffa409f1080xffffffffa409f2480xffffffffa409f3380xffffffffa409f4780xffffffffa409f5680xffffffffa409f6a8
    0xffffffffa409f7980xffffffffa409f8880xffffffffa9383c900xffffffffa409fa680xffffffffa1a2e8780xffffffffa409fb08
    0xffffffffacfbb4c80xffffffffa409fd380xffffffffa1a2eeb80xffffffffa40ba0080xffffffffa40ba1980xffffffffa40ba2d8
    0xffffffffa40ba3c80xffffffffa40ba4b8, ... ]
        ct_lbhash 
    = [ 00000xffffffffad188ca0000000000xffffffff8ff5a658000xffffffff8276e8780000
    00000000000xffffffffad1d0528, ... ]
    }

    非常的幸运,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

  • 相关阅读:
    ES6数组的扩展--Array.from()和Array.of()
    前端面试中的各种方法实现
    理解 JavaScript call()/apply()/bind()
    【前端面试】变量和类型计算
    Kubernetes1.3新特性:支持GPU
    撸了一个微信小程序项目
    微信开发(调用各种接口)
    Android 神兵利器之通过解析网页获取到的API数据合集,可拿来就用
    Kubernetes1.4正式发布
    Kubernetes1.4即将发布
  • 原文地址:https://www.cnblogs.com/ainima/p/6330807.html
Copyright © 2020-2023  润新知