[dtrace-discuss] DTrace interference

[James Litchfield]

I'm trying to figure out why, on rare occasions, this code (slightly simplified) takes much longer (6x) than expected:

gethrtime()
mutex_tryenter(&foo)
cv_signal(&cv)< br>mutex_exit(&foo)
gethrtime()

This is a "high-level" soft interrupt handler (IPL 6)

I use a version of this d script:

#pragma D option cleanrate=200hz
#pragma D option nspec=10
#pragma D option specsize=16M
#pragma D option bufsize=16M
::func:entry
{
       self->spec = speculate();
       self->ts = timestamp;
}
::func:return
/self->spec & ((timestamp - self->ts) > $1)/
{
           commit(self->spec);
           self->spec = 0;
}
::func:return
/self->spec & ((timestamp - self->ts) <= $1)/
{
        discard(self->spec);
        self->spec = 0;
}
:::entry,
:::return
/self->spec/
{
}

I generated a baseline profile without the speculations
to see what the behavior is normally and then added in the 
speculations and limits.

When this fires, I see this additional output, interspersed
at different places:

do_interrupt
    tlb_service (in and out)
    apic_intr_enter(in and out)
    hilevel_intr_prolog( in and out)
        the new pil is 15 and the oldpil is either 6 or 11
do_interrupt return

The CPU this is running on is in a single CPU processor set and
has interrupts turned off.

The questions is whether this is dtrace internal stuff I'm seeing 
or if it's a symptom of something else.
--
This message posted from opensolaris.org