Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

#463: Add ability for timeout to print full thread stack dump #768

Closed
wants to merge 1 commit into from
Closed

#463: Add ability for timeout to print full thread stack dump #768

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
89 changes: 83 additions & 6 deletions src/main/java/org/junit/internal/runners/statements/FailOnTimeout.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,8 +1,12 @@
package org.junit.internal.runners.statements;

import java.lang.management.ManagementFactory;
import java.lang.management.ThreadInfo;
import java.lang.management.ThreadMXBean;
import java.util.Arrays;
import java.util.ArrayList;
import java.util.List;
import java.util.Map;
import java.util.Map.Entry;
import java.util.concurrent.Callable;
import java.util.concurrent.ExecutionException;
import java.util.concurrent.FutureTask;
Expand All @@ -17,21 +21,23 @@ public class FailOnTimeout extends Statement {
private final TimeUnit fTimeUnit;
private final long fTimeout;
private final boolean fLookForStuckThread;
private final boolean fFullThreadStackDump;
private ThreadGroup fThreadGroup = null;

public FailOnTimeout(Statement originalStatement, long millis) {
this(originalStatement, millis, TimeUnit.MILLISECONDS);
}

public FailOnTimeout(Statement originalStatement, long timeout, TimeUnit unit) {
this(originalStatement, timeout, unit, false);
this(originalStatement, timeout, unit, false, false);
}

public FailOnTimeout(Statement originalStatement, long timeout, TimeUnit unit, boolean lookForStuckThread) {
public FailOnTimeout(Statement originalStatement, long timeout, TimeUnit unit, boolean lookForStuckThread, boolean fullThreadStackDump) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

IMHO this is far too many parameters. Could we create a Builder for FailOnTimeout and get rid of all of these constructors? See Effective Java, Second Edition, Item 2.

I personally like the style where there is a private constructor that takes in an instance of the Builder.

fOriginalStatement = originalStatement;
fTimeout = timeout;
fTimeUnit = unit;
fLookForStuckThread = lookForStuckThread;
fFullThreadStackDump = fullThreadStackDump;
}

@Override
Expand Down Expand Up @@ -74,18 +80,89 @@ private Exception createTimeoutException(Thread thread) {
currThreadException.setStackTrace(stackTrace);
thread.interrupt();
}

List<Throwable> exceptions = new ArrayList<Throwable>();
exceptions.add(currThreadException);

if (stuckThread != null) {
Exception stuckThreadException =
Exception stuckThreadException =
new Exception ("Appears to be stuck in thread " +
stuckThread.getName());
stuckThreadException.setStackTrace(getStackTrace(stuckThread));
return new MultipleFailureException
(Arrays.<Throwable>asList(currThreadException, stuckThreadException));
exceptions.add(stuckThreadException);
}

// TODO: would it make sense to make this optional, i.e. if stuckThread != null, then skip the full thread dump?
if (fFullThreadStackDump) {
// For the sake of convenience just add the full thread dump directly to the failure message: this can really
// hurt when getting long :-(
Exception fullThreadDumpException = new Exception(
"Appears to be stuck => Full thread dump:\n"
+ getFullThreadDump());
exceptions.add(fullThreadDumpException);
}

if (exceptions.size() > 1) {
return new MultipleFailureException(exceptions);
} else {
return currThreadException;
}
}

private String getFullThreadDump() {
StringBuilder sb = new StringBuilder();

// TODO: ThreadMXBean provides interesting thread dump information (locks, monitors, synchronizers) only with Java >= 1.6
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

style-nit: this should line up with the next comment


// First try ThreadMXBean#findMonitorDeadlockedThreads():
ThreadMXBean threadMxBean = ManagementFactory.getThreadMXBean();
long[] deadlockedThreadIds = threadMxBean.findMonitorDeadlockedThreads();
if (deadlockedThreadIds != null) {
sb.append("Found deadlocked threads:");
ThreadInfo[] threadInfos = threadMxBean.getThreadInfo(deadlockedThreadIds);
for (ThreadInfo threadInfo : threadInfos) {
sb.append("\n\t" + threadInfo.getThreadName() + " Id=" + threadInfo.getThreadId()
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: String format would make this code easy to read.
String.format("\n\t '%s' Id='%s' Lock name='%s' Lock owner Id='%s' Lock owner name='%s'" , threadInfo.getThreadName(), threadInfo.getThreadId(), threadInfo.getLockName(), threadInfo.getLockOwnerId(), threadInfo.getLockOwnerName())

+ " Lock name=" + threadInfo.getLockName() + " Lock owner Id=" + threadInfo.getLockOwnerId()
+ " Lock owner name=" + threadInfo.getLockOwnerName());
}
}

// Then just the full thread dump:
Map<Thread, StackTraceElement[]> allStackTraces = Thread.getAllStackTraces();
sb.append("Thread dump (total threads=" + allStackTraces.size() + ")");
for (Thread thread : allStackTraces.keySet()) {
sb.append("\n\t" + thread.getName());
}
sb.append("\n");
for (Entry<Thread, StackTraceElement[]> threadEntry : allStackTraces.entrySet()) {
sb.append("\n" + threadToHeaderString(threadEntry.getKey()));

StackTraceElement[] stackTraces = threadEntry.getValue();
for (int i = 0; i < stackTraces.length; i++) {
StackTraceElement ste = stackTraces[i];
sb.append("\tat " + ste.toString());
sb.append('\n');
}
}

return sb.toString();
}

