Skip to content

Commit

Permalink
ISPN-10024 Long test killer doesn't work on Java 11
Browse files Browse the repository at this point in the history 
* Add alternative location for jstack
* Add custom thread dump for JDKs without jstack
  • Loading branch information
@danberindei @tristantarrant
danberindei authored and tristantarrant committed Mar 19, 2019
1 parent 4d0fb80 commit ad0e363
Show file tree
Hide file tree
Showing 2 changed files with 129 additions and 21 deletions.
144 changes: 126 additions & 18 deletions commons-test/src/main/java/org/infinispan/commons/test/RunningTestsRegistry.java
View file
@@ -1,17 +1,22 @@
package org.infinispan.commons.test; package org.infinispan.commons.test;


import static java.util.Collections.singleton;
import static java.util.concurrent.TimeUnit.MINUTES; import static java.util.concurrent.TimeUnit.MINUTES;
import static java.util.concurrent.TimeUnit.SECONDS; import static java.util.concurrent.TimeUnit.SECONDS;


import java.io.BufferedReader; import java.io.BufferedReader;
import java.io.File; import java.io.File;
import java.io.FileWriter;
import java.io.InputStreamReader; import java.io.InputStreamReader;
import java.io.PrintWriter;
import java.lang.management.LockInfo;
import java.lang.management.ManagementFactory; import java.lang.management.ManagementFactory;
import java.lang.management.MonitorInfo;
import java.lang.management.ThreadInfo;
import java.lang.management.ThreadMXBean;
import java.time.LocalDateTime;
import java.util.ArrayList; import java.util.ArrayList;
import java.util.Arrays; import java.util.Arrays;
import java.util.Collections; import java.util.Collections;
import java.util.Date;
import java.util.List; import java.util.List;
import java.util.Map; import java.util.Map;
import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.ConcurrentHashMap;
Expand Down Expand Up @@ -46,19 +51,27 @@ static void registerThreadWithTest(String testName, String simpleName) {
scheduledTasks.put(testThread, future); scheduledTasks.put(testThread, future);
} }


