dtrace discuss - Apr 2009 - Unexpected behavior of ''self'' in profile/tick probes

Hi all,

It seems that ''self'' behaves differently in profile and tick
probes compared with regular ones (perhaps because they can interrupt normal
dtrace probes?)

For example, the following code does not output anything on my machine, even
when ''foo'' is called repeatedly by the target process:

pid$target::foo:entry/tid == 1/ { self->val = 1; }
profile-10001usec /self->val/ { }

The following probe fires as expected, though:

pid$target::foo:return /self->val/ { }

If I set self->val from a profile/tick probe then they see it; I
haven''t checked whether self and tid are tied to each other or whether
normal probes can see it, but I suspect the answer on both counts is no.

So far I''ve had to work around this using global dynamic arrays, keyed
by tid, to store thread-local data I want to pass to the profiling probes, but
this is cumbersome and doesn''t perform terribly well, either.

Is this a bug or a feature?
Ryan
-- 
This message posted from opensolaris.org

On Sat, Apr 18, 2009 at 12:48 PM, Ryan <ryanjohn at ece.cmu.edu>
wrote:
> Hi all,
>
> It seems that ''self'' behaves differently in profile and
tick probes compared with regular ones (perhaps because they can interrupt
normal dtrace probes?)
>
> For example, the following code does not output anything on my machine,
even when ''foo'' is called repeatedly by the target process:
>
> pid$target::foo:entry/tid == 1/ { self->val = 1; }
> profile-10001usec /self->val/ { }
>
> The following probe fires as expected, though:
>
> pid$target::foo:return /self->val/ { }
>
> If I set self->val from a profile/tick probe then they see it; I
haven''t checked whether self and tid are tied to each other or whether
normal probes can see it, but I suspect the answer on both counts is no.
"self" variables are thread-local variables, which are unique to the
thread in which they fire.  The thread in which the foo:entry probe
fires isn''t the same thread in which the profile probe fires.

The same problem affects io:::start and io:::end probes.  You can''t
rely on thread-local variables to match an io:::start with its
corresponding io:::end, you have to use a global array indexed on
information unique to that I/O.  You can see this in the examples in
the chapter on the io provider.

Chad

> "self" variables are thread-local variables, which
> are unique to the thread in which they fire.  The 
> thread in which the foo:entry probe fires isn''t 
> the same thread in which the profile probe fires.
I understand that the profile interrupt fires in a different context than the
standard lwp, but it did take over the lwp indicated by {pid, tid}, which is
still valid AFAIK.

I guess the issue is that I had always assumed self and tid were tied together,
when in fact self is (apparently) tied to some piece of the current context
(register g7, perhaps?) which happens to match tid for most probes but not all
of them.
> The same problem affects io:::start and io:::end
> probes.  You can''t rely on thread-local variables to 
> match an io:::start with its corresponding io:::end
> you have to use a global array indexed on
> information unique to that I/O.  
That''s unfortunate. Even with a 100001us tick the profile probe that
reads global_array[tid] sends system time through the roof (and throughput
through the floor) when dtrace is running. You lose cacheable predicates, too.

Also, does that mean that if I declare multiple
''profile-10001us'' probes they won''t necessarily share
a common ''self'' ? I tested that ''self''
persists between ticks but didn''t think to check between probes. If so
my script is horribly broken...
> You can see this in the examples in the chapter 
> on the io provider.
Some examples like that for chapter on the profile provider would probably be
helpful. Right now there''s no hint of this other than the sentence
about "unanchored probes" which doesn''t actually explain the
definition -- or the implications -- of "unanchored."

Incidentally, the I/O provider chapter doesn''t ever explain why most of
the examples use associative arrays instead of self. Worse, the second to last
example actually does use self to communicate between io:::start and io:::end
(that''s a bug, right?).

Ryan
-- 
This message posted from opensolaris.org

***
Incidentally, the I/O provider chapter doesn''t ever explain why most of
the examples use associative arrays instead of self. Worse, the second to last
example actually does use self to communicate between io:::start and io:::end
(that''s a bug, right?).
***
Did you mean io:::done? If so, I''m not finding the example you mean in
the Sep 2008 version of the guide. I''m all but certain you''re
not confusing this with the (dtrace:::)END probe, for which there are several
examples using aggregations.
-- 
This message posted from opensolaris.org

