DTrace Case Study for Developers

By Jay Danielsen, October 14, 2004  


This case study focuses on leveraging the DTrace capability for device driver development. DTrace is a feature of the Solaris 10 Operating System, which is available as the Solaris Express release.

Historically, debugging a device driver required that a developer use function calls like cmn_err() to log diagnostic information to the /var/adm/messages file. This cumbersome process requires guesswork, re-compilation, and system reboots to uncover software coding errors. Developers with a talent for assembly language can use adb and create custom modules in C for mdb to diagnose software errors. Bottom line, historical approaches to kernel development and debugging are quite time-consuming.

DTrace provides a diagnostic short-cut. Instead of sifting through the /var/adm/messages file or pages of truss output, DTrace can be used to capture information on only the events that you as a developer wish to view. The magnitude of the benefit provided by DTrace can best be provided through a few simple examples. I'll share a few experiences in diagnosing a device driver that fails to load. The following example is a work in progress.

 
Example 1: Porting the smbfs Driver From Linux to the Solaris OS

First step: I created an smbfs driver template based on Sun's nfs driver. Once the driver compiles successfully, I want to test that the driver can be loaded and unloaded successfully.

I first copy my prototype driver to /usr/kernel/fs and attempt to modload it by hand:

# modload /usr/kernel/fs/smbfs
    can't load module: Out of memory or no room in system tables

And the /var/adm/messages file contains:

    genunix: [ID 104096 kern.warning] WARNING: system call missing
    from bind file

I'm new to this, so these messages are a bit cryptic to me. How can DTrace help me here?

Searching for the system call missing message, I find it in the function mod_getsysent() in the file modconf.c, on a failed call to mod_getsysnum.

Instead of manually searching the flow of mod_getsysnum() from source file to source file, here's a simple DTrace script to enable all entry and return events in the fbt (Function Boundary Tracing) provider once mod_getsynum() is entered.

    #!/usr/sbin/dtrace -s

    #pragma D option flowindent

    fbt::mod_getsysnum:entry
    /execname == "modload"/
    {
        self->follow = 1;
    }

    fbt::mod_getsysnum:return
    {
        self->follow = 0;
        trace(arg1);
    }

    fbt:::entry
    /self->follow/
    {
    }
    
    fbt:::return
    /self->follow/
    {
        trace(arg1);
    }


