MDB for STREAMS

OpenSolaris includes a very powerful and modular debugger MDB that is an invaluable tool for analyzing crash dumps and live systems. It comes with a comprehensive manual which is a great read. Here is a brief information for brave souls having to debug STREAMS-related issues.

Queues

The most useful MDB dcmd for most module and driver developers is ::queue. Typing ::help queue will show the full usage information:

NAME
  queue - filter and display STREAM queue

SYNOPSIS
  addr ::queue [-q|v] [-m mod] [-f flag] [-F flag] [-s syncq_addr]

DESCRIPTION
  
  Print queue information for a given queue pointer.
  
  Without the address of a "queue_t" structure given, print information about al
  l
  queues in the "queue_cache".
  
  Options:
        -v:             be verbose - print symbolic flags falues
        -q:             be quiet - print queue pointer only
        -f flag:        print only queues with flag set
        -F flag:        print only queues with flag NOT set
        -m modname:     print only queues with specified module name
        -s syncq_addr:  print only queues which use specified syncq
  
  Available conversions:
        q2rdq:          given a queue addr print read queue pointer
        q2wrq:          given a queue addr print write queue pointer
        q2otherq:       given a queue addr print other queue pointer
        q2syncq:        given a queue addr print syncq pointer (::help syncq)
        q2stream:       given a queue addr print its stream pointer
                (see ::help stream and ::help stdata)
  
  To walk q_next pointer of the queue use
        queue_addr::walk qnext

ATTRIBUTES

  Target: kvm
  Module: genunix
  Interface Stability: Unstable

If you just type ::queue, MDB will print information about all opened queue instances ¹ in the system. For example, on my desktop:

> ::queue
    ADDR MODULE         FLAGS NBLK
d0353008 fifostrrhead  044032    0 00000000
d0353180 ip            204032    0 00000000
d03532f8 consms        202032    0 00000000
d0353470 strrhead      044032    0 00000000
d03535e8 tcp           204032    0 00000000
d0353760 strrhead      044032    0 00000000
d03538d8 conskbd       20c032    0 00000000
d0353a50 wc            242032    0 00000000
d0353bc8 ip            204032    0 00000000
d0353d40 strrhead      044032    0 00000000
d033f010 usbms         002032    0 00000000
d033f188 hid           201032    0 00000000
d033f300 consms        242032    0 00000000
d033f478 rts           108832    0 00000000
 ...

What you see in the output is the actual read queue address for each open module or instance, the module name, queue flags, number of messages on the module queue and the pointer to the first message in the queue. You can translate hex flag values into symbolic names adding -v option:

> ::queue -v
    ADDR MODULE         FLAGS NBLK
d0353008 fifostrrhead  044032    0 00000000
                       |
                       +-->  QWANTR       Someone wants to read Q
                             QREADR       This is the reader (first) Q
                             QUSE         This queue in use (allocation)
                             QMTSAFE      stream module is MT-safe
                             QEND         last queue in stream
d0353180 ip            204032    0 00000000
                       |
                       +-->  QWANTR       Someone wants to read Q
                             QREADR       This is the reader (first) Q
                             QUSE         This queue in use (allocation)
                             QMTSAFE      stream module is MT-safe
                             QISDRV       the Queue is attached to a driver
 ...

You can ask about specific queue by providing its address for the ::queue command:

> d0353180::queue -v                  
    ADDR MODULE         FLAGS NBLK
d0353180 ip            204032    0 00000000
                       |
                       +-->  QWANTR       Someone wants to read Q
                             QREADR       This is the reader (first) Q
                             QUSE         This queue in use (allocation)
                             QMTSAFE      stream module is MT-safe
                             QISDRV       the Queue is attached to a driver

What if you want to find all open instances of a specific module? This is easy with the -m flag. For example, to find all open instances of IP you can type

> ::queue -m ip
d0353180
d0353bc8
d197e5f8
d2263020
  ...

Notice that when you use any of the filtering flags, the ::queuedcmd prints only the address of matching queues. You can still get more detailed information by pipelining the output to the ::queue dcmd:

> ::queue -m ip | ::queue
    ADDR MODULE         FLAGS NBLK
d0353180 ip            204032    0 00000000
d0353bc8 ip            204032    0 00000000
d197e5f8 ip            244032    0 00000000
d2263020 ip            204032    0 00000000
  ...

