X

Solaris serviceability and nifty tools

Coloring dtrace output

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:


alt="colored dtrace output (data)">

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:


alt="colored dtrace output (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

Join the discussion

Comments ( 1 )
  • Adam Leventhal Monday, June 18, 2007
    Very cool! You might take a look at this blog post I made a couple of years ago about a script I used during the JavaOne keynote in which I used VT100 escape sequences to colorize the output.
Please enter your name.Please provide a valid email address.Please enter a comment.CAPTCHA challenge response provided was incorrect. Please try again.