@SuppressWarnings("deprecation")
private static void killLongTest(Thread testThread, String testName, String simpleName) { private static void killLongTest(Thread testThread, String testName, String simpleName) {
String safeTestName = testName.replaceAll("[^a-zA-Z0-9=]", "_");

List<String> pids = collectChildProcesses(testName);

dumpThreads(safeTestName, pids);

killTest(testThread, pids);
}

private static List<String> collectChildProcesses(String testName) {
try { try {
String safeTestName = testName.replaceAll("[^a-zA-Z0-9=]", "_");
System.err.printf( System.err.printf(
"Test %s has been running for more than %d seconds. Interrupting the test thread and dumping " + "Test %s has been running for more than %d seconds. Interrupting the test thread and dumping " +
"thread stacks of the test suite process and its children.\n", "threads of the test suite process and its children.\n",
testName, MAX_TEST_SECONDS); testName, MAX_TEST_SECONDS);


String jvmName = ManagementFactory.getRuntimeMXBean().getName(); String jvmName = ManagementFactory.getRuntimeMXBean().getName();
String ppid = jvmName.split("@")[0]; String ppid = jvmName.split("@")[0];


ArrayList<String> pids = new ArrayList<>(singleton(ppid)); List<String> pids = new ArrayList<>(Collections.singletonList(ppid));
int index = 0; int index = 0;
while (index < pids.size()) { while (index < pids.size()) {
String pid = pids.get(index); String pid = pids.get(index);
Expand All @@ -80,24 +93,60 @@ private static void killLongTest(Thread testThread, String testName, String simp
ps.waitFor(10, SECONDS); ps.waitFor(10, SECONDS);
} }


File dumpFile =
new File(String.format("threaddump-%1$s-%2$tY-%2$tm-%2$td-%3$s.log", safeTestName, new Date(), pid));
System.out.printf("Dumping thread stacks of process %s to %s\n", pid, dumpFile.getAbsolutePath());
Process jstack = new ProcessBuilder()
.command(System.getProperty("java.home") + "/../bin/jstack", pid)
.redirectOutput(dumpFile)
.start();
jstack.waitFor(10, SECONDS);

index++; index++;
} }
return pids;
} catch (Exception e) {
System.err.println("Error collecting child processes:");
e.printStackTrace(System.err);
return Collections.emptyList();
}
}

private static void dumpThreads(String safeTestName, List<String> pids) {
try {
File jstackFile = new File(System.getProperty("java.home") + "/../bin/jstack");
if (!jstackFile.canExecute()) {
jstackFile = new File(System.getProperty("java.home") + "/bin/jstack");
}
LocalDateTime now = LocalDateTime.now();
if (jstackFile.canExecute() && !pids.isEmpty()) {
for (String pid : pids) {
File dumpFile = new File(String.format("threaddump-%1$s-%2$tY-%2$tm-%2$td-%3$s.log",
safeTestName, now, pid));
System.out.printf("Dumping thread stacks of process %s to %s\n", pid, dumpFile.getAbsolutePath());
Process jstack = new ProcessBuilder()
.command(jstackFile.getAbsolutePath(), pid)
.redirectOutput(dumpFile)
.start();
jstack.waitFor(10, SECONDS);
}
} else {
File dumpFile = new File(String.format("threaddump-%1$s-%2$tY-%2$tm-%2$td.log",
safeTestName, now));
ThreadMXBean threadMXBean = ManagementFactory.getThreadMXBean();
try (PrintWriter writer = new PrintWriter(new FileWriter(dumpFile))) {
// 2019-02-05 14:03:11
writer.printf("%1$tF %1$tT\nTest thread dump:\n\n", now);
ThreadInfo[] threads = threadMXBean.dumpAllThreads(true, true);
for (ThreadInfo thread : threads) {
dumpThread(writer, thread);
}
}
}
} catch (Exception e) {
System.err.println("Error dumping threads:");
e.printStackTrace(System.err);
}
}


private static void killTest(Thread testThread, List<String> pids) {
try {
// Interrupt the test thread // Interrupt the test thread
testThread.interrupt(); testThread.interrupt();
System.out.printf("Interrupted thread %s (%d).\n", testThread.getName(), testThread.getId()); System.out.printf("Interrupted thread %s (%d).\n", testThread.getName(), testThread.getId());


testThread.join(SECONDS.toMillis(MAX_TEST_SECONDS) / 10); testThread.join(SECONDS.toMillis(1));

if (testThread.isAlive()) { if (testThread.isAlive()) {
// Thread.interrupt() doesn't work if the thread is waiting to enter a synchronized block or in lock() // Thread.interrupt() doesn't work if the thread is waiting to enter a synchronized block or in lock()
// Thread.stop() works for lock(), but not if the thread is waiting to enter a synchronized block // Thread.stop() works for lock(), but not if the thread is waiting to enter a synchronized block
Expand All @@ -123,8 +172,67 @@ private static void killLongTest(Thread testThread, String testName, String simp
System.out.printf("Killed processes %s\n", String.join(" ", pids)); System.out.printf("Killed processes %s\n", String.join(" ", pids));
} }
} catch (Exception e) { } catch (Exception e) {
System.err.println("Error dumping thread stacks/interrupting threads/killing processes:"); System.err.println("Error killing test:");
e.printStackTrace(System.err); e.printStackTrace(System.err);
} }
} }

