Currently I am working on a subtle bug in KSSL. (SSL kernel proxy) In order to diagnose the root cause of the bug I use set of dtrace scripts to gather data in various probes. One of the dtrace scripts I am using looks like this:

#!/usr/sbin/dtrace -Cs
/*
  trace mbuf which caused activation of 
  kssl-i-kssl_handle_any_record_recszerr probe

  NOTE: this presumes that every mblk seen by TCP/KSSL
        is resonably sized (cca 100 bytes)
 */

/* how many bytes from a mblk to dump */
#define DUMP_SIZE       48

/* 
  generic kssl mblk dump probe 
  (covers both input path and special cases)
 */
sdt:::kssl_mblk-*
{
  trace(timestamp);
  printf("\nmblk size = %d",
      ((mblk_t *)arg0)->b_wptr - ((mblk_t *)arg0)->b_rptr);
  tracemem(((mblk_t *)arg0)->b_rptr, DUMP_SIZE);
  tracemem(((mblk_t *)arg0)->b_wptr - DUMP_SIZE, DUMP_SIZE);
}

The scripts usually collect big chunks of data from the various SDT probes I have put into kssl kernel module. After the data are collected I usually spend big chunks of time sifting though it. At one point of time I have got a suspicion that the problem is actually a race condition of sorts. In order to shed some light on what's going on I have used less(1) which provides highlighting of data when searching. While this is sufficient when searching for a single pattern, it does not scale when more patterns are used. This is when I got the idea to color the output from dtrace scripts to see the correlations (or lack of them) of the events with a simple Perl script. Example of the output colored by the script:

This looks slightly more useful than plain black output in terminal but even with 19" display the big picture is missing. So, I have changed the dtrace-coloring script to be able to strip the data parts for probes and print just the headers:

This is done via '-n' command line option. (the default is to print everything.) The output containing just the colored headers is especially nice for tracking down race conditions and other time-sensitive misbehaviors. You can download the script for dtrace log coloring here: dtrace-coloring.pl

The colors can be assigned to regular expressions in the hash 'coloring' in the script itself. For the example above I have used the following assignments:

my %coloring = (
  '.*kssl_mblk-i-handle_record_cycle.*' => '4b6983',    # dark blue
  '.*kssl_mblk-enqueue_mp.*'    => '6b7f0d',    # dark green
  '.*kssl_mblk-getnextrecord_retmp.*'   => 'a11c10',    # dark red
);

In the outputs above you might have noticed that a timestamp is printed when a probe fires. This is useful for pre-processing of the log file. dtrace(1) (or libdtrace to be more precise) does not sort events as they come from the kernel. (see CR 6496550 for more details) In cases when hunting down a race condition on multiprocessor machine having the output sorted is crucial. So in order to get consistent image suitable for race condition investigation a sort script is needed. You might use a crude script of mine or you can write yours :)

Technorati Profile