Who is calling this method?

July 3, 2013 by Kristjan Reinloo

Have you ever stood in front of a piece of code and wondered why it behaves the way it does. And wished you had the information about the possible locations from which this method was invocated. Back in the old times it might have been easy – static code analysis could have given you the answer. But nowadays when we have reflection and bytecode modification tooling at hand the answer is often not so simple.

Well, we have lived with the same problem for a long time. In Plumbr we are making your lives easier by surfacing the sources of the problems. As a sample – when you happen to have a memory leak in your application, we tell you where the leaking objects are created. Down to the line in source code where the object was created. But we have not been able to hand over the whole call stack so far – it is just too expensive to gather this information during the application runtime.

But there is a very nice tool available just for the task at hand called BTrace. This is a dynamic tracing tool which you can attach to your Java process during runtime to acquire a call stack and then disconnect when you have acquired the information you needed. Btrace dynamically instruments the class bytecode in the target application in order to inject tracing code. You can use the same tool for other amazing purposes, but for the sake of clarity, lets just stick with this feature.

Lets go through a case study using the very same leak report acquired from Plumbr demo application. From the leak report below, we can see that something fishy is happening at the line 27 in the LeakingInterceptor class preHandle() method.

Call stack screenshot

When exploring the source code, we can see that a new ImageEntry instance is created in the line 27:

lastUsedImages.add(new ImageEntry(image));

To get the full stack trace of this situation, we have to give a hint to BTrace about what to monitor in our source code. We do this in a form a small Java class, which will print out the entire stack trace every time a new instance of ImageEntry is created. Code for this is rather straightforward as you see:

import com.sun.btrace.annotations.*;
import static com.sun.btrace.BTraceUtils.*;
@BTrace
class LeakStack {
   @OnMethod(clazz="org.springframework.samples.petclinic.web.ImageEntry", method="<init>")
   public void printStack() {
      Threads.jstack();
      println("");
   }
}

The printStack() function is executed every time when a new ImageEntry instance is created. The mapping is in the annotations which specify the class and the method to monitor. And as you might recall from your bytecode classes, “<init>” denotes the constructor.

Now, hopefully you have managed to download the BTrace and it’s time to start the demo application (run “start.sh” to start the application and “create_usage.sh” script to generate usage). After that we can find out the PID of our demo application with the help of “jps” command.

In order to run btrace executable (found in $BTRACE_ROOT/bin/ folder), we have to specify the PID of our application and our desired script.

$ ./btrace <PID_OF_DEMO_APP> LeakStack.java

After that, we should get stack traces printed out to our console similar to the following:

org.springframework.samples.petclinic.web.LeakingInterceptor.preHandle(LeakingInterceptor.java:27)
org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:891)
org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:827)
org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:882)
org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:778)
javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:547)
org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1359)
org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:77)
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1330)
org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:478)
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:119)
org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:483)
org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:227)
org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:941)
org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:409)
org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:186)
org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:875)
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:117)
org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:250)
org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:149)
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:110)
org.eclipse.jetty.server.Server.handle(Server.java:345)
org.eclipse.jetty.server.HttpConnection.handleRequest(HttpConnection.java:441)
org.eclipse.jetty.server.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:919)
org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:582)
org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:218)
org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:51)
org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:586)
org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:44)
org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:598)
org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:533)
java.lang.Thread.run(Thread.java:722)

And we have successfully acquired the full call stack from the running application. Those of you who are now confused and worried that running Plumbr is complex – dont stress yourself. Out of the thousands of leaks we have discovered, less than ten were complex enough to hunt down without the full call stack. Plus – our RnD is working to improve our solution to the extent where you do not need to go through such tricky exercises. They just need a bit more time. And maybe a little bit of inspiration as well.

If you managed to read past this last call stack, you are definitely going to enjoy our future posts. So subsribe to our RSS feed or follow us in Twitter and stay tuned.

Can't figure out what causes your OutOfMemoryError? Read more

ADD COMMENT

COMMENTS

Your posts are always very interesting. Thanks.

In your second last paragraph, you say “Out of the thousands of leaks we have discovered, less than ten were complex enough to hunt down without the full call stack.”. I think you may want to revisit the wording. As is, it is not much of an endorsement for Plumbr. :)

Rob

Thanks for pointing it out. Rephrased our intentions in a (hopefully) more meaningful way.

Ivo Mägi

Can't figure out what causes your OutOfMemoryError? Read more

Latest
Recommended
You cannot predict the way you die
When debugging a situation where systems are failing due to the lack of resources, you can no longer count on anything. Seemingly unrelated changes can trigger completely different messages and control flows within the JVM. Read more
Tuning GC - it does not have to be that hard
Solving GC pauses is a complex task. If you do not believe our words, check out the recent LinkedIn experience in garbage collection optimization. It is a complex and tedious task, so we are glad to report we have a whole lot simpler solution in mind Read more
Building a nirvana
We have invested a lot into our continuous integration / delivery infrastructure. As of now we can say that the Jenkins-orchestrated gang consisting of Ansible, Vagrant, Gradle, LiveRebel and TestNG is something an engineer can call a nirvana. Read more
Creative way to handle OutOfMemoryError
Wish to spend a day troubleshooting? Or make enemies among sysops? Registering pkill java to OutOfMemoryError events is one darn good way to achieve those goals. Read more