private String threadToHeaderString(Thread thread) {
StringBuilder sb = new StringBuilder("\"" + thread.getName() + "\""
+ " Id=" + thread.getId() + " Daemon=" + thread.isDaemon()
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: consider using String.format()

+ " State=" + thread.getState() + " Priority=" + thread.getPriority()
+ " Group=" + thread.getThreadGroup().getName());
if (thread.isAlive()) {
sb.append(" (alive)");
}
if (thread.isInterrupted()) {
sb.append(" (interrupted)");
}
sb.append('\n');
return sb.toString();
}

/**
* Retrieves the stack trace for a given thread.
* @param thread The thread whose stack is to be retrieved.
Expand Down
13 changes: 10 additions & 3 deletions src/main/java/org/junit/rules/Timeout.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,11 +1,11 @@
package org.junit.rules;

import java.util.concurrent.TimeUnit;

import org.junit.internal.runners.statements.FailOnTimeout;
import org.junit.runner.Description;
import org.junit.runners.model.Statement;

import java.util.concurrent.TimeUnit;

/**
* The Timeout Rule applies the same timeout to all test methods in a class:
* <pre>
Expand Down Expand Up @@ -37,6 +37,7 @@ public class Timeout implements TestRule {
private final long fTimeout;
private final TimeUnit fTimeUnit;
private boolean fLookForStuckThread;
private boolean fFullThreadStackDump;

/**
* Create a {@code Timeout} instance with the timeout specified
Expand Down Expand Up @@ -68,6 +69,7 @@ public Timeout(long timeout, TimeUnit unit) {
fTimeout = timeout;
fTimeUnit = unit;
fLookForStuckThread = false;
fFullThreadStackDump = false;
}

/**
Expand Down Expand Up @@ -100,7 +102,12 @@ public Timeout lookForStuckThread(boolean enable) {
return this;
}

public Timeout printFullThreadStackDump(boolean enable) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

we should make this return a new instance, so the fields can be final. To avoid having a large number of constructors, you can use a builder:

return toBuilder()
        .printFullThreadStackDump(enable)
        .build();

fFullThreadStackDump = enable;
return this;
}

public Statement apply(Statement base, Description description) {
return new FailOnTimeout(base, fTimeout, fTimeUnit, fLookForStuckThread);
return new FailOnTimeout(base, fTimeout, fTimeUnit, fLookForStuckThread, fFullThreadStackDump);
}
}
93 changes: 86 additions & 7 deletions src/test/java/org/junit/tests/running/methods/TimeoutTest.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,8 +1,8 @@
package org.junit.tests.running.methods;

import static org.hamcrest.CoreMatchers.containsString;
import static org.hamcrest.CoreMatchers.not;
import static org.hamcrest.CoreMatchers.is;
import static org.hamcrest.CoreMatchers.not;
import static org.junit.Assert.assertEquals;
import static org.junit.Assert.assertThat;
import static org.junit.Assert.assertTrue;
Expand All @@ -12,6 +12,7 @@
import java.io.StringWriter;
import java.io.Writer;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.locks.ReentrantLock;

import junit.framework.JUnit4TestAdapter;
import junit.framework.TestResult;
Expand Down Expand Up @@ -152,7 +153,7 @@ private String stackForException(Throwable exception) {
exception.printStackTrace(writer);
return buffer.toString();
}

@Test
public void stalledThreadAppearsInStackTrace() throws Exception {
JUnitCore core = new JUnitCore();
Expand All @@ -164,7 +165,7 @@ public void stalledThreadAppearsInStackTrace() throws Exception {
}

public static class InfiniteLoopMultithreaded {

private static class ThreadTest implements Runnable {
private boolean fStall;

Expand All @@ -174,14 +175,14 @@ public ThreadTest(boolean stall) {

public void run() {
if (fStall)
for (; ; ) ;
for (; ; ) ;
try {
Thread.sleep(500);
} catch (InterruptedException e) {
}
}
}

public void failure(boolean mainThreadStalls) throws Exception {
Thread t1 = new Thread(new ThreadTest(false), "timeout-thr1");
Thread t2 = new Thread(new ThreadTest(!mainThreadStalls), "timeout-thr2");
Expand All @@ -196,7 +197,7 @@ public void failure(boolean mainThreadStalls) throws Exception {
t3.join();
}
}

public static class InfiniteLoopWithStuckThreadTest {
@Rule
public TestRule globalTimeout = new Timeout(100, TimeUnit.MILLISECONDS).lookForStuckThread(true);
Expand All @@ -206,7 +207,7 @@ public void failure() throws Exception {
(new InfiniteLoopMultithreaded()).failure(false);
}
}

public static class InfiniteLoopStuckInMainThreadTest {
@Rule
public TestRule globalTimeout = new Timeout(100, TimeUnit.MILLISECONDS).lookForStuckThread(true);
Expand Down Expand Up @@ -242,6 +243,84 @@ public void timeoutFailureMultithreadedStuckInMain() throws Exception {
assertThat(exception.getMessage(), not(containsString("Appears to be stuck")));
}


public static class LockedWithDeadlockTest {
@Rule
public TestRule globalTimeout = new Timeout(100, TimeUnit.MILLISECONDS).lookForStuckThread(true).printFullThreadStackDump(true);

final ReentrantLock lock1 = new ReentrantLock();
final ReentrantLock lock2 = new ReentrantLock();

private class LockedThread1 extends Thread {

public LockedThread1() {
super("Thread-locked-1");
}

@Override
public void run() {
lock1.lock();
try {
Thread.sleep(50);
} catch (InterruptedException e) {
// Ignore
}
lock2.lock();
}
}

private class LockedThread2 extends Thread {

public LockedThread2() {
super("Thread-locked-2");
}

@Override
public void run() {
lock2.lock();
try {
Thread.sleep(50);
} catch (InterruptedException e) {
// Ignore
}
lock1.lock();
}
}

@Test
public void failure() throws Exception {
LockedThread1 thread1 = new LockedThread1();
LockedThread2 thread2 = new LockedThread2();

thread1.start();
thread2.start();

thread1.join();
thread2.join();
}
}


@Test
public void timeoutFailureMultithreadedDeadlockWithFullDump() throws Exception {
JUnitCore core = new JUnitCore();
Result result = core.run(LockedWithDeadlockTest.class);
assertEquals(1, result.getRunCount());
assertEquals(2, result.getFailureCount());
Throwable exception[] = new Throwable[2];
for (int i = 0; i < 2; i++)
exception[i] = result.getFailures().get(i).getException();
assertThat(exception[0].getMessage(), containsString("test timed out after 100 milliseconds"));
assertThat(stackForException(exception[0]), containsString("Thread.join"));
assertThat(exception[1].getMessage(), containsString("Appears to be stuck => Full thread dump"));
// TODO: this is really not nice and safe
assertTrue("Failed to find Thread-locked-1 information in full thread dump:\n" + exception[1].getMessage(),
exception[1].getMessage().matches("(?s).*\"Thread-locked-1\".*State=WAITING.*at .*ReentrantLock\\.lock.*at org\\.junit\\.tests\\.running\\.methods\\.TimeoutTest\\$LockedWithDeadlockTest\\$LockedThread1\\.run.*"));
assertTrue("Failed to find Thread-locked-2 information in full thread dump:\n" + exception[1].getMessage(),
exception[1].getMessage().matches("(?s).*\"Thread-locked-2\".*State=WAITING.*at .*ReentrantLock\\.lock.*at org\\.junit\\.tests\\.running\\.methods\\.TimeoutTest\\$LockedWithDeadlockTest\\$LockedThread2\\.run.*"));
}


@Test
public void compatibility() {
TestResult result = new TestResult();
Expand Down