Oracle® Solaris 11.2 Dynamic Tracing Guide

Exit Print View

Updated: July 2014
 
 

Examples

You can use FBT to easily explore the kernel's implementation. The following example script records the first ioctl(2) from any xclock process and then follows the subsequent code path through the kernel:

/*
 * To make the output more readable, we want to indent every function entry
 * (and unindent every function return).  This is done by setting the
 * "flowindent" option.
 */
#pragma D option flowindent

syscall::ioctl:entry
/execname == "xclock" && guard++ == 0/
{
        self->traceme = 1;
        printf("fd: %d", arg0);
}

fbt:::
/self->traceme/
{}

syscall::ioctl:return
/self->traceme/
{
        self->traceme = 0;
        exit(0);
}

Running this script results in output similar to the following example:

# dtrace -s ./xioctl.d
dtrace: script './xioctl.d' matched 26254 probes
CPU FUNCTION                                 
  0  => ioctl                                 fd: 3
  0    -> ioctl                               
  0      -> getf                              
  0        -> set_active_fd                   
  0        <- set_active_fd                   
  0      <- getf                              
  0      -> fop_ioctl                         
  0        -> sock_ioctl                      
  0          -> strioctl                      
  0            -> job_control_type            
  0            <- job_control_type            
  0            -> strcopyout                  
  0              -> copyout                   
  0              <- copyout                   
  0            <- strcopyout                  
  0          <- strioctl                      
  0        <- sock_ioctl                      
  0      <- fop_ioctl                         
  0      -> releasef                          
  0        -> clear_active_fd                 
  0        <- clear_active_fd                 
  0        -> cv_broadcast                    
  0        <- cv_broadcast                    
  0      <- releasef                          
  0    <- ioctl                               
  0  <= ioctl

The output shows that an xclock process called ioctl on a file descriptor that appears to be associated with a socket.

You can also use FBT when trying to understand kernel drivers. For example, the ssd(7D) driver has many code paths by which EIO may be returned. FBT can be easily used to determine the precise code path that resulted in an error condition, as shown in the following example:

fbt:ssd::return
/arg1 == EIO/
{
        printf("%s+%x returned EIO.", probefunc, arg0);
}

For more information on any one return of EIO, one may wish to speculatively trace all fbt probes, and then commit(or discard) based on the return value of a specific function. See Chapter 7, Speculative Tracing for details on speculative tracing.

Alternatively, you can use FBT to understand the functions called within a specified module. The following example lists all of the functions called in UFS:

# dtrace -n fbt:ufs::entry'{@a[probefunc] = count()}'
dtrace: description 'fbt:ufs::entry' matched 353 probes
^C
  ufs_ioctl                                                         1
  ufs_statvfs                                                       1
  ufs_readlink                                                      1
  ufs_trans_touch                                                   1
  wrip                                                              1
  ufs_dirlook                                                       1
  bmap_write                                                        1
  ufs_fsync                                                         1
  ufs_iget                                                          1
  ufs_trans_push_inode                                              1
  ufs_putpages                                                      1
  ufs_putpage                                                       1
  ufs_syncip                                                        1
  ufs_write                                                         1
  ufs_trans_write_resv                                              1
  ufs_log_amt                                                       1
  ufs_getpage_miss                                                  1
  ufs_trans_syncip                                                  1
  getinoquota                                                       1
  ufs_inode_cache_constructor                                       1
  ufs_alloc_inode                                                   1
  ufs_iget_alloced                                                  1
  ufs_iget_internal                                                 2
  ufs_reset_vnode                                                   2
  ufs_notclean                                                      2
  ufs_iupdat                                                        2
  blkatoff                                                          3
  ufs_close                                                         5
  ufs_open                                                          5
  ufs_access                                                        6
  ufs_map                                                           8
  ufs_seek                                                         11
  ufs_addmap                                                       15
  rdip                                                             15
  ufs_read                                                         15
  ufs_rwunlock                                                     16
  ufs_rwlock                                                       16
  ufs_delmap                                                       18
  ufs_getattr                                                      19
  ufs_getpage_ra                                                   24
  bmap_read                                                        25
  findextent                                                       25
  ufs_lockfs_begin                                                 27
  ufs_lookup                                                       46
  ufs_iaccess                                                      51
  ufs_imark                                                        92
  ufs_lockfs_begin_getpage                                        102
  bmap_has_holes                                                  102
  ufs_getpage                                                     102
  ufs_itimes_nolock                                               107
  ufs_lockfs_end                                                  125
  dirmangled                                                      498
  dirbadname                                                      498