You can use filtering options to find all queues with specific flag value set:

> ::queue -f QISDRV|::queue
    ADDR MODULE         FLAGS NBLK
d0353180 ip            204032    0 00000000
d03532f8 consms        202032    0 00000000
d03535e8 tcp           204032    0 00000000
d03538d8 conskbd       20c032    0 00000000
d0353a50 wc            242032    0 00000000
  ...

prints information about all driver queues. What if you want information about modules and not drivers? Easy:

> ::queue -F QISDRV|::queue
    ADDR MODULE         FLAGS NBLK
d0353008 fifostrrhead  044032    0 00000000
d0353470 strrhead      044032    0 00000000
d0353760 strrhead      044032    0 00000000
d0353d40 strrhead      044032    0 00000000
d033f010 usbms         002032    0 00000000
d033f478 rts           108832    0 00000000
  ...

Similarly you can find all queues which are flow controlled. Here is an example from a real core dump:

> ::queue -f QFULL|::queue
            ADDR MODULE         FLAGS NBLK
ffffffff83e9d000 strrhead      04403c   64 ffffffff953c0600
ffffffff82548018 strrhead      04403c  331 ffffffff949c2680
ffffffff85f4ba48 timod         00083c    7 ffffffffbfa04140
ffffffff83acf2e8 timod         00083c    3 ffffffff84659f00

Careful reader will notice that this will print information only about flow controlled read side queues. How about write side queues? Here comes a useful little ::q2wrq dcmd:

> ::queue -q | ::q2wrq | ::queue -f QFULL|::queue -v
            ADDR MODULE         FLAGS NBLK
ffffffff83cb0388 tl            24402c  205 fffffe80e3017040
                               |
                               +-->  QWANTW       Someone wants to write Q
                                     QFULL        Q is considered full
                                     QUSE         This queue in use (allocation)
                                     QMTSAFE      stream module is MT-safe
                                     QEND         last queue in stream
                                     QISDRV       the Queue is attached to a driver

The ::q2wrq dcmd simply maps the read queue pointer to the write queue pointer. The ::q2rdq performs the opposite mapping and the ::q2otherq dcmd maps read queue pointer to the write queue pointer and visa versa.

Stream Heads

Once you are comfortable dealing with individual queues you may wonder about the state of a whole open STREAM. The simplest way to find a stream containing a given queue is to apply a ::q2stream dcmd which maps a queue pointer to the stream head pointer. You can use a nice ::stream dcmd to display the whole stream graphically:

> ffffffff83acf2e8::q2stream|::stream

+-----------------------+-----------------------+
| 0xffffffff82548110    | 0xffffffff82548018    | 
| strwhead              | strrhead              | 
|                       |                       |
| cnt = 0t0             | cnt = 0t57420         | 
| flg = 0x00004022      | flg = 0x0004403c      | 
+-----------------------+-----------------------+
            |                       ^
            v                       |
+-----------------------+-----------------------+
| 0xffffffff83acf3e0    | 0xffffffff83acf2e8    | 
| timod                 | timod                 | 
|                       |                       |
| cnt = 0t0             | cnt = 0t528           | 
| flg = 0x00000822      | flg = 0x0000083c      | 
+-----------------------+-----------------------+
            |                       ^
            v                       |
+-----------------------+-----------------------+
| 0xffffffff83acf670    | 0xffffffff83acf578    | 
| udp                   | udp                   | 
|                       |                       |
| cnt = 0t0             | cnt = 0t0             | 
| flg = 0x00000822      | flg = 0x00000832      | 
+-----------------------+-----------------------+
            |                       ^
            v                       |
+-----------------------+-----------------------+
| 0xffffffff82a86128    | 0xffffffff82a86030    | 
| ip                    | ip                    | 
|                       |                       |
| cnt = 0t0             | cnt = 0t0             | 
| flg = 0x00244022      | flg = 0x00204032      | 
+-----------------------+-----------------------+

You can see all read and write queues of the stream and their state. The read side stream head is not very happy - it has 57420 bytes hanging around and blocking another 528 bytes in timod.

>p> Another way to look at the stream is to walk the read or write side using the qnext walker:

> 0xffffffff82548110::walk qnext|::queue 
            ADDR MODULE         FLAGS NBLK
