X

Solaris serviceability and nifty tools

Adding dtrace SDT probes

It seems that many developers and dtrace users found themselves in a position where they
wanted to add some SDT probes to a module to get more insight into what's going on but the had to pause
and were thinking "okay, more probes. But where to put them ? Do I really
need the additional probes when I already have the fbt ones ?"
.
To do this, systematic approach is needed in order not to over-do or under-do.
I will use KSSL (Solaris kernel SSL proxy [1]) for illustration.

With CR 6556447,
tens of SDT probes were introduced into KSSL module and other modules which interface with it.
Also, in addition to the new SDT probes, in KSSL we got rid of the
KSSL_DEBUG macros compiled only in DEBUG kernels and substituted them with
SDT probes. As a result, much better observability and error detection was achieved
with both debug and non-debug kernels. The other option would be to create KSSL
dtrace provider but that would be too big gun for what is needed to achieve.

Generically, the following interesting data points for data gathering/observation
can be identified in code:

  • data paths

    When there is a more than one path how data could flow into a subsystem.
    E.g. for TCP we have couple of cases how SSL data could reach KSSL input queue.
    To identify where from exactly was tcp_kssl_input() called we use SDT probes:

    if (tcp->tcp_listener || tcp->tcp_hard_binding) {
    ...

    if (tcp->tcp_kssl_pending) {

    DTRACE_PROBE1(kssl_mblk__ksslinput_pending,

    mblk_t \*, mp);

    tcp_kssl_input(tcp, mp);

    } else {

    tcp_rcv_enqueue(tcp, mp, seg_len);

    }

    } else {
    ...

    /\* Does this need SSL processing first? \*/

    if ((tcp->tcp_kssl_ctx != NULL) &&

    (DB_TYPE(mp) == M_DATA)) {

    DTRACE_PROBE1(kssl_mblk__ksslinput_data1,

    mblk_t \*, mp);

    tcp_kssl_input(tcp, mp);

    } else {

    putnext(tcp->tcp_rq, mp);

    if (!canputnext(tcp->tcp_rq))

    tcp->tcp_rwnd -= seg_len;

    }
    ...
  • data processed in while/for cycles

    To observe what happens in each iteration of the cycle. Can be used in code like this:
    while (mp != NULL) {
    DTRACE_PROBE1(kssl_mblk__handle_record_cycle, mblk_t \*, mp);
    /\* process the data \*/
    ...
    mp = mp->b_cont;
    }
  • switch statements

    If significant/non-trivial processing happens inside switch it may be useful to add SDT probes there too. E.g.:
      content_type = (SSL3ContentType)mp->b_rptr[0];
    switch(content_type) {
    /\* select processing according to type \*/
    case content_alert:
    DTRACE_PROBE1(kssl_mblk__content_alert, mblk_t \*, mp);
    ...
    break;
    case content_change_cipher_spec:
    DTRACE_PROBE1(kssl_mblk__change_cipher_spec, mblk_t \*, mp);
    ...
    break;
    default:
    DTRACE_PROBE1(kssl_mblk__unexpected_msg, mblk_t \*, mp);
    break;
    }
  • labels which cannot be (easily) identified in other way

    Useful if code which follows the label is generic (assignments, no function calls), e.g.:
                                    /\*
    \* Give this session a chance to fall back to
    \* userland SSL
    \*/
    if (ctxmp == NULL)
    goto no_can_do;
    ...
    no_can_do:
    DTRACE_PROBE1(kssl_no_can_do, tcp_t \*, tcp);
    listener = tcp->tcp_listener;
    ind_mp = tcp->tcp_conn.tcp_eager_conn_ind;
    ASSERT(ind_mp != NULL);

You've surely noticed that same of the probe definitions above have common prefix
(kssl_mblk-). This is one of the things which make SDT probes
so attractive.
With prefixes it is possible to do the e.g. following:

sdt:::kssl_err-\*
{
trace(timestamp);
printf("hit error in %s\\n", probefunc);
stack(); ustack();
}

The important part is that we do not specify module of function name.
The implicit wildcard (funcname/probename left out) combined with explicit wildcard
(prefix + asterisk) will lead to all KSSL error probes to be activated
regardless of in which module or function there are defined.
This is obviously very useful for technologies which span multiple Solaris
subsystems or modules (such as KSSL).

The nice thing about the error probes is that they could be leveraged in test suites.
For each test case we can first run dtrace script with the above probeset
covering all KSSL errors in the background and after the test completes
just check if it produced some data. If it did, then the test case can be considered
as failed. No need to check kstat(1M) (and other counters), log files, etc.

Also, thanks to the way how dtrace probes are activated we can have both
generic probeset (using this for lack of better term) as above with
addition of probe specific action, e.g.:

/\* probeset of all KSSL error probes \*/
sdt:::kssl_err-\*
{
trace(timestamp);
printf("hit error in %s\\n", probefunc);
}
/\*
the probe definition is:
DTRACE_PROBE2(kssl_err__bad_record_size,
uint16_t, rec_sz, int, spec->cipher_bsize);
\*/
sdt:kssl:kssl_handle_record:kssl_err-bad_record_size
{
trace(timestamp);
tracemem(arg0, 32);
printf("rec_sz = %d , cipher_bsize = %d\\n", arg1, arg2);
}

If probe kssl_err-bad_record_size gets activated the generic
probe will be activated (and fires) too because the probeset contains the probe.

Similarly to the error prefix, we can have data specific prefix. For KSSL it is kssl_mblk- prefix which could be used for tracing
all mblks (msgb(9S)) as they flow through TCP/IP, STREAMS and KSSL modules.
With such probes it is possible to do e.g. the following:

/\* how many bytes from a mblk to dump \*/
#define DUMP_SIZE 48
/\* use macros from \*/
#define MBLKL(mp) ((mp)->b_wptr - (mp)->b_rptr)
#define DB_FLAGS(mp) ((mp)->b_datap->db_flags)
#define PRINT_MBLK_INFO(mp) \\
printf("mblk = 0x%p\\n", mp); \\
printf("mblk size = %d\\n", MBLKL((mblk_t \*)mp)); \\
PRINT_MBLK_PTRS(mp);
#define PRINT_MBLK(mp) \\
trace(timestamp); \\
printf("\\n"); \\
PRINT_MBLK_INFO(mp); \\
printf("DB_FLAGS = 0x%x", DB_FLAGS((mblk_t \*)mp)); \\
tracemem(((mblk_t \*)mp)->b_rptr, DUMP_SIZE); \\
tracemem(((mblk_t \*)mp)->b_wptr - DUMP_SIZE, \\
DUMP_SIZE);
sdt:::kssl_mblk-\*
{
trace(timestamp);
printf("\\n");
PRINT_MBLK(arg0)
}

This is actually an excerpt from my (currently internal) KSSL debugging suite.


An example of output from such probe can be seen in my
Coloring dtrace output
post.

For more complex projects it would be waste to stop here. Prefixes could be further
structured. However, this has some drawbacks. In particular, I was thinking about having
kssl_mblk- and kssl_err- prefixes. Now what to do for places
where an error condition occurred _and_ we would like to see the associated mblk ?
Using something like kssl_mblk_err-\* comes to ones mind. However, there is a problem
with that - what about the singleton cases (only mblk, only err). Sure, using multiple
wildcards in dtrace is possible (e.g. syscall::\*read\*:) but this will
make it ugly and complicated given the number of mblk+err cases (it's probably safe to
assume that the number of such cases will be low). Simply, it's not worth the hassle.
Rather, I went with 2 probes.


To conclude, using structured prefixes is highly beneficial only for set of probes where
categories/sub-prefixes create non-intersecting sets (e.g. data type and debug level).

Of course, all of the above is not valid only for kernel but also for custom userland probes !

[1] High-level description of KSSL can be found in blueprint 819-5782.

Be the first to comment

Comments ( 0 )
Please enter your name.Please provide a valid email address.Please enter a comment.CAPTCHA challenge response provided was incorrect. Please try again.