If you know the purpose or arguments of a kernel function, you can use FBT to understand how or why the function is being called. For example, putnext(9F) takes a pointer to a queue(9S) structure as its first member. The q_qinfo member of the queue structure is a pointer to a qinit(9S) structure. The qi_minfo member of the qinit structure has a pointer to a module_info(9S) structure, which contains the module name in its mi_idname member. The following example puts this information together by using the FBT probe in putnext to track putnext(9F) calls by module name:

fbt::putnext:entry
{
        @calls[stringof(args[0]->q_qinfo->qi_minfo->mi_idname)] = count();
}

Running the above script results in output similar to the following example:

# dtrace -s ./putnext.d
^C
  iprb

                         1
  rpcmod

                       1
  pfmod                        1
  timod                        2
  vpnmod                       2
  pts                          40
  conskbd                      42
  kb8042                       42
  tl                           58
  arp                          108
  tcp                          126
  ptm                          249
  ip                           313
  ptem                         340
  vuid2ps2                     361
  ttcompat                     412
  ldterm                       413
  udp                          569
  strwhead                     624
  mouse8042 								

726

You can also use FBT to determine the time spent in a particular function. The following example shows how to determine the callers of the DDI delaying routines drv_usecwait(9F) and delay(9F).

fbt::delay:entry,
fbt::drv_usecwait:entry
{
        self->in = timestamp
}

fbt::delay:return,
fbt::drv_usecwait:return
/self->in/
{
        @snoozers[stack()] = quantize(timestamp - self->in);
        self->in = 0;
}

This example script is particularly interesting to run during boot. Chapter 15, Anonymous Tracing describes the procedure for performing anonymous tracing during system boot. Upon reboot, you might see output similar to the following example:

# dtrace -ae

              ata`ata_wait+0x34
              ata`ata_id_common+0xf5
              ata`ata_disk_id+0x20
              ata`ata_drive_type+0x9a
              ata`ata_init_drive+0xa2
              ata`ata_attach+0x50
              genunix`devi_attach+0x75
              genunix`attach_node+0xb2
              genunix`i_ndi_config_node+0x97
              genunix`i_ddi_attachchild+0x4b
              genunix`devi_attach_node+0x3d
              genunix`devi_config_one+0x1d0
              genunix`ndi_devi_config_one+0xb0
              devfs`dv_find+0x125
              devfs`devfs_lookup+0x40
              genunix`fop_lookup+0x21
              genunix`lookuppnvp+0x236
              genunix`lookuppnat+0xe7
              genunix`lookupnameat+0x87
              genunix`cstatat_getvp+0x134

           value  ------------- Distribution ------------- count    
            2048 |                                         0        
            4096 |@@@@@@@@@@@@@@@@@@@@@                    4105     
            8192 |@@@@                                     783      
           16384 |@@@@@@@@@@@@@@                           2793     
           32768 |                                         16       
           65536 |                                         0


              kb8042`kb8042_wait_poweron+0x29
              kb8042`kb8042_init+0x22
              kb8042`kb8042_attach+0xd6
              genunix`devi_attach+0x75
              genunix`attach_node+0xb2
              genunix`i_ndi_config_node+0x97
              genunix`i_ddi_attachchild+0x4b
              genunix`devi_attach_node+0x3d
              genunix`devi_config_one+0x1d0
              genunix`ndi_devi_config_one+0xb0
              genunix`resolve_pathname+0xa5
              genunix`ddi_pathname_to_dev_t+0x16
              consconfig_dacf`consconfig_load_drivers+0x14
              consconfig_dacf`dynamic_console_config+0x6c
              consconfig`consconfig+0x8
              unix`stubs_common_code+0x3b

           value  ------------- Distribution ------------- count    
          262144 |                                         0        
          524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@      221      
         1048576 |@@@@                                     29       
         2097152 |                                         0

        
              usba`hubd_enable_all_port_power+0xed
              usba`hubd_check_ports+0x8e
              usba`usba_hubdi_attach+0x275
              usba`usba_hubdi_bind_root_hub+0x168
              uhci`uhci_attach+0x191
              genunix`devi_attach+0x75
              genunix`attach_node+0xb2
              genunix`i_ndi_config_node+0x97
              genunix`i_ddi_attachchild+0x4b
              genunix`i_ddi_attach_node_hierarchy+0x49
              genunix`attach_driver_nodes+0x49
              genunix`ddi_hold_installed_driver+0xe3
              genunix`attach_drivers+0x28

           value  ------------- Distribution ------------- count    
        33554432 |                                         0        
        67108864 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3        
       134217728 |                                         0