On Sat, Apr 18, 2009 at 6:57 PM, Ryan <ryanjohn at ece.cmu.edu>
wrote:
>> "self" variables are thread-local variables, which
>> are unique to the thread in which they fire. ?The
>> thread in which the foo:entry probe fires isn''t
>> the same thread in which the profile probe fires.
>
> I understand that the profile interrupt fires in a different context than
the standard lwp, but it did take over the lwp indicated by {pid, tid}, which is
still valid AFAIK.
>
> I guess the issue is that I had always assumed self and tid were tied
together, when in fact self is (apparently) tied to some piece of the current
context (register g7, perhaps?) which happens to match tid for most probes but
not all of them.
This comment describes how self is tied to the thread ID
(specifically, t_did, the kernel thread ID.)  (This is from
http://src.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/uts/common/dtrace/dtrace.c.):

    321  * The key for a thread-local variable consists of the lower
61 bits of the
    322  * t_did, plus the 3 bits of the highest active interrupt
above LOCK_LEVEL.

This is above the definition of DTRACE_TLS_KEY():

    335 #define	DTRACE_TLS_THRKEY(where) { \
    336 	uint_t intr = 0; \
    337 	uint_t actv = CPU->cpu_intr_actv >> (LOCK_LEVEL + 1); \
    338 	for (; actv; actv >>= 1) \
    339 		intr++; \
    340 	ASSERT(intr < (1 << 3)); \
    341 	(where) = ((curthread->t_did + DIF_VARIABLE_MAX) & \
    342 	    (((uint64_t)1 << 61) - 1)) | ((uint64_t)intr << 61); \
    343 }

The profile provider uses cyclics, and cyclics fire at a high
interrupt level, so a self variable will never refer to the same
storage between, e.g., a syscall probe and a profile probe.

We can examine this with this D script:

#!/usr/sbin/dtrace -s
#pragma D option quiet

pid$target::main:entry
{
        t_did = curthread->t_did;
        printf("t_did == %lu intr_actv == %d\n", curthread->t_did,
            curthread->t_cpu->cpu_intr_actv);
}

profile-1
/ curthread->t_did == t_did /
{
        printf("t_did == %lu intr_actv == %d\n", curthread->t_did,
            curthread->t_cpu->cpu_intr_actv);
}

When I run this, I see the following:

# /tmp/foo.d -c ./cpu-hog
t_did == 27914 intr_actv == 0
t_did == 27914 intr_actv == 16384
t_did == 27914 intr_actv == 16384
t_did == 27914 intr_actv == 16384
^C

When the profile probe fires, there is an active interrupt above
LOCK_LEVEL (10), so the key for this thread-local variable is
necessarily different between these two probes.
>
>> The same problem affects io:::start and io:::end
>> probes. ?You can''t rely on thread-local variables to
>> match an io:::start with its corresponding io:::end
>> you have to use a global array indexed on
>> information unique to that I/O.
>
> That''s unfortunate. Even with a 100001us tick the profile probe
that reads global_array[tid] sends system time through the roof (and throughput
through the floor) when dtrace is running. You lose cacheable predicates, too.
>
> Also, does that mean that if I declare multiple
''profile-10001us'' probes they won''t necessarily share
a common ''self'' ? I tested that ''self''
persists between ticks but didn''t think to check between probes. If so
my script is horribly broken...
If you declare multiple identical profile probes (e.g.,
profile-10001us), they''ll share the same self variable within a single
firing of that probe.  (As mentioned in the other thread, the probe
will only fire once, and all of the clauses attached to this probe
will be run when the probe fires.)

They won''t necessarily share the same probe firing between instances,
though.  Consider this script and output:

#!/usr/sbin/dtrace -qs

profile-1
/ !self->i && cpu == 1 /
{
        self->i = 1;
}

profile-1
/ self->i && cpu == 1 /
{
        self->i++;
        printf("%d %d\n", self->i, curthread->t_did);
}

# /tmp/bar.d
2 29074
3 29074
2 29073
4 29074
3 29073
4 29073
2 29075
^C
>
>> You can see this in the examples in the chapter
>> on the io provider.
>
> Some examples like that for chapter on the profile provider would probably
be helpful. Right now there''s no hint of this other than the sentence
about "unanchored probes" which doesn''t actually explain the
definition -- or the implications -- of "unanchored."
>
> Incidentally, the I/O provider chapter doesn''t ever explain why
most of the examples use associative arrays instead of self. Worse, the second
to last example actually does use self to communicate between io:::start and
io:::end (that''s a bug, right?).
Which example is that?  I see one that uses a self variable to
communicate between io:::wait-start and io:::wait-done, but those are
going to fire in the same thread.

Chad

> > Incidentally, the I/O provider chapter doesn''t ever
> explain why most of the examples use associative
> arrays instead of self. Worse, the second to last
> example actually does use self to communicate between
> io:::start and io:::end (that''s a bug, right?).
> 
> Which example is that?  I see one that uses a self
> variable to
> communicate between io:::wait-start and
> io:::wait-done, but those are
> going to fire in the same thread.
Ah, you''re right. It is io::wait-*  My bad.

Ryan
-- 
This message posted from opensolaris.org