dtrace discuss - May 2009 - How to calculate java method timestamp?

Hi,

I need help in calculating Java method time-stamp in following fashion.
Consider following method example.

long method3(long stop) {
        try {
            Thread.sleep(1500);
        } catch (Exception e) {

        }
//////////////////// real CPU intensive operation ///////////////////////////
       for (int i = 1; i < stop; i++) {
           stop = stop * stop * i;
        };
        return stop;
    }
  
For above method, I can get time-stamp by using "vtimestamp" and
method-entry/return probes.
But I also want to how much time it is spending as idle ( in above case 1500 ms)
and how much in real CPU intensive operation.

Is there any way to do this?
Help appreciated.

Thanks,
Ajit
-- 
This message posted from opensolaris.org

Hi Ajit,
You can add static dtrace probes into your code, to get a accurate
measure of time spent in the ''real CPU intensive'' section of
the code.
eg.,
DTRACE_PROBE_START
<code snippet to time> 
DTRACE_PROBE_END

For adding probes in your java application see,
http://blogs.sun.com/kamg/entry/announcing_statically_defined_dtrace_probes

Regards,
Krishnan

On Fri, 2009-05-15 at 02:40 -0700, Ajit Bansode wrote:
> Hi,
> 
> I need help in calculating Java method time-stamp in following fashion.
> Consider following method example.
> 
> long method3(long stop) {
>         try {
>             Thread.sleep(1500);
>         } catch (Exception e) {
> 
>         }
> //////////////////// real CPU intensive operation
///////////////////////////
>        for (int i = 1; i < stop; i++) {
>            stop = stop * stop * i;
>         };
>         return stop;
>     }
>   
> For above method, I can get time-stamp by using "vtimestamp" and
method-entry/return probes.
> But I also want to how much time it is spending as idle ( in above case
1500 ms) and how much in real CPU intensive operation.
> 
> Is there any way to do this?
> Help appreciated.
> 
> Thanks,
> Ajit

Thanks for reply Krishnan.

But we don''t have access to code.
So I am wondering if there is any other way apart from adding static dtrace
probes.

Thanks,
Ajit
-- 
This message posted from opensolaris.org

Hi Ajit, 
Probably you can exploit the fact Thread.sleep() is another function you
can probe and get timestamp information. Now you can have a mathematical
relation to get what data you want as below,

Warning: This code might not compile, just check if this idea looks
fine!

hotspot$target::method3:method-entry {
	self->time1 = vtimestamp; 
	self->trace = 1; /* to denote it has entered method3 */
}

hotspot$target::sleep:method-entry /self->trace/ {
	self->time2 = vtimestamp; 
}

hotspot$target::sleep:method-return /self->trace/ {
	self->idle_time = vtimestamp - self->time2; 
}

hotspot$target::method3:method-return /self->trace/ {
	self->time3 = vtimestamp - self->time1;
	self->cpu_time = self->time3 - self->idle_time;
	printf("cpu time = %d, idle time = %d\n", self->cpu_time,
self->idle_time);
	self->trace = 0;
}

Regards,
Krishnan

On Fri, 2009-05-15 at 03:27 -0700, Ajit Bansode wrote:
> Thanks for reply Krishnan.
> 
> But we don''t have access to code.
> So I am wondering if there is any other way apart from adding static dtrace
probes.
> 
> Thanks,
> Ajit

Note that you''ll need a pre-release build of JDK7 to use these static 
probes - they are no available in JDK6 or earlier.

--
- Keith

krishnan parthasarathi - Sun Microsystems - Bangalore India
wrote:
> Hi Ajit,
> You can add static dtrace probes into your code, to get a accurate
> measure of time spent in the ''real CPU intensive'' section
of the code.
> eg.,
> DTRACE_PROBE_START
> <code snippet to time> 
> DTRACE_PROBE_END
> 
> For adding probes in your java application see,
> http://blogs.sun.com/kamg/entry/announcing_statically_defined_dtrace_probes
> 
> Regards,
> Krishnan
> 
> On Fri, 2009-05-15 at 02:40 -0700, Ajit Bansode wrote:
>> Hi,
>>
>> I need help in calculating Java method time-stamp in following fashion.
>> Consider following method example.
>>
>> long method3(long stop) {
>>         try {
>>             Thread.sleep(1500);
>>         } catch (Exception e) {
>>
>>         }
>> //////////////////// real CPU intensive operation
///////////////////////////
>>        for (int i = 1; i < stop; i++) {
>>            stop = stop * stop * i;
>>         };
>>         return stop;
>>     }
>>   
>> For above method, I can get time-stamp by using "vtimestamp"
and method-entry/return probes.
>> But I also want to how much time it is spending as idle ( in above case
1500 ms) and how much in real CPU intensive operation.
>>
>> Is there any way to do this?
>> Help appreciated.
>>
>> Thanks,
>> Ajit
> 
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org

@ Krishnan:
Thanks a lot for your reply.
This idea looks good.
Actually I was not aware of "sleep" probefunc for
"method-entry".

@ Keith:
Thanks Keith.
Actually right now I am working on dvm probes with JDK 5.


Thanks,
Ajit.
-- 
This message posted from opensolaris.org

Krishnan,

I tried your way.
But it''s not working.
I think "dvm$target:sleep::method-entry" probe is not there.
Please point me if I am doing anything wrong.

Thanks,
Ajit
-- 
This message posted from opensolaris.org

Hi Ajit,
Probably you must relax the name of the function by changing it into
*sleep*. 
If that also fails, probably you can aggregate on all the functions
called using dvm$target:::method-entry { @funcs[probefunc] = count() }.
Now look for a function name closest to sleep and replace the failing
probe with the appropriate function name. 

Note: if any of these attempts makes your java app or the entire system
less responsive, use predicates to narrow down your probes,
like /execname == "your-prog-name"/ etc.

Regards,
Krishnan 

On Sun, 2009-05-17 at 22:33 -0700, Ajit Bansode wrote:
> Krishnan,
> 
> I tried your way.
> But it''s not working.
> I think "dvm$target:sleep::method-entry" probe is not there.
> Please point me if I am doing anything wrong.
> 
> Thanks,
> Ajit

Hi Ajit, 
First and foremost check which java version you are using and choose the
jvm provider appropriately.

Regards,
Krishnan

On Mon, 2009-05-18 at 11:33 +0530, krishnan parthasarathi - Sun
Microsystems - Bangalore India wrote:
> Hi Ajit,
> Probably you must relax the name of the function by changing it into
> *sleep*. 
> If that also fails, probably you can aggregate on all the functions
> called using dvm$target:::method-entry { @funcs[probefunc] = count() }.
> Now look for a function name closest to sleep and replace the failing
> probe with the appropriate function name. 
> 
> Note: if any of these attempts makes your java app or the entire system
> less responsive, use predicates to narrow down your probes,
> like /execname == "your-prog-name"/ etc.
> 
> Regards,
> Krishnan 
> 
> On Sun, 2009-05-17 at 22:33 -0700, Ajit Bansode wrote:
> > Krishnan,
> > 
> > I tried your way.
> > But it''s not working.
> > I think "dvm$target:sleep::method-entry" probe is not there.
> > Please point me if I am doing anything wrong.
> > 
> > Thanks,
> > Ajit
> 
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org

Instead of

hotspot$target::sleep:method-entry /self->trace/ {
	self->time2 = vtimestamp; 
}

hotspot$target::sleep:method-return /self->trace/ {
	self->idle_time = vtimestamp - self->time2; 
}

you could use the sched provider probes in Solaris.
sched:::off-cpu
/self->trace/ {

	self->time2 = vtimestamp; 
}


sched:::on-cpu

/self->trace/ {

self->idle_time = vtimestamp - self->time2; 
}




Pramod



On 05/18/09 11:03, Ajit Bansode wrote:
> Krishnan,
>
> I tried your way.
> But it''s not working.
> I think "dvm$target:sleep::method-entry" probe is not there.
> Please point me if I am doing anything wrong.
>
> Thanks,
> Ajit
>   
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20090518/c5856c17/attachment.html>

But "sched" providers don''t give method-level information.
And I want to know which method is responsible for "off-CPU" behavior.

Thanks,
Ajit
-- 
This message posted from opensolaris.org

Hi Krishnan,
I recorded all the things. I didn''t find anything near
"sleep".
Following is the list.
Prov	             Mod			Func		     Name
dvm9766     libdvmti.so         cbVMDeath            vm-death
dvm9766     libdvmti.so         cbVMInit             vm-init
dvm9766     libdvmti.so         cbThreadEnd          thread-end
dvm9766     libdvmti.so         cbThreadStart        thread-start
dvm9766     libdvmti.so         cbException          exception-throw
dvm9766     libdvmti.so         cbExceptionCatch     exception-catch
dvm9766     libdvmti.so         cbClassFileLoadHook  class-load
dvm9766     libdvmti.so         track_allocation     object-alloc
dvm9766     libdvmti.so         _method_exit         method-return
dvm9766     libdvmti.so         _method_entry        method-entry


Also, Java version is 

java version "1.5.0_06"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_06-b05)
Java HotSpot(TM) Server VM (build 1.5.0_06-b05, mixed mode)

Thanks,
Ajit
-- 
This message posted from opensolaris.org

Hi Ajit,
Take a look at this https://solaris10-dtrace-vm-agents.dev.java.net/
In this you can find that arg0 gives the class name and arg1  gives the
function name in method-entry probe. 
So with that you can write a predicate having, copyinstr(arg1)
="Sleep" in the method-entry probe.

Hope this helps,
Krishnan

On Mon, 2009-05-18 at 01:23 -0700, Ajit Bansode wrote:
> Hi Krishnan,
> I recorded all the things. I didn''t find anything near
"sleep".
> Following is the list.
> Prov	             Mod			Func		     Name
> dvm9766     libdvmti.so         cbVMDeath            vm-death
> dvm9766     libdvmti.so         cbVMInit             vm-init
> dvm9766     libdvmti.so         cbThreadEnd          thread-end
> dvm9766     libdvmti.so         cbThreadStart        thread-start
> dvm9766     libdvmti.so         cbException          exception-throw
> dvm9766     libdvmti.so         cbExceptionCatch     exception-catch
> dvm9766     libdvmti.so         cbClassFileLoadHook  class-load
> dvm9766     libdvmti.so         track_allocation     object-alloc
> dvm9766     libdvmti.so         _method_exit         method-return
> dvm9766     libdvmti.so         _method_entry        method-entry
> 
> 
> Also, Java version is 
> 
> java version "1.5.0_06"
> Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_06-b05)
> Java HotSpot(TM) Server VM (build 1.5.0_06-b05, mixed mode)
> 
> Thanks,
> Ajit

On 05/18/09 12:35, Ajit Bansode wrote:
> But "sched" providers don''t give method-level
information.
> And I want to know which method is responsible for "off-CPU"
behavior.
>   
You could use the jstack(10) action in the probe
sched:::off-cpu
/self->trace/ {

	self->time2 = vtimestamp; 
        jstack(10);
} 

Pramod

> Thanks,
> Ajit
>   
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20090518/fcca31fd/attachment.html>