Jaroslav Bachorik
|
Posted: August 25, 2010 14:45 by Jaroslav Bachorik
|
|
See http://kenai.com/jira/browse/BTRACE-50 For the purposes of providing real-time performance metrics to the VisualVM Tracer it became necessary to have the infrastructure for capturing the method runtime metrics in very compact and efficient way. Currently, an aggregation would be used to obtain such data. The problem is that at least 4 aggregations would be necessary to track invocation count, total time, min and max - this leading to huge performance impact. Not even mentioning that it is impossible to calculate a method self time (time spent within a method minus the time spent in the methods it called). Because of this a new entity was created - a Profiler. Profiler basically tracks the enter/exit events to a particular code block and assigns the duration to it. It is aware of the call tree so it can calculate the self time as well as not counting the time spent in callees during recursive processing. A profiler can be exposed as a @Property as well as a snapshot can be made and printed via printSnapshot() method. All the methods related to profiling are placed in BTraceUtils.Profiling namespace. An example of a real-life usage:
package com.sun.tools.visualvm.modules.tracer.swing.resources;
import com.sun.btrace.Profiler;
import com.sun.btrace.annotations.*;
import static com.sun.btrace.BTraceUtils.*;
@BTrace(name="SwingStats") public class SwingTracer {
// <fragment name="swing_paint">
@Property(name="jcPaintProfiler") private static Profiler jcPaintProfiler = Profiling.newProfiler(3);
@OnMethod(
clazz="+javax.swing.JComponent",
method="/paint(Component|Border|Children)/"
)
public static void componentPaintBefore(@ProbeMethodName String pmn) {
Profiling.recordEntry(jcPaintProfiler, pmn);
}
@OnMethod(
clazz="+javax.swing.JComponent",
method="/paint(Component|Border|Children)/",
location=@Location(Kind.RETURN)
)
public static void componentPaintAfter(@Duration long time, @ProbeMethodName String pmn) {
Profiling.recordExit(jcPaintProfiler, pmn, time);
}
// </fragment>
// <fragment name="componentui">
@Property(name="cuiProfiler") private static Profiler cuiProfiler = Profiling.newProfiler(5);
@OnMethod(
clazz="+javax.swing.plaf.ComponentUI",
method="/(paint|update|getPreferredSize|getMinimumSize|getMaximumSize)/")
public static void cuPaintEntry(@ProbeMethodName String pmn) {
Profiling.recordEntry(cuiProfiler, pmn);
}
@OnMethod(
clazz="+javax.swing.plaf.ComponentUI",
method="/(paint|update|getPreferredSize|getMinimumSize|getMaximumSize)/",
location=@Location(Kind.RETURN))
public static void cuPaintExit(@Duration long time, @ProbeMethodName String pmn) {
Profiling.recordExit(cuiProfiler, pmn, time);
}
// </fragment>
// <fragment name="component_events">
@Property(name="jcEventsProfiler") private static Profiler jcEventsProfiler = Profiling.newProfiler(10);
@OnMethod(
clazz="+java.awt.Component",
method="/process(Component|Focus|Key|Mouse|MouseMotion|MouseWheel|InputMethod|Hierarchy)Event/"
)
public static void componentEventBefore(@ProbeMethodName String pmn) {
Profiling.recordEntry(jcEventsProfiler, pmn);
}
@OnMethod(
clazz="+java.awt.Component",
method="/process(Component|Focus|Key|Mouse|MouseMotion|MouseWheel|InputMethod|Hierarchy)Event/",
location=@Location(Kind.RETURN)
)
public static void componentEventsAfter(@Duration long time, @ProbeMethodName String pmn) {
Profiling.recordExit(jcEventsProfiler, pmn, time);
}
// </fragment>
// <fragment name="basic_events">
@Property(name="eventsProfiler") private static Profiler eventsProfiler = Profiling.newProfiler(3);
@OnMethod(
clazz="+java.awt.event.ActionListener",
method="actionPerformed")
public static void apEntry(@ProbeMethodName String pmn) {
Profiling.recordEntry(eventsProfiler, pmn);
}
@OnMethod(
clazz="+java.awt.event.ActionListener",
method="actionPerformed",
location=@Location(Kind.RETURN))
public static void apExit(@Duration long time, @ProbeMethodName String pmn) {
Profiling.recordExit(eventsProfiler, pmn, time);
}
@OnMethod(
clazz="+javax.swing.event.ChangeListener",
method="stateChanged")
public static void scEntry(@ProbeMethodName String pmn) {
Profiling.recordEntry(eventsProfiler, pmn);
}
@OnMethod(
clazz="+javax.swing.event.ChangeListener",
method="stateChanged",
location=@Location(Kind.RETURN))
public static void scExit(@Duration long time, @ProbeMethodName String pmn) {
Profiling.recordExit(eventsProfiler, pmn, time);
}
@OnMethod(
clazz="+java.beans.PropertyChangeListener",
method="propertyChange")
public static void pcEntry(@ProbeMethodName String pmn) {
Profiling.recordEntry(eventsProfiler, pmn);
}
@OnMethod(
clazz="+java.beans.PropertyChangeListener",
method="propertyChange",
location=@Location(Kind.RETURN))
public static void pcExit(@Duration long time, @ProbeMethodName String pmn) {
Profiling.recordExit(eventsProfiler, pmn, time);
}
// </fragment>
// <fragment name="layout">
@Property(name="layoutProfiler") private static Profiler layoutProfiler = Profiling.newProfiler(3);
@OnMethod(
clazz="+java.awt.LayoutManager",
method="/(preferredLayoutSize|minimumLayoutSize|layoutContainer)/")
public static void layoutEntry(@ProbeMethodName String pmn) {
Profiling.recordEntry(layoutProfiler, pmn);
}
@OnMethod(
clazz="+java.awt.LayoutManager",
method="/(preferredLayoutSize|minimumLayoutSize|layoutContainer)/",
location=@Location(Kind.RETURN))
public static void layoutExit(@Duration long time, @ProbeMethodName String pmn) {
Profiling.recordExit(layoutProfiler, pmn, time);
}
// </fragment>
@OnTimer(1000)
public static void updateMBeans() {
// <fragment name="swing_paint">
Profiling.snapshotAndReset(jcPaintProfiler);
// </fragment>
// <fragment name="componentui">
Profiling.snapshotAndReset(cuiProfiler);
// </fragment>
// <fragment name="component_events">
Profiling.snapshotAndReset(jcEventsProfiler);
// </fragment>
// <fragment name="basic_events">
Profiling.snapshotAndReset(eventsProfiler);
// </fragment>
// <fragment name="layout">
Profiling.snapshotAndReset(layoutProfiler);
// </fragment>
}
}
|
BTrace profiling support
Replies: 9 - Last Post: March 07, 2011 09:02
by: Jaroslav Bachorik
by: Jaroslav Bachorik
showing 1 - 10 of 10
Jaroslav Bachorik
|
Posted: August 25, 2010 15:38 by Jaroslav Bachorik
|
| Of course, available in the dev build |
joachimhskeie
|
Posted: August 25, 2010 20:50 by joachimhskeie
|
| Now this looks really interesting!! I will be sure to check out this feature from the dev build!! |
joachimhskeie
|
Posted: August 27, 2010 22:01 by joachimhskeie
|
|
Hello JB, Having tried out this functionality a bit I find it an extremely valluable addition to BTrace. I am currently replacing my Aggregations with the Profiler for all my class instrumentation and time-measuring. One question though, what is the difference between self time and wall time ? |
Jaroslav Bachorik
|
Posted: August 28, 2010 08:32 by Jaroslav Bachorik
|
| Wall time means the time spent in a method, including also time spent in all methods called from the measured method. On the other hand the self time compensates for the time spent in subsequent method calls (only the tracked ones) and hence it gives you the time spend in the methods code only. |
devangini
|
Posted: March 05, 2011 13:48 by devangini
|
|
I am new to BTrace. I wanted to know if there is something special with the names of these action methods and how these probe points are associated with the action methods. Is it like: btrace-class{ probe point -1 action method code -1 probe point -2 action method code -2 .... probe point -n action method code -n } |
Jaroslav Bachorik
|
Posted: March 07, 2011 09:02 by Jaroslav Bachorik
|
|
I would recommend reading the user guide first. But shortly - in its simplest form the probe point is defined by the java annotation placed on the action method. |
m_hess
|
Posted: August 26, 2010 06:29 by m_hess
|
|
I am somewhat confused about how this relates to the Aggregation. What's the difference (feature wise) between the Aggregation and the Profiler? Is the Profiler meant to replace the Aggregation completely? It would be great if you could shed some more light on this, Jaroslav. bye, Michael |
Jaroslav Bachorik
|
Posted: August 26, 2010 09:22 by Jaroslav Bachorik
|
|
Well, the profiler is a highly specialized kind of aggregation. It can take only one key and calculates only the preset (and inevitable) runtime metrics. On the other hand the Aggregations support is really flexible when it comes to various statistics and custom keys. The price for that is pretty high overhead for adding the measured values to aggregations and the inability to compensate for nested method calls without another expensive operations like storing the execution flow in a stack, for example. So, the profiler is not meant to be a replacement for aggregations - rather a complement. You would use it for capturing the method level runtime metrics (invocations, total self time, avg self time, min self time, max self time, total wall time, avg wall time, min wall time, max wall time) and obtaining the application CPU performance profile only. Aggregations would be used for anything else. Using the profiler instead of multiple aggregations in the VisualVM Tracer probes I was able to cut down the instrumentation overhead cca. 6 times down to 1700ns for entry/exit pair (it used to be more than 10000ns before) so the benefit is obvious. |
showing 1 - 10 of 10
Replies: 9 - Last Post: March 07, 2011 09:02
by: Jaroslav Bachorik
by: Jaroslav Bachorik









