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.
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!