Naming Java threads

Naming the threads in a Java application is good practice as the default name given by a default thread pool looks like this: pool-x-thread-y.

Here is a simple implementation of a named thread factory:

public class NamedThreadFactory implements ThreadFactory {

    private final AtomicInteger threadIndex = new AtomicInteger(0);

    private final String name;

    public NamedThreadFactory(String name) {
        this.name = name;
    }

    @Override
    public Thread newThread(Runnable runnable) {
        Thread thread = new Thread(runnable);
        thread.setName(String.format("%s-%d", name, threadIndex.addAndGet(1)));
        return thread;
    }

}

Use it like this:

ExecutorService threadPool = Executors.newFixedThreadPool(
        numberOfThreads, new NamedThreadFactory("MyUsefulThreadName"));

Using top and jstack to find the Java thread that is hogging the CPU

The *nix command top is a neat tool for getting a quick real-time view of a system. In this post I want to show how it can be used together with jstack to find a Java thread (or lightweight process) that is currently consuming higher than normal CPU resources.

Let’s say we’ve noticed that our application server has been a bit sluggish for some time and we want to have a look at what it’s currently doing. We can use top to list the processes that are running on our box ordered by CPU usage, and filtering on a relevant user, using top -U:

# top -Ubox

top-user

Let’s say we watch top for a little while and notice that the uppermost process, with a process ID (PID) of 26536, is consistently running at an unexpectedly high level of CPU usage.

The percentage is the relative usage of one processor (or core), so for example on a four-core machine the highest number we could observe would be 400%.

We can filter top and show just one specific process with top -p, so let’s have a look at PID 26536:

# top -p26536

top-pid

This is where it gets cool!

Press Shift+H.

This makes top display all lightweight processes, ie threads, that are currently running in the parent process. Listing them is not instantaneous, though, they appear one by one with a second or two inbetween. In this case there were 80 threads, and it took almost two minutes to get them all in listed.

top-lwp

Ok, so looking at this, it seems the lightweight process with PID 29711 is of particular interest. How do we find out what it’s currently doing?

Let’s convert the decimal PID into hexadecimal. 29711 corresponds to 0x740F:

Thread ID in hex

So armed with the hexadecimal thread ID we can use jstack and have a look at the stack trace of that thread:

bash$ /usr/java/jdk1.6.0_26/bin/jstack 26536 |less

When using less we can press / (forward slash) and type in the hexadecimal number to search the output for the thread ID.

Bingo!

[...]

"TP-Processor31" daemon prio=10 tid=0x00002b1e4cb77000 nid=0x740f runnable [0x00002b1e5255f000]
 java.lang.Thread.State: RUNNABLE
 at java.net.SocketInputStream.socketRead0(Native Method)
[...]
 at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
 - locked <0x00000007b79aa940> (a com.mysql.jdbc.util.ReadAheadInputStream)
 at com.mysql.jdbc.CompressedInputStream.readFully(CompressedInputStream.java:296)
[...]
 at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2172)
 at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2696)
 - locked <0x00000007b79a5740> (a java.lang.Object)
 at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2105)
 at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2264)
 - locked <0x00000007b79a5740> (a java.lang.Object)
 at org.apache.tomcat.dbcp.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96)
 at org.apache.tomcat.dbcp.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96)
 at com.boxjar.MyService.doSomething(MyService.java:102)
 at com.boxjar.MyServlet.handleRequest(MyServlet.java:33)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:617)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
[...]
 at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690)
 at java.lang.Thread.run(Thread.java:662)

That’s quite cool – we’ve gone from a high level overview with top to a detailed snapshot of what that particular Java thread is currently doing. In this case it looks it is busy executing a MySQL database query, triggered by a web request. We can also see that the database query is executed by line 102 of the MyService class. Since we know the thread ID we can run jstack a couple more times and see what happens to the execution of the code over time.

This gives us some clues as to what is going on and it might just be enough to work out what part of the application needs a bit of tweaking. It could also be that we need to do some further investigation, in which case we may want to have a look at the web request logs. We could also try and reproduce locally in the IDE and do some debugging. In any case, using just top and jstack we have come a long way!