Tracing method calls in Java
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.
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
-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
environment variable in your
Start your application running, then open a terminal. We'll start
jdb running and tell it to attach to our JVM. The
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 ... >
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
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
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 threads [... lots of stuff ...] Group main: [... lots of stuff ...] (org.apache.tomcat.util.threads.TaskThread)0x9380 http-bio-7575-exec-25 running (at breakpoint)
http-bio-7575-exec-25 will be our
jdb prompt from now
on—yours may be different.
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 trace go methods 0x9380
jdb to start tracing method calls for our thread.
Now we just need to unpause it with the
http-bio-7575-exec-25 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!