Tracing method calls in Java

Mark Triggs <mark@teaspoon-consulting.com>

Founder & Expert Button Pusher of Teaspoon Consulting

This article shows a quick way of seeing how the methods in a Java program are called. It's a useful trick for getting a bird's eye view of how requests are handled in an unfamiliar web application.

Sometimes I'll be debugging an unfamiliar web application and not be sure where to start. With all of their indirection, inversion of control and dependency injection, some Java webapps do a great job of obscuring where the action actually happens.

At particularly low moments I've even resorted to firing up a debugger, setting a breakpoint on the servlet container itself, and then single-stepping the whole way through until I hit an application class. That works, but it's pretty tedious and feels bad for the soul.

Using jdb

A better approach is to connect to the JVM with the jdb program and trace all of the methods called by the thread handling our request, giving us a neat log of everything that happened between request and response. Armed with this information, we'll have some idea of where in the code to look—or at least, where to next point the debugger.

Warning: Don't try this in production! What we'll do here will cause the JVM to stop responding. Dev machines only, please.

To get started, you will need to add some switches to your java command-line:

 -Xdebug
 -Djava.complier=NONE
 -Xrunjdwp:transport=dt_socket,server=y,suspend=n,address=5000

These tell Java to start a debug server listening on port 5000. If you're using Tomcat, you can add these switches to the JAVA_OPTS environment variable in your bin/setenv.sh file.

Start your application running, then open a terminal. We'll start jdb running and tell it to attach to our JVM. The jdb utility ships with Java, so you should already have it:

 $ jdb -attach localhost:5000
 Set uncaught java.lang.Throwable
 Set deferred uncaught java.lang.Throwable
 Initializing jdb ...
 >

With jdb running, we can set a breakpoint on the outermost method we know about. For Tomcat, the org.apache.catalina.connector.CoyoteAdapter.service will do fine: it's called by Tomcat just prior to handing a web request to your application. If you're using a different servlet container you'll need to use a different method, but looking at a stack trace from your application should give some clues about what will work.

On with the show! Set the breakpoint:

 > stop in org.apache.catalina.connector.CoyoteAdapter.service
 Set breakpoint org.apache.catalina.connector.CoyoteAdapter.service

and now hit the web application from your browser. You should see:

The browser sit there spinning; and

A message in your jdb window like:

 Breakpoint hit: "thread=http-bio-7575-exec-25", org.apache.catalina.connector.CoyoteAdapter.service(), line=366 bci=0

So we can see that the thread handling our request (http-bio-7575-exec-25 in this case) hit the breakpoint and has been paused. Good.

We need one more piece of information about this thread: its ID. We can get that from jdb by typing threads and looking for the thread name we just saw:

 http-bio-7575-exec-25[1] threads
   [... lots of stuff ...]
 Group main:
   [... lots of stuff ...]
   (org.apache.tomcat.util.threads.TaskThread)0x9380    http-bio-7575-exec-25    running (at breakpoint)

Note: http-bio-7575-exec-25[1] will be our jdb prompt from now on—yours may be different.

That 0x9380 is the ID of the thread. We can feed this to the trace command, which will cause all methods called by our blocked thread to be logged. Here's what we do:

 http-bio-7575-exec-25[1] trace go methods 0x9380

That's instructed jdb to start tracing method calls for our thread. Now we just need to unpause it with the cont command:

 http-bio-7575-exec-25[1] cont
 > Method entered: "thread=http-bio-7575-exec-25", org.apache.coyote.Request.getNote(), line=473 bci=0
 Method exited: return value = instance of org.apache.catalina.connector.Request(id=37831), "thread=http-bio-7575-exec-25", org.apache.coyote.Request.getNote(), line=473 bci=6
 Method entered: "thread=http-bio-7575-exec-25", org.apache.coyote.Response.getNote(), line=162 bci=0
 Method exited: return value = instance of org.apache.catalina.connector.Response(id=37832), "thread=http-bio-7575-exec-25", org.apache.coyote.Response.getNote(), line=162 bci=6
 Method entered: "thread=http-bio-7575-exec-25", org.apache.catalina.connector.Connector.getXpoweredBy(), line=829 bci=0
 Method exited: return value = false, "thread=http-bio-7575-exec-25", org.apache.catalina.connector.Connector.getXpoweredBy(), line=829 bci=4
 Method entered: "thread=http-bio-7575-exec-25", org.apache.coyote.Request.getRequestProcessor(), line=520 bci=0
 Method exited: return value = instance of org.apache.coyote.RequestInfo(id=37833), "thread=http-bio-7575-exec-25", org.apache.coyote.Request.getRequestProcessor(), line=520 bci=4
 [... lots of stuff ...]

and we're off to the races! Your terminal should fill up with two lines for every method call made to handle your request.

So, that's a very small introduction into some of the things that jdb can do for you. It's not the most sophisticated debugger in the world, but it's pretty straightforward and available almost everywhere. Happy debugging!