Logging a unique ID for every request using log4j

I wanted to assign a unique ID to web requests in my application so that I could easily differentiate between different requests when looking at my logs.

My log4j conversion pattern (or format) looked like this:

%d{ISO8601} [%t] %p %c - %m%n


  • %d{ISO8601}: Timestamp using log4j’s ISO8601DateFormat
  • %t: Thread name
  • %p: Priority (eg DEBUG, INFO, etc)
  • %c: Category (in my code I’m using the class as category)
  • %m: Message
  • %n: Line break

I added a custom field:

%d{ISO8601} [%t] %p %c %X{requestId} - %m%n

Using my RandomIdGenerator class, I added this interceptor:

public boolean preHandle(
        HttpServletRequest request,
        HttpServletResponse response, Object handler) {
    String requestId = RandomIdGenerator.base32(4);
    MDC.put("requestId", requestId);
    return true;

I now get output like this in my log:

2013-06-21 10:01:49,178 [http-443-4] INFO com.boxjar.web.AuthenticationInterceptor YDXT5PI - User box authenticated successfully.
2013-06-21 10:01:49,182 [http-443-4] DEBUG com.boxjar.logic.DomainService YDXT5PI - Saved changes to contract 154.

I wish everything was this easy!

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


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


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.


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.



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