(Note: trace(arg1) displays the function's return value.)

Executing this script and running the modload command in another window produces the following output:

    # ./mod_getsysnum.d
    dtrace: script './mod_getsysnum.d' matched 35750 probes


    CPU FUNCTION
      0  -> mod_getsysnum
      0    -> find_mbind
      0     -> nm_hash
      0     <- nm_hash                                          41
      0     -> strcmp
      0     <- strcmp                                   4294967295
      0     -> strcmp
      0     <- strcmp                                            7
      0    <- find_mbind                                          0
      0  <- mod_getsysnum                                4294967295


Thus either find_mbind() returning '0', or nm_hash() returning '41' is the culprit. A quick look at find_mbind() reveals that a return value of 0 indicates an error state.

Viewing the source to find_mbind() in /usr/src/uts/common/os/modsubr.c, I see that we're searching for a char string in a hash table. Let's use DTrace to display the contents of the search string and hash table.

To view the contents of the search string we add a strcmp() trace to our previous mod_getsysnum.d script:

    fbt::strcmp:entry
    {
        printf("name:%s, hash:%s", stringof(arg0),
            stringof(arg1));
    }

Here are the results of our next attempt to load our driver:

    
    # ./mod_getsysnum.d    
    dtrace: script './mod_getsysnum.d' matched 35751 probes
    CPU FUNCTION
      0  -> mod_getsysnum
      0    -> find_mbind
      0     -> nm_hash
      0     <- nm_hash                                          41
      0     -> strcmp
      0      | strcmp:entry            name:smbfs,
                        hash:timer_getoverrun
      0     <- strcmp                                   4294967295
      0     -> strcmp
      0      | strcmp:entry            name:smbfs, 
                        hash:lwp_sema_post
      0     <- strcmp                                            7
      0    <- find_mbind                                          0
      0  <- mod_getsysnum                                4294967295


So we're looking for smbfs in a hash table, and it's not present. How does smbfs get into this hash table?

Let's return to find_mbind() and observe that the hash table variable sb_hashtab is passed to the failing nm_hash() function. A quick search of the source code reveals that sb_hashtab is initialized with a call to read_binding_file(), which takes as its arguments a config file, the hash table, and a function pointer. A few more clicks on our source code browser reveal the contents of the config file to be defined as /etc/name_to_sysnum in the file /usr/src/uts/common/os/modctl.c.

Looks like I forgot to include a configuration entry for my driver. I add the following to the /etc/name_to_sysnum file and reboot.

    'smbfs            177'
    (read_binding_file() is read once at boot time.)

After rebooting the driver can be loaded successfully.

    # modload /usr/kernel/fs/smbfs

Success! Verify that the driver is loaded with the modinfo command:

    # modinfo | grep smbfs
    160 feb21a58  351ac 177      1  smbfs (SMBFS syscall, client, and comm)
    160 feb21a58  351ac  24      1  smbfs (network filesystem)
    160 feb21a58  351ac  25      1  smbfs (network filesystem version 2)
    160 feb21a58  351ac  26      1  smbfs (network filesystem version 3)

(Recall that I based this driver on an nfs template, which explains this output.)

 
Example 2: Unloading the Module

Let's make sure we can also unload the module.


    # modinfo | grep smbfs
    # modunload -i 160
    can't unload the module: Device busy

This is most likely due to an EBUSY errno return value.

But now, since the smbfs driver is a loaded module, I have access to all of the smbfs functions:

    # dtrace -l fbt:smbfs:: | wc -l
    1002

This is amazing to me! Without any special coding, I now have access to 1002 entry and return events contained in my driver. These 1002 function handles allow me to debug my work without a special 'instrumented code' version of my driver!

Let's monitor all smbfs calls when modunload is called, using this simple DTrace script:

    #!/usr/sbin/dtrace -s

    #pragma D option flowindent

    fbt:smbfs::entry
    {
    }

    fbt:smbfs::return
    {
        trace(arg1);
    }

Oops, dead end ... it seems that the smbfs code is not being accessed by modunload.

Let's use DTrace to look at modunload with this script:

    #!/usr/sbin/dtrace -s

    #pragma D option flowindent

    fbt::modunload:entry
    {
         self->follow = 1;
        trace(execname);
        trace(arg0);
    }

    fbt::modunload:return
    {
         self->follow = 0;
        trace(arg1);
    }

    fbt:::entry
    /self->follow/
    {
    }

    fbt:::return
    /self->follow/
    {
         trace(arg1);
    }


Here's the output of this script:

    # ./modunload.d
    dtrace: script './modunload.d' matched 36695 probes
    CPU FUNCTION
      0  -> modunload                modunload             160
      0   | modunload:entry
      0    -> mod_hold_by_id
      0     -> mod_circdep
      0     <- mod_circdep                                       0
      0     -> mod_hold_by_modctl
      0     <- mod_hold_by_modctl                                0
      0    <- mod_hold_by_id                             3602566648
      0    -> moduninstall
      0    <- moduninstall                                       16
      0    -> mod_release_mod
      0     -> mod_release
      0     <- mod_release                              3602566648
      0    <- mod_release_mod                            3602566648
      0  <- modunload                                            16


I observe that the EBUSY return value '16' is coming from moduninstall. Let's take a look at the source code for moduninstall.

moduninstall returns EBUSY in a few locations, so let's look at the following possibilities:

  1. if (mp->mod_prim || mp->mod_ref || mp->mod_nenabled != 0) return (EBUSY);
  2. if ( detach_driver(mp->mod_modname) != 0 ) return (EBUSY);
  3. if ( kobj_lookup(mp->mod_mp, "_fini") == NULL )
  4. A failed call to smbfs _fini() routine

We can't directly access all of these possibilities, but let's approach them from a process of elimination.

We'll use the following script to display the contents of the various structures and return values in moduninstall:

    #!/usr/sbin/dtrace -s

    #pragma D option flowindent

    fbt::moduninstall:entry
    {
        self->follow = 1;
        printf("mod_prim:%d\n",
            ((struct modctl *)arg0)->mod_prim);
        printf("mod_ref:%d\n",
            ((struct modctl *)arg0)->mod_ref);
        printf("mod_nenabled:%d\n",
            ((struct modctl *)arg0)->mod_nenabled);
        printf("mod_loadflags:%d\n",
            ((struct modctl *)arg0)->mod_loadflags);
    }

    fbt::moduninstall:return
    {
        self->follow = 0;
        trace(arg1);
    }

    fbt::kobj_lookup:entry
    /self->follow/
    {
    }

    fbt::kobj_lookup:return
    /self->follow/
    {
        trace(arg1);
    }

    fbt::detach_driver:entry
    /self->follow/
    {
    }

    fbt::detach_driver:return
    /self->follow/
    {
         trace(arg1);
    }


This script produces the following output:

    # ./moduninstall.d
    dtrace: script './moduninstall.d' matched 6 probes
    CPU FUNCTION
      0  -> moduninstall
        mod_prim:0
        mod_ref:0
        mod_nenabled:0
        mod_loadflags:1
      0    -> detach_driver
      0    <- detach_driver                                       0
      0    -> kobj_lookup
      0    <- kobj_lookup                                4273103456
      0  <- moduninstall                                         16


Comparing this output to the code tells us that the failure is not due to the mp structure values or the return values from detach_driver() of kobj_lookup(). Thus, by a process of elimination, it must be the status returned via the status = (*func)(); call, which calls the smbfs _fini() routine.

And here's what the smbfs _fini() routine contains:

    int _fini(void)
    {
        /* don't allow module to be unloaded */
        return (EBUSY);
    }

Changing the return value to '0' and recompiling the code results in a driver that we can now load and unload, thus we have completed the objectives of this exercise.

 
Summary

Dtrace is powerful debugging tool for software developers, offering you the ability to dynamically instrument your code to display function arguments and return values. I've used the Function Boundary Tracing provider exclusively in these examples. Note that fbt is only one of DTrace's many providers; I'm just scratching the surface of the functionality provided by DTrace. For more information on DTrace, see the BigAdmin DTrace resource page.

 
Resources
 
About the Author

Jay Danielsen is a member of Sun's Advanced development engineering group and an operating systems ambassador. Based in Detroit, Michigan, Jay works with automotive customers to evaluate and customize Sun technologies. His background in software development includes C, Java, and assembly programming languages.