dtrace discuss - Feb 2006 - Java dtrace questions (dmvti probe effect, etc.)

Hi, I have a few questions with respect to using the JVMTI agent. 
Specifically, I''ve run some dtrace scripts using it, and I''m
curious
about a discrepancy I''m seeing.

I know that there''s a non-zero probe effect, but would it be enough to
account for the following?  When I run this:

dvm$1:::object-alloc
{
    @allocsum[tid,copyinstr(arg0)] = sum(1);
}

for about a minute, I see this at the top end:

        1  java/util/ArrayList                                           87903
        1  [Ljava/lang/Object;                                        183934
        1  java/util/LinkedList$Entry                               767351

But when I run the following:

dvm$1:::object-alloc
/ copyinstr(arg0) == "java/util/LinkedList$Entry" /
{
    @allocsum[jstack(20)] = sum(1);
}

for about a minute, the counts I get on the stack traces are an order
of magnitude lower than I expect to see, ~50,000 as compared to the
~1,000,000 the above would seem to indicate.

Is it the case that the copyinstr() in the predicate is very
expensive, and there''s a better way to do what I want?

Also, unrelated to the probe effect, does that
million-object-allocations-per-minute figure above seem ridiculous?  I
don''t really have anything to compare against, but it seems a bit
ludicrous to me.

Thanks,
Chad Mynhier

Chad Mynhier''s email at 2/13/2006 9:14 AM,
said:
> Hi, I have a few questions with respect to using the JVMTI agent. 
> Specifically, I''ve run some dtrace scripts using it, and
I''m curious
> about a discrepancy I''m seeing.
> 
> I know that there''s a non-zero probe effect, but would it be
enough to
> account for the following?  When I run this:
> 
> dvm$1:::object-alloc
> {
>     @allocsum[tid,copyinstr(arg0)] = sum(1);
> }
> 
> for about a minute, I see this at the top end:
> 
>         1  java/util/ArrayList                                          
87903
>         1  [Ljava/lang/Object;                                       
183934
>         1  java/util/LinkedList$Entry                               767351
> 
> But when I run the following:
> 
> dvm$1:::object-alloc
> / copyinstr(arg0) == "java/util/LinkedList$Entry" /
> {
>     @allocsum[jstack(20)] = sum(1);
> }
> 
> for about a minute, the counts I get on the stack traces are an order
> of magnitude lower than I expect to see, ~50,000 as compared to the
> ~1,000,000 the above would seem to indicate.
> 
> Is it the case that the copyinstr() in the predicate is very
> expensive, and there''s a better way to do what I want?
It is really no more expensive than the copyinstr() you have in the 
first script. However, the comparison and especially the jstack() action 
are going to be painful. For the jstack(), DTrace has to ask the JVM to 
resolve the stack so he gets roped into doing extra work on your behalf.
> 
> Also, unrelated to the probe effect, does that
> million-object-allocations-per-minute figure above seem ridiculous?  I
> don''t really have anything to compare against, but it seems a bit
> ludicrous to me.
Nah, I wouldn''t be overly concerned. A million objects per minute is 
pretty tame compared to what I have seen. However, you need to be sure 
that it is reasonable for your HW and that the GC is not too busy.

In looking at this, I would be more concerned about the fact that they 
are java/util/LinkedList$Entry. A linked list with at least a million 
entries is a bit troublesome. There is probably a better data structure 
for this if these objects persist for any amount of time and if this 
structure is ever searched.

Thanks,

Jarod