ffffffff82548110 strwhead      004022    0 0000000000000000
ffffffff83acf3e0 timod         000822    0 0000000000000000
ffffffff83acf670 udp           000822    0 0000000000000000
ffffffff82a86128 ip            244022    0 0000000000000000

> 0xffffffff82a86030::walk qnext|::queue 
            ADDR MODULE         FLAGS NBLK
ffffffff82a86030 ip            204032    0 0000000000000000
ffffffff83acf578 udp           000832    0 0000000000000000
ffffffff83acf2e8 timod         00083c    3 ffffffff84659f00
ffffffff82548018 strrhead      04403c  331 ffffffff949c2680

A careful reader will notice that the ::stream dcmd displays how many bytes bytes are in the queue while ::queue displays ho many messages are there. Do we want to know what are these messages? here comes the next useful dcmd.

Messages

Let me introduce a new player - the ::mblk dcmd. Typing ::help mblk will show you all the gory details:

NAME
  mblk - print an mblk

SYNOPSIS
  addr ::mblk [-q|v] [-f|F flag] [-t|T type] [-l|L|B len] [-d dbaddr]

DESCRIPTION
  
  Print mblock information for a given mblk pointer.
  Without the address, print information about all mblocks.
  
  Fields printed:
        ADDR:   mblk address
        FL:     Flags
        TYPE:   Type of corresponding dblock
        LEN:    Data length as b_wptr - b_rptr
        BLEN:   Dblock space as db_lim - db_base
        RPTR:   Read pointer
        DBLK:   Dblock pointer
  
  Options:
        -v:             be verbose - print symbolic flags falues
        -q:             be quiet - print mblk pointer only
        -d dbaddr:      print mblks with specified dblk address
        -f flag:        print only mblks with flag set
        -F flag:        print only mblks with flag NOT set
        -t type:        print only mblks of specified db_type
        -T type:        print only mblks other then the specified db_type
        -l len:         tprint only mblks with MBLKL == len
        -L len:         print only mblks with MBLKL <= len 
        -G len:         print only mblks with MBLKL >= len 
        -b len:         print only mblks with db_lim - db_base == len
  

ATTRIBUTES

  Target: kvm
  Module: genunix
  Interface Stability: Unstable

It is easy to look at a specific message:

> ffffffff949c2680::mblk
            ADDR FL TYPE    LEN   BLEN              RPTR             DBLK
ffffffff949c2680 0  proto   56    80    ffffffff88f145b0 ffffffff88f14540

This output shows us that this is an M_PROTO message with 56 bytes of information starting at address ffffffff88f145b0². We know that messages like to hang out together. How do we print the whole b_cont chain? Like this:

> ffffffff949c2680::walk b_cont|::mblk
            ADDR FL TYPE    LEN   BLEN              RPTR             DBLK
ffffffff949c2680 0  proto   56    80    ffffffff88f145b0 ffffffff88f14540
ffffffff943b5240 0  data    108   144   ffffffff9868878c ffffffff98688700

Now we can see both the M_PROTO and the attached M_DATA messages, and we can see that UDP is sending 108 bytes of data upstream. Similarly, the b_next walker will follow the b_next chain:

> ffffffff84659f00::walk b_next|::mblk
            ADDR FL TYPE    LEN   BLEN              RPTR             DBLK
ffffffff84659f00 0  proto   56    80    ffffffff94257c70 ffffffff94257c00
fffffe80e3078340 0  proto   56    80    ffffffff94257bb0 ffffffff94257b40
ffffffff84658a40 0  proto   56    80    ffffffff942575b0 ffffffff94257540

And, of course, we can combine both in the pipeline:

> ffffffff84659f00::walk b_next|::walk b_cont|::mblk
            ADDR FL TYPE    LEN   BLEN              RPTR             DBLK
ffffffff84659f00 0  proto   56    80    ffffffff94257c70 ffffffff94257c00
ffffffff84659300 0  data    120   208   ffffffff82fc144c ffffffff82fc13c0
fffffe80e3078340 0  proto   56    80    ffffffff94257bb0 ffffffff94257b40
ffffffff846599c0 0  data    120   208   ffffffff8465120c ffffffff84651180
ffffffff84658a40 0  proto   56    80    ffffffff942575b0 ffffffff94257540
ffffffff84658b00 0  data    120   208   ffffffff84651d4c ffffffff84651cc0

If you are really curious, you can see all allocated messages by simply typing ::mblk:

