Time taken to execute all methods in a method stack

Question

A lot of times while writing applications, I wish to profile and measure the time taken for all methods in a stacktrace. What I mean is say:

Method A --> Method B --> Method C ...

A method internally calls B and it might call another. I wish to know the time taken to execute inside each method. This way in a web application, I can precisely know the percentage of time being consumed by what part of the code.

To explain further, most of the times in spring application, I write an aspect which collects information for every method call of a class. Which finally gives me summary. But I hate doing this, its repetitive and verbose and need to keep changing regex to accommodate different classes. Instead I would like this:

@Monitor
public void generateReport(int id){
...
}

Adding some annotation on method will trigger instrumentation api to collect all statistics of time taken by this method and any method later called. And when this method is exited, it stops collection information. I think this should be relatively easy to implement.

The questions is: Are there any reasonable alternatives that lets me do that for general java code? Or any quick way of collection this information. Or even a spring plugin for spring applications?

PS: Exactly like XRebel, it generates beautiful summaries of time take by the security, dao, service etc part of code. But it costs a bomb. If you can afford, you should definitely buy it.

Answer 1

You want to write a Java agent. Such an agent allows you to redefine a class when it is loaded. This way, you can implement an aspect without polluting your source code. I have written a library, Byte Buddy, which makes this fairly easy.

For your monitor example, you could use Byte Buddy as follows:

new AgentBuilder.Default()
 .rebase(declaresMethod(isAnnotatedWith(Monitor.class))
 .transform( (builder, type) ->
   builder
     .method(isAnnotatedWith(Monitor.class))
     .intercept(MethodDelegation.to(MonitorInterceptor.class);
  );

class MonitorInterceptor {
  @RuntimeType
  Object intercept(@Origin String method,
                                @SuperCall Callable<?> zuper)
      throws Exception {
    long start = System.currentTimeMillis();
    try {
       return zuper.call();
     } finally {
       System.out.println(method + " took " + (System.currentTimeMillis() - start);
     }
   }
}

The above built agent can than be installed on an instance of the instrumentation interface which is provided to any Java agent.

As an advantage over using Spring, the above agent will work for any Java instance, not only for Spring beans.

Answer 2

I don't know if theres already a library doing it nor can I give you a ready to use code. But I can give you a description how you can implement it on your own.

First of all i assume its no problem to include AspectJ into your project. Than create an annotation f.e. @Monitor which acts as marker for the time measurment of whatever you like. Than create a simple data strucutre holding the information you wana track. An example for this could be the following :

public class OperationMonitoring {
    boolean active=false;
    List<MethodExecution> methodExecutions = new ArrayList<>();
}

public class MethodExecution {
    MethodExcecution invoker;
    List<MethodExeuction> invocations = new ArrayList<>();
    long startTime;
    long endTime;
}

Than create an Around advice for all methods. On execution check if the called Method is annotated with your Monitoring annotation. If yes started monitoring each method execution in this thread. A simple example code could look like:

@Aspect
public class MonitoringAspect {

    private ThreadLocal<OperationMonitoring> operationMonitorings = new ThreadLocal<>();

    @Around("execution(* *.*(..))")
    public void monitoring(ProceedingJoinPoint pjp) {  
        Method method = extractMethod(pjp);
        if (method != null) {
            OperationMonitoring monitoring = null;
            if(method.isAnnotationPresent(Monitoring.class){
                 monitoring = operationMonitorings.get();
                 if(monitoring!=null){
                     if(!monitoring.active) {
                          monitoring.active=true;
                     }
                 } else {
                     // Create new OperationMonitoring object and set it
                 }
            }
            if(monitoring == null){
                 // this method is not annotated but is the tracking already active?
                 monitoring = operationMonitoring.get();
            }
            if(monitoring!=null && monitoring.active){
               // do monitoring stuff and invoke the called method
            } else {
               // invoke the called method without monitoring
            }
            // Stop the monitoring by setting monitoring.active=false if this method was annotated with Monitoring (and it started the monitoring).
        }
    }


    private Method extractMethod(JoinPoint joinPoint) {
         if (joinPoint.getKind().equals(JoinPoint.METHOD_EXECUTION) && joinPoint.getSignature() instanceof MethodSignature) {
              return ((MethodSignature) joinPoint.getSignature()).getMethod();
         }
         return null;
    }
}

The code above is just a how to. I would also restructure the code but I've written it in a textfield, so please be aware of architectural flaws. As mentioned with a comment at the end. This solution does not supporte multiple annotated methods along the way. But it would be easy to add this. A limitation of this approach is that it fails when you start additional threads during a tracked path. Adding support for starting new threads in a monitored Thread is not that easy. Thats also the reason why IoC frameworks have own features for handling threads to be able to track this.

I hope you understand the general concept of this, if not feel free to ask further questions.

Answer 3

This is the exact reason why I built the open source tool stagemonitor, which uses Byte Buddy to insert profiling code. If you want to monitor a web application you don't have to alter or annotate your code. If you have a standalone application, there is a @MonitorRequests annotation you can use.

Answer 4

You say you want to know the percentage of time taken within each routine on the stack.

I assume you mean inclusive time.

I also assume you mean wall-clock time, on the theory that if one of those lower-level callees happens to do some I/O, locking, etc., you don't want to be blind to that.

So a stack-sampling profiler that samples on wall-clock time will be getting the right kind of information.

The percentage time that A takes is the percentage of samples containing A, same for B, etc.

To get the percentage of A's time used by B, it is the percentage of samples containing A that happen to have B at the next level below.

The information is all in the stack samples, but it may be hard to get the profiler to extract just the information you want.

You also say you want precise percentage. That means you also need a large number of stack samples. For example, if you want to shrink the uncertainty of your measurements by a factor of 10, you need 100 times as many samples.

In my experience finding performance problems, I am willing to tolerate an uncertainty of 10% or more, because my goal is to find big wastage, not to know with precision how bad it is. So I take samples manually, and look at them manually. In fact, if you look at the statistics, you only have to see something wasteful on as few as two samples to know it's bad, and the fewer samples you take before seeing it twice, the worse it is. (Example: If the problem wastes 30% of time, it takes on average 2/30% = 6.67 samples to see it twice. If it wastes 90% of time, it only takes 2.2 samples, on average.)