Background
Recently, I was briefed on a situation where a main public facing java web application was going down fairly regularly, for what appeared to be an out of memory error.
After an investigation by a previous developer turned up no concrete leads, they suggested using JStack to get a profile of what the threads in the application were holding locks that could be causing the crash.
Now I’ve never worked with JStack before, but the purpose seems fairly straightforward. Trouble is, with ~500 threads in the output, analysing each one to find a common cause would be a pretty intensive task.
I set about searching for some kind of output analyser for JStack, but with no luck, I decided to write my own to give me a summary of the results.
Requirements
At least for my application, there were a lot of similar-looking stacktraces, so it made sense to group and summarise the results.
The JStack output I was provided with looked something like this:
Attaching to process ID 18526, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 1.5.0_14-b03
Thread t@6872: (state = BLOCKED)
- java.lang.Thread.sleep(long) @bci=-1766132960 (Interpreted frame)
- java.lang.Thread.sleep(long) @bci=0 (Interpreted frame)
- sun.net.www.http.KeepAliveCache.run() @bci=3, line=149 (Interpreted frame)
- java.lang.Thread.run() @bci=11, line=595 (Interpreted frame)
Thread t@6871: (state = BLOCKED)
- java.lang.Object.wait(long) @bci=0 (Compiled frame; information may be imprecise)
- java.util.TimerThread.mainLoop() @bci=201, line=509 (Compiled frame)
- java.util.TimerThread.run() @bci=1, line=462 (Interpreted frame)
What I initially wanted from my parser was to:
- See the total number of thread states
- Summary information for each stacktrace.
So what I need to do is extract each thread and its corresponding stacktrace to be able to process and report on it.
The Code
Firstly the main checks for a file parameter, then passes to the application instance which will check for its existence before calling a parser.
public class ParseJStack {
public ParseJStack(final String filename) {
File jstackFile = new File(filename);
if (!jstackFile.exists()) {
System.out.println("File does not exist. Exiting.");
return;
}
//new Parser(jstackFile).process();
}
public static void main(String[] args) {
if (args.length < 1) {
System.out.println("Program requires a filename");
System.exit(1);
} else {
new ParseJStack(args[0]);
}
}
}
For now, the call to the parser is commented out, as I’m yet to create it or determine its return type.
Test-driven
Now that I’m thinking about main functionality of the application, I’ll write testcases (JUnit 4) around the container classes JStackMeta and JStackEntry which are the thread detail and stacktrace objects respectively, and will be populated by the parser engine
JStackEntry will be a fairly simple container for a List of stack calls, and a String for its header text. From the looks of it the thread headers all follow the same pattern, so I will expect to be able to extract the state (and the id if we need to later) with a simple regex pattern.
public class JStackEntryTest {
@Test
public void shouldGetContentsAsNotNullWhenNullParameter() throws Exception {
final JStackEntry stackEntry = new JStackEntry("");
Assert.assertNotNull(stackEntry.getContents());
}
@Test
public void shouldGetContents() throws Exception {
final JStackEntry stackEntry = new JStackEntry("");
stackEntry.append("Test Content");
Assert.assertEquals(12, stackEntry.getContents().length());
Assert.assertEquals("Test Content", stackEntry.getContents().toString());
}
@Test
public void shouldGetEntryState() throws Exception {
final JStackEntry stackEntry = new JStackEntry("Thread t@6872: (state = BLOCKED)");
stackEntry.append("Test Content");
Assert.assertEquals("BLOCKED", stackEntry.getState());
}
@Test
public void shouldGetUnknownStateWhenHeaderEmpty() throws Exception {
final JStackEntry stackEntry = new JStackEntry("");
stackEntry.append("Test Content");
Assert.assertEquals("UNKNOWN", stackEntry.getState());
}
}
JStackMeta will hold the collection of JStackEntry objects, and the non-entry related meta (e.g. process id, java version info that appears at the top of the file).
public class JStackMetaTest {
@Test
public void testConstructorInit() throws Exception {
Assert.assertNotNull(new JStackMeta().getHeader());
Assert.assertNotNull(new JStackMeta().getEntries());
}
@Test
public void testAppend() throws Exception {
final JStackMeta stackMeta = new JStackMeta();
stackMeta.append("Test Meta");
Assert.assertEquals(9, stackMeta.getHeader().length());
}
@Test
public void testAddEntry() throws Exception {
final JStackMeta stackMeta = new JStackMeta();
final JStackEntry stackEntry = new JStackEntry("");
stackEntry.append("Test Entry");
stackMeta.addEntry(stackEntry);
Assert.assertEquals(1, stackMeta.getEntries().size());
}
}
With those two classes set, we move back to the JStackParser which populates them. It’ll take the File handle provided by the application object, read in the contents and store them a JStackMeta and its JStackEntry objects. To test this class I created a test.jstack file (which is the same content as the example at the top of this post).
public class ParserTest {
@Test
public void testProcess() throws Exception {
final URL resource = getClass().getResource("test.jstack");
final File file = new File(resource.getFile());
final JStackMeta stackMeta = new Parser(file).process();
Assert.assertEquals(132, stackMeta.getHeader().length());
Assert.assertEquals(2, stackMeta.getEntries().size());
}
}
The actual parsing function looks like this (note that I’ve decided that it is important to keep the newlines in the stack trace to simplify the output):
/**
* Process the JStack output file and extract the data into a {@link JStackMeta} object.
*
* @return The {@link JStackMeta} object representing the JStack output.
*/
public JStackMeta process() {
_meta = new JStackMeta();
try {
FileInputStream inputStream;
inputStream = new FileInputStream(_file);
BufferedReader in = new BufferedReader(new InputStreamReader(inputStream));
boolean finishedHeader = false;
JStackEntry currentEntry = new JStackEntry("");
String line;
while ((line = in.readLine()) != null)
{
// Skip blanks
if ("".equals(line.trim())) {
continue;
}
line += "\n";
// Check if we're done with the header lines
if (!finishedHeader && line.startsWith("Thread")) {
finishedHeader = true;
}
if (!finishedHeader) {
_meta.append(line);
continue;
}
if (line.startsWith("Thread")) {
currentEntry = new JStackEntry(line);
_meta.addEntry(currentEntry);
} else {
currentEntry.append(line);
}
}
in.close();
} catch (FileNotFoundException e) {
System.out.println("ERROR: File was not found");
} catch (IOException e) {
System.out.println("ERROR: A problem occurred");
e.printStackTrace();
}
return _meta;
}
Reporting
The last part of the application is a simple analysis of the JStackMeta object and reporting the statistics. As per the requirements, I want two parts to this, the totals for the different states and the single-line summary with counts.
For the purposes of a quick solution, I’m writing the output to the console. I’ll make a Report interface, just in case I get inspired and write some other implementation to report to a text or HTML file..
I’ll use two maps to keep track of the totals – one map for the status counts and one for the line summary totals. To keep the second part looking organised, I’ll use a TreeMap so that the entries remain sorted.
public interface Report {
void buildReport(JStackMeta stackMeta);
}
public class ConsoleReport implements Report {
public void buildReport(final JStackMeta stackMeta) {
Map<String, Integer> stateCountMap = new HashMap<String, Integer>();
Map<String, Integer> messageCountMap = new TreeMap<String, Integer>(); // Sorted
// Report on results
for (int i = 0; i < stackMeta.getEntries().size(); i++) {
JStackEntry entry = stackMeta.getEntries().get(i);
final String state = entry.getState();
final Integer count;
if (stateCountMap.containsKey(state)) {
count = stateCountMap.get(state) + 1;
} else {
count = 1;
}
stateCountMap.put(state, count);
final StringBuilder contents = entry.getContents();
final String strStackEnd;
if (contents.length() != 0) {
strStackEnd = "(" + state + ") " + contents.substring(0, contents.indexOf("\n"));
} else {
strStackEnd = "(" + state + ") " + "[No stacktrace]";
}
final Integer countMessage;
if (messageCountMap.containsKey(strStackEnd)) {
countMessage = messageCountMap.get(strStackEnd) + 1;
} else {
countMessage = 1;
}
messageCountMap.put(strStackEnd, countMessage);
}
// State counts
for (Map.Entry<String, Integer> entry : stateCountMap.entrySet()) {
System.out.println(entry.getValue() + " threads at " + entry.getKey());
}
System.out.println("\n");
// Message counts
for (Map.Entry<String, Integer> entry : messageCountMap.entrySet()) {
System.out.println(entry.getValue() + "\tthreads at " + entry.getKey());
}
}
}
(I may have gotten lazy here and neglected some unit test coverage- but with the report being written to console its fairly easy to eyeball bugs, right??)
With the Parser and report classes implemented, I can update the code in ParseJStack with a call to the parser and report:
...
final JStackMeta stackMeta = new Parser(jstackFile).process();
final Report report = new ConsoleReport();
report.buildReport(stackMeta);
...
Finally
The end result of this analysis is being able to see an overview of the JStack results, which may give some indication of where to start looking for problems with the application.
39 threads at IN_NATIVE
503 threads at BLOCKED
1 threads at (BLOCKED) - com.sun.appserv.util.cache.BaseCache.incrementMissCount() @bci=6, line=864 (Compiled frame; information may be imprecise)
3 threads at (BLOCKED) - java.io.ByteArrayOutputStream.write(byte[], int, int) @bci=71, line=95 (Interpreted frame)
2 threads at (BLOCKED) - java.io.FileInputStream.readBytes(byte[], int, int) @bci=0 (Compiled frame; information may be imprecise)
1 threads at (BLOCKED) - java.lang.Object.hashCode() @bci=0 (Compiled frame; information may be imprecise)
4 threads at (BLOCKED) - java.lang.Object.wait(long) @bci=-1749045981 (Interpreted frame)
195 threads at (BLOCKED) - java.lang.Object.wait(long) @bci=-1749046076 (Interpreted frame)
...
As you can see we’re interested in seeing the counts for the end frames of the threads, and the state that they are in at this point.
This will at least give an opportunity to where the majority of the threads are ending up, and from this we might be able to gain some insight on what these threads are waiting on (e.g. by looking up stack traces via the byte code index in the original JStack log)
Next Steps
- It may be of use to include a little bit more of the stacktrace in the comparison and output – I noticed that some taces would end on the frame with the same byte code index, but their full stacks would vary slightly.
- As mentioned, it might be useful to write the report out to a file, such as a text or HTML file.
References
The Coding Bone 