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:
trace mbuf which caused activation of
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)
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
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:
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.
(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 :)