private static void dumpThread(PrintWriter writer, ThreadInfo thread) {
// "management I/O-2" tid=0x00007fe6a8134000 runnable
// [0x00007fe64e4db000]
// java.lang.Thread.State:RUNNABLE
// - waiting to lock <0x00007fa12e5a5d40> (a java.lang.Object)
// - waiting on <0x00007fb2c4017ba0> (a java.util.LinkedList)
// - parking to wait for <0x00007fc96bd87cf0> (a java.util.concurrent.CompletableFuture$Signaller)
// - locked <0x00007fb34c037e20> (a com.arjuna.ats.arjuna.coordinator.TransactionReaper)
writer.printf("\"%s\" #%s prio=0 tid=0x%x nid=NA %s\n", thread.getThreadName(), thread.getThreadId(),
thread.getThreadId(), thread.getThreadState().toString().toLowerCase());
writer.printf(" java.lang.Thread.State: %s\n", thread.getThreadState());
LockInfo blockedLock = thread.getLockInfo();
StackTraceElement[] s = thread.getStackTrace();
MonitorInfo[] monitors = thread.getLockedMonitors();
for (int i = 0; i < s.length; i++) {
StackTraceElement ste = s[i];
writer.printf("\tat %s\n", ste);
if (i == 0 && blockedLock != null) {
boolean parking = ste.isNativeMethod() && ste.getMethodName().equals("park");
writer.printf("\t- %s <0x%x> (a %s)\n", blockedState(thread, blockedLock, parking),
blockedLock.getIdentityHashCode(), blockedLock.getClassName());
}
if (monitors != null) {
for (MonitorInfo monitor : monitors) {
if (monitor.getLockedStackDepth() == i) {
writer.printf("\t- locked <0x%x> (a %s)\n", monitor.getIdentityHashCode(), monitor.getClassName());
}
}
}
}
writer.println();

LockInfo[] synchronizers = thread.getLockedSynchronizers();
if (synchronizers != null && synchronizers.length > 0) {
writer.print("\n Locked ownable synchronizers:\n");
for (LockInfo synchronizer : synchronizers) {
writer.printf("\t- <0x%x> (a %s)\n", synchronizer.getIdentityHashCode(), synchronizer.getClassName());
}
writer.println();
}
}

private static String blockedState(ThreadInfo thread, LockInfo blockedLock, boolean parking) {
String state;
if (blockedLock != null) {
if (thread.getThreadState().equals(Thread.State.BLOCKED)) {
state = "waiting to lock";
} else if (parking) {
state = "parking to wait for";
} else {
state = "waiting on";
}
} else {
state = null;
}
return state;
}

} }
6 changes: 3 additions & 3 deletions commons-test/src/main/java/org/infinispan/commons/test/ThreadLeakChecker.java
View file
Expand Up @@ -183,7 +183,7 @@ private static void performCheck() {


if (!leaks.isEmpty()) { if (!leaks.isEmpty()) {
for (LeakInfo leakInfo : leaks) { for (LeakInfo leakInfo : leaks) {
log.warnf("Possible leaked thread:\n%s", prettyPringStacktrace(leakInfo.thread)); log.warnf("Possible leaked thread:\n%s", prettyPrintStacktrace(leakInfo.thread));
leakInfo.reported = true; leakInfo.reported = true;
} }
// Strategies for debugging test suite thread leaks // Strategies for debugging test suite thread leaks
Expand Down Expand Up @@ -227,7 +227,7 @@ private static boolean ignore(LeakInfo leakInfo) {
return false; return false;
} }


public static String prettyPringStacktrace(Thread thread) { public static String prettyPrintStacktrace(Thread thread) {
// "management I/O-2" #55 prio=5 os_prio=0 tid=0x00007fe6a8134000 nid=0x7f9d runnable // "management I/O-2" #55 prio=5 os_prio=0 tid=0x00007fe6a8134000 nid=0x7f9d runnable
// [0x00007fe64e4db000] // [0x00007fe64e4db000]
// java.lang.Thread.State:RUNNABLE // java.lang.Thread.State:RUNNABLE
Expand All @@ -238,7 +238,7 @@ public static String prettyPringStacktrace(Thread thread) {
sb.append(" java.lang.Thread.State: ").append(thread.getState()).append('\n'); sb.append(" java.lang.Thread.State: ").append(thread.getState()).append('\n');
StackTraceElement[] s = thread.getStackTrace(); StackTraceElement[] s = thread.getStackTrace();
for (StackTraceElement ste : s) { for (StackTraceElement ste : s) {
sb.append("\t").append(ste).append('\n'); sb.append("\tat ").append(ste).append('\n');
} }
return sb.toString(); return sb.toString();
} }
Expand Down

0 comments on commit ad0e363

Please sign in to comment.