> ::mblk
    ADDR FL TYPE    LEN   BLEN      RPTR     DBLK
d6d0e000 0  proto   24    64    cfedaf00 cfedaec0
d6d0e020 0  data    0     8192  d377d400 d23d7c00
d6d0e040 0  data    3     64    dc14d580 dc14d540
d6d0e060 0  proto   156   320   cfedbd00 cfedbcc0
d6d0e080 0  data    0     64    d366a9c4 d366a980
d6d0e0a0 0  data    80    320   cfedbe80 cfedbe40
d6d0e0c0 0  proto   24    64    cfe5e0c0 cfe5e080
d6d0e0e0 0  data    115   320   cfe490e7 cfe49080

As with the ::queue command you can filter by the message type. For example, you can look at M_DATA messages³ only:

> ::mblk -t M_DATA|::mblk
    ADDR FL TYPE    LEN   BLEN      RPTR     DBLK
d6d0e020 0  data    0     8192  d377d400 d23d7c00
d6d0e040 0  data    16    64    dc14d580 dc14d540
d6d0e080 0  data    0     64    d366a9c4 d366a980
d6d0e0a0 0  data    80    320   cfedbe80 cfedbe40
d6d0e0e0 0  data    115   320   cfe490e7 cfe49080
d6d0e140 0  data    0     64    d77c7480 d77c7440

Or you can find all 0-bytes messages:

> ::mblk -l 0|::mblk
    ADDR FL TYPE    LEN   BLEN      RPTR     DBLK
d6d0e020 0  data    0     8192  d377d400 d23d7c00
d6d0e040 0  data    0     64    dc1ab714 dc1ab6c0
d6d0e080 0  data    0     64    d366a9c4 d366a980
d6d0e140 0  data    0     64    d77c7480 d77c7440
...

In my opinion these example shows why MDB is really cool for kernel debugging. It can present huge amount of information in an informative way. Want to know how many 1-byte messages are floating around your system?

> ::mblk -l 0t1 ! wc -l 
      51

Conclusions

We flexed just a small muscle of the MDB and we already can go a long way in debugging complicated STREAMS issues in the kernel. We can study individual queues, STREAMS, messages, or get a bird's eye view and look at the picture from some distance. Whenever you encounter a difficult debugging problem MDB is your friend (if you know how to talk to it politely).

---

Footnotes:

¹The ::queue command will print all read queues.

²The UDP module talks a protocol called TPI, so the M_PROTO message is one of the TPI primitives. The first part of the primitive is always its ID, we can get this by typing

> ffffffff88f145b0/D                      
0xffffffff88f145b0:             20              

Looking at usr/src/uts/common/sys/tihdr.h we see that this is the T_UNITDATA_IND message (makes sense). We can print the whole message now:

> ffffffff88f145b0::print 'struct T_unitdata_ind'
{
    PRIM_type = 0x14
    SRC_length = 0x10
    SRC_offset = 0x14
    OPT_length = 0x14
    OPT_offset = 0x24
}

³ Underground hackers special:

> ::mblk -t M_DATA|::print mblk_t b_rptr|/s
Jun 15 09:57:16 lpr[13390]: [ID 575460 FACILITY_AND_PRIORITY] net_response(18)
NOTICE: NFS4 FACT SHEET: 
 Action: NR_CLIENTID 
 NFS4 error: NFS4ERR_STALE_CLIENTID 
 Suspected server reboot.   
Jun 15 09:57:16 lpr[13390]: [ID 626751 FACILITY_AND_PRIORITY] net_write(18, 0x8045478, 12)
NOTICE: [NFS4][Server: onnv.sfbay][Mntpt: /ws/onnv-gate/usr]NFS server onnv.sfbay not responding; still trying
·gp0Jun 15 09:57:16 lpr[13390]: [ID 458697 FACILITY_AND_PRIORITY] net_open(bulka.SFBay, 5)
NOTICE: [NFS4][Server: onnv.sfbay][Mntpt: /ws/onnv-gate/usr]NFS server onnv.sfbay ok
...

Prints the content of all the data messages. I can see eyes flashing in the darkness!

---

Technorati Tag: Solaris
Technorati Tag: OpenSolaris
Technorati Tag: MDB
Technorati Tag: STREAMS

( Jun 15 2005, 12:29:08 PM PDT ) Permalink Comments [0]