dtrace discuss - Aug 2005 - measuring user and system time with DTrace

Hello, 

  I would like to measure system time and user time of some java methods in a
multithreaded java application. Can this be done with DTrace?

Here are some details: 

OS: Solaris 9/10
Java: 1.5
Accuracy: ~ 10 nanos

 So, currently we have something like this: 

==================================  start = getTime(); 
    void foo() { 
    // do some work here 

    }

  end = getTime();
==================================
  Currently, we are using gethrvtime() (to implement getTime()) , but this gives
only user time in Solaris. We miss the system time, and would like to know what
it is. Is this possible with DTrace? How can we implement this needed
functionality with DTrace?
This message posted from opensolaris.org

With DTrace and the dvm provider, you can easily take a timestamp on entry
to a Java method and then compare it to a timestamp you take upon return
from that method. For information on the dvm provider, try these links:

  https://solaris10-dtrace-vm-agents.dev.java.net/
  http://blog.sun.com/roller/page/ahl/?anchor=dtracing_java

Adam

On Fri, Aug 12, 2005 at 11:16:51AM -0700, Eugene wrote:
> Hello, 
> 
>   I would like to measure system time and user time of some java methods in
a multithreaded java application. Can this be done with DTrace?
> 
> Here are some details: 
> 
> OS: Solaris 9/10
> Java: 1.5
> Accuracy: ~ 10 nanos
> 
>  So, currently we have something like this: 
> 
> ==================================>   start = getTime(); 
>     void foo() { 
>     // do some work here 
> 
>     }
> 
>   end = getTime();
> ==================================> 
>   Currently, we are using gethrvtime() (to implement getTime()) , but this
gives only user time in Solaris. We miss the system time, and would like to know
what it is. Is this possible with DTrace? How can we implement this needed
functionality with DTrace?
> This message posted from opensolaris.org
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org
-- 
Adam Leventhal, Solaris Kernel Development       http://blogs.sun.com/ahl

Taking a timestamp(or did u mean vtimestamp) would just give me wallclock,
right? What if the thread got descheduled in the middle of the java method? The
vtimestamp looks more promising and is defined in the Dtrace guide as:

"The current value of a nanosecond timestamp counter that is virtualized to
the amount of time that the current thread has been running on a CPU, minus the
time spent in DTrace predicates and actions."

So does the time that "the current thread has been running on cpu" =
System time + User time? Or is it like gethrvtime, only giving the user
time....Please clarify....
This message posted from opensolaris.org

To see what vtimestamp and timestamp output, I wrote some Java code that read in
characters from a file. I instrumented my own Java method, doRead() with the dvm
provider, taking a timestamp on entry and exit as you suggested.  So basically
my dtrace code has two probes defined, and each probe fires once. The DTrace
overhead seems to be overwhelming. I ran without DTrace on a 30 MB file (using
BufferedReader read method) for a wall clock of 45 seconds. With DTrace, it took
194 seconds and the CPU utilization went up from 41% (on 2 cpus, i think only
one is doing the work) to 49%. Any idea what is going on? Since I only have two
probes instrumented, why is the overhead so large?
This message posted from opensolaris.org

On Wed, Aug 17, 2005 at 10:05:00AM -0700, Eugene wrote:
> To see what vtimestamp and timestamp output, I wrote some Java code that
read in characters from a file. I instrumented my own Java method, doRead() with
the dvm provider, taking a timestamp on entry and exit as you suggested.  So
basically my dtrace code has two probes defined, and each probe fires once. The
DTrace overhead seems to be overwhelming. I ran without DTrace on a 30 MB file
(using BufferedReader read method) for a wall clock of 45 seconds. With DTrace,
it took 194 seconds and the CPU utilization went up from 41% (on 2 cpus, i think
only one is doing the work) to 49%. Any idea what is going on? Since I only have
two probes instrumented, why is the overhead so large?
Because you don''t just have two probes enabled -- you are instrumenting
_every_ method entry and return in your program, and you are copying in
a string upon every entry and return to check against "doRead". 
(Frankly,
I''m surprised that the hit was only 4X.)  This is why the Java solution
we
have now isn''t the ideal solution:  it has a non-zero disabled probe
effect,
and (as you discovered) it''s is very difficult to minimize the enabled
probe effect.  The problem is that instrumenting Java the way we''d like
to
do it -- with the kind of true, dynamic instrumention that we use in the
kernel and for C/C++ apps -- is a very difficult problem.  

So why did we put this out there if it''s not the perfect solution? 
Because
the state-of-the-art in debugging systemic problems in Java is so woefully
bad that the dvm provider is still a giant lurch over what else is out
there -- imperfections and all.  We _will_ ultimately solve the harder
problem (or at least, we will _try_ to solve the harder problem -- it''s
that hard) but it''s going to be a while -- we have a lot of foundation
to
pour before we get there...

	- Bryan

--------------------------------------------------------------------------
Bryan Cantrill, Solaris Kernel Development.       http://blogs.sun.com/bmc

Bryan Cantrill''s email at 8/17/2005 12:17 PM,
said:
> On Wed, Aug 17, 2005 at 10:05:00AM -0700, Eugene wrote:
> 
>>To see what vtimestamp and timestamp output, I wrote some Java code that
read in characters from a file. I instrumented my own Java method, doRead() with
the dvm provider, taking a timestamp on entry and exit as you suggested.  So
basically my dtrace code has two probes defined, and each probe fires once. The
DTrace overhead seems to be overwhelming. I ran without DTrace on a 30 MB file
(using BufferedReader read method) for a wall clock of 45 seconds. With DTrace,
it took 194 seconds and the CPU utilization went up from 41% (on 2 cpus, i think
only one is doing the work) to 49%. Any idea what is going on? Since I only have
two probes instrumented, why is the overhead so large?
> 
> 
> Because you don''t just have two probes enabled -- you are
instrumenting
> _every_ method entry and return in your program, and you are copying in
> a string upon every entry and return to check against "doRead". 
(Frankly,
> I''m surprised that the hit was only 4X.)  This is why the Java
solution we
> have now isn''t the ideal solution:  it has a non-zero disabled
probe effect,
> and (as you discovered) it''s is very difficult to minimize the
enabled
> probe effect.  The problem is that instrumenting Java the way we''d
like to
> do it -- with the kind of true, dynamic instrumention that we use in the
> kernel and for C/C++ apps -- is a very difficult problem.  
> 
The dvm provider will have much less overhead than other similar approaches when
you don''t actually have DTrace running (and less in general). I concur
with
Bryan that 4X is actually respectable. It can be much worse. The good news is 
that the dvm provider is fairly consistent with its probe effect. Other tools 
are not nearly as nice. What this means is that you will see a marked 
degredation in performance, but measurement numbers will generally be a 
consistent magnifier. So if you use this to look at a comparison of time spent 
in various methods, you can be assured that you are getting a decent metric to 
know where to focus your time.

As a side note, use the JVMTI version whenever possible - it is far less 
intrusive. Also, if you don''t need to time methods (like looking at 
allocations), then don''t specify the '':all''. Method
entry and return are the
most painful for dvm.

Thanks,

Jarod