diff --git a/.github/workflows/pulsar-ci.yaml b/.github/workflows/pulsar-ci.yaml index e067e42f43c8d4..2077f95831ccd7 100644 --- a/.github/workflows/pulsar-ci.yaml +++ b/.github/workflows/pulsar-ci.yaml @@ -29,7 +29,22 @@ on: collect_coverage: description: 'Collect test coverage and upload to Codecov' required: true - default: 'true' + type: boolean + default: true + trace_test_resource_cleanup: + description: 'Collect thread & heap information before exiting a test JVM. When set to "on", thread dump and heap histogram will be collected. When set to "full", a heap dump will also be collected.' + required: true + type: choice + options: + - 'off' + - 'on' + - 'full' + default: 'off' + thread_leak_detector_wait_millis: + description: 'Duration in ms to wait for threads to exit in thread leak detection between test classes. It is necessary to wait for threads to complete before they are determined to be leaked threads.' + required: true + type: number + default: 10000 concurrency: group: ${{ github.workflow }}-${{ github.ref }} @@ -172,6 +187,10 @@ jobs: JOB_NAME: CI - Unit - ${{ matrix.name }} COLLECT_COVERAGE: "${{ needs.preconditions.outputs.collect_coverage }}" GRADLE_ENTERPRISE_ACCESS_KEY: ${{ secrets.GE_ACCESS_TOKEN }} + TRACE_TEST_RESOURCE_CLEANUP: ${{ github.event_name == 'workflow_dispatch' && github.event.inputs.trace_test_resource_cleanup || 'off' }} + TRACE_TEST_RESOURCE_CLEANUP_DIR: ${{ github.workspace }}/target/trace-test-resource-cleanup + THREAD_LEAK_DETECTOR_WAIT_MILLIS: ${{ github.event_name == 'workflow_dispatch' && github.event.inputs.thread_leak_detector_wait_millis || 10000 }} + THREAD_LEAK_DETECTOR_DIR: ${{ github.workspace }}/target/thread-leak-dumps runs-on: ubuntu-22.04 timeout-minutes: ${{ matrix.timeout || 60 }} needs: ['preconditions', 'build-and-license-check'] @@ -212,6 +231,10 @@ jobs: - name: Tune Runner VM uses: ./.github/actions/tune-runner-vm + - name: Clean Disk when tracing test resource cleanup + if: ${{ env.TRACE_TEST_RESOURCE_CLEANUP != 'off' }} + uses: ./.github/actions/clean-disk + - name: Setup ssh access to build runner VM # ssh access is enabled for builds in own forks if: ${{ github.repository != 'apache/pulsar' && github.event_name == 'pull_request' }} @@ -273,9 +296,19 @@ jobs: report_paths: 'test-reports/TEST-*.xml' annotate_only: 'true' + - name: Report detected thread leaks + if: ${{ always() }} + run: | + if [ -d "$THREAD_LEAK_DETECTOR_DIR" ]; then + cd "$THREAD_LEAK_DETECTOR_DIR" + for file in threadleak*.txt; do + cat "$file" | awk '{ if($0 != "") { print "::warning::"$0 }}' + done + fi + - name: Upload Surefire reports uses: actions/upload-artifact@v3 - if: ${{ !success() }} + if: ${{ !success() || env.TRACE_TEST_RESOURCE_CLEANUP != 'off' }} with: name: Unit-${{ matrix.group }}-surefire-reports path: surefire-reports @@ -290,6 +323,8 @@ jobs: /tmp/*.hprof **/hs_err_*.log **/core.* + ${{ env.TRACE_TEST_RESOURCE_CLEANUP_DIR }}/* + ${{ env.THREAD_LEAK_DETECTOR_DIR }}/* retention-days: 7 if-no-files-found: ignore diff --git a/buildtools/src/main/java/org/apache/pulsar/tests/HeapDumpUtil.java b/buildtools/src/main/java/org/apache/pulsar/tests/HeapDumpUtil.java new file mode 100644 index 00000000000000..555e312e1f87c7 --- /dev/null +++ b/buildtools/src/main/java/org/apache/pulsar/tests/HeapDumpUtil.java @@ -0,0 +1,53 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +package org.apache.pulsar.tests; + +import com.sun.management.HotSpotDiagnosticMXBean; +import java.io.File; +import java.lang.management.ManagementFactory; +import javax.management.MBeanServer; + +public class HeapDumpUtil { + private static final String HOTSPOT_BEAN_NAME = "com.sun.management:type=HotSpotDiagnostic"; + + // Utility method to get the HotSpotDiagnosticMXBean + private static HotSpotDiagnosticMXBean getHotSpotDiagnosticMXBean() { + try { + MBeanServer server = ManagementFactory.getPlatformMBeanServer(); + return ManagementFactory.newPlatformMXBeanProxy(server, HOTSPOT_BEAN_NAME, HotSpotDiagnosticMXBean.class); + } catch (Exception e) { + throw new RuntimeException(e); + } + } + + /** + * Dump the heap of the JVM. + * + * @param file the system-dependent filename + * @param liveObjects if true dump only live objects i.e. objects that are reachable from others + */ + public static void dumpHeap(File file, boolean liveObjects) { + try { + HotSpotDiagnosticMXBean hotspotMBean = getHotSpotDiagnosticMXBean(); + hotspotMBean.dumpHeap(file.getAbsolutePath(), liveObjects); + } catch (Exception e) { + throw new RuntimeException("Error generating heap dump", e); + } + } +} diff --git a/buildtools/src/main/java/org/apache/pulsar/tests/HeapHistogramUtil.java b/buildtools/src/main/java/org/apache/pulsar/tests/HeapHistogramUtil.java new file mode 100644 index 00000000000000..53d66400ae7553 --- /dev/null +++ b/buildtools/src/main/java/org/apache/pulsar/tests/HeapHistogramUtil.java @@ -0,0 +1,62 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +package org.apache.pulsar.tests; + +import java.lang.management.ManagementFactory; +import java.time.ZonedDateTime; +import java.time.format.DateTimeFormatter; +import javax.management.JMException; +import javax.management.ObjectName; + +public class HeapHistogramUtil { + public static String buildHeapHistogram() { + StringBuilder dump = new StringBuilder(); + dump.append(String.format("Timestamp: %s", DateTimeFormatter.ISO_OFFSET_DATE_TIME.format(ZonedDateTime.now()))); + dump.append("\n\n"); + try { + dump.append(callDiagnosticCommand("gcHeapInfo")); + } catch (Exception e) { + e.printStackTrace(); + return null; + } + dump.append("\n"); + try { + dump.append(callDiagnosticCommand("gcClassHistogram")); + } catch (Exception e) { + e.printStackTrace(); + return null; + } + return dump.toString(); + } + + /** + * Calls a diagnostic commands. + * The available operations are similar to what the jcmd commandline tool has, + * however the naming of the operations are different. The "help" operation can be used + * to find out the available operations. For example, the jcmd command "Thread.print" maps + * to "threadPrint" operation name. + */ + static String callDiagnosticCommand(String operationName, String... args) + throws JMException { + return (String) ManagementFactory.getPlatformMBeanServer() + .invoke(new ObjectName("com.sun.management:type=DiagnosticCommand"), + operationName, new Object[] {args}, new String[] {String[].class.getName()}); + } +} diff --git a/buildtools/src/main/java/org/apache/pulsar/tests/ThreadDumpUtil.java b/buildtools/src/main/java/org/apache/pulsar/tests/ThreadDumpUtil.java index e20a02f95a9920..6484600bad4f58 100644 --- a/buildtools/src/main/java/org/apache/pulsar/tests/ThreadDumpUtil.java +++ b/buildtools/src/main/java/org/apache/pulsar/tests/ThreadDumpUtil.java @@ -25,7 +25,7 @@ import java.lang.management.MonitorInfo; import java.lang.management.ThreadInfo; import java.lang.management.ThreadMXBean; -import java.time.LocalDateTime; +import java.time.ZonedDateTime; import java.time.format.DateTimeFormatter; import java.util.Map; import javax.management.JMException; @@ -65,7 +65,7 @@ static String buildThreadDump() { // fallback to using JMX for creating the thread dump StringBuilder dump = new StringBuilder(); - dump.append(String.format("Timestamp: %s", DateTimeFormatter.ISO_OFFSET_DATE_TIME.format(LocalDateTime.now()))); + dump.append(String.format("Timestamp: %s", DateTimeFormatter.ISO_OFFSET_DATE_TIME.format(ZonedDateTime.now()))); dump.append("\n\n"); Map stackTraces = Thread.getAllStackTraces(); diff --git a/buildtools/src/main/java/org/apache/pulsar/tests/ThreadLeakDetectorListener.java b/buildtools/src/main/java/org/apache/pulsar/tests/ThreadLeakDetectorListener.java index 803d1c4980bc91..a2b092d219c0c5 100644 --- a/buildtools/src/main/java/org/apache/pulsar/tests/ThreadLeakDetectorListener.java +++ b/buildtools/src/main/java/org/apache/pulsar/tests/ThreadLeakDetectorListener.java @@ -16,49 +16,140 @@ * specific language governing permissions and limitations * under the License. */ + package org.apache.pulsar.tests; +import com.google.common.base.Charsets; +import com.google.common.io.Files; +import java.io.File; +import java.io.IOException; +import java.io.PrintWriter; +import java.time.ZonedDateTime; +import java.time.format.DateTimeFormatter; import java.util.Collections; import java.util.LinkedHashSet; import java.util.Objects; import java.util.Set; import java.util.stream.Collectors; import org.apache.commons.lang3.ThreadUtils; +import org.apache.commons.lang3.mutable.MutableBoolean; import org.slf4j.Logger; import org.slf4j.LoggerFactory; /** - * Detects new threads that have been created during the test execution. + * Detects new threads that have been created during the test execution. This is useful to detect thread leaks. + * Will create files to the configured directory if new threads are detected and THREAD_LEAK_DETECTOR_WAIT_MILLIS + * is set to a positive value. A recommended value is 10000 for THREAD_LEAK_DETECTOR_WAIT_MILLIS. This will ensure + * that any asynchronous operations should have completed before the detector determines that it has found a leak. */ public class ThreadLeakDetectorListener extends BetweenTestClassesListenerAdapter { private static final Logger LOG = LoggerFactory.getLogger(ThreadLeakDetectorListener.class); + private static final long WAIT_FOR_THREAD_TERMINATION_MILLIS = + Long.parseLong(System.getenv().getOrDefault("THREAD_LEAK_DETECTOR_WAIT_MILLIS", "0")); + private static final File DUMP_DIR = + new File(System.getenv().getOrDefault("THREAD_LEAK_DETECTOR_DIR", "target/thread-leak-dumps")); + private static final long THREAD_TERMINATION_POLL_INTERVAL = + Long.parseLong(System.getenv().getOrDefault("THREAD_LEAK_DETECTOR_POLL_INTERVAL", "250")); + private static final boolean COLLECT_THREADDUMP = + Boolean.parseBoolean(System.getenv().getOrDefault("THREAD_LEAK_DETECTOR_COLLECT_THREADDUMP", "true")); private Set capturedThreadKeys; + @Override protected void onBetweenTestClasses(Class endedTestClass, Class startedTestClass) { LOG.info("Capturing identifiers of running threads."); - capturedThreadKeys = compareThreads(capturedThreadKeys, endedTestClass); + MutableBoolean differenceDetected = new MutableBoolean(); + Set currentThreadKeys = + compareThreads(capturedThreadKeys, endedTestClass, WAIT_FOR_THREAD_TERMINATION_MILLIS <= 0, + differenceDetected, null); + if (WAIT_FOR_THREAD_TERMINATION_MILLIS > 0 && endedTestClass != null && differenceDetected.booleanValue()) { + LOG.info("Difference detected in active threads. Waiting up to {} ms for threads to terminate.", + WAIT_FOR_THREAD_TERMINATION_MILLIS); + long endTime = System.currentTimeMillis() + WAIT_FOR_THREAD_TERMINATION_MILLIS; + while (System.currentTimeMillis() < endTime) { + try { + Thread.sleep(THREAD_TERMINATION_POLL_INTERVAL); + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + } + differenceDetected.setFalse(); + currentThreadKeys = compareThreads(capturedThreadKeys, endedTestClass, false, differenceDetected, null); + if (!differenceDetected.booleanValue()) { + break; + } + } + if (differenceDetected.booleanValue()) { + String datetimePart = + DateTimeFormatter.ofPattern("yyyyMMdd-HHmmss.SSS").format(ZonedDateTime.now()); + PrintWriter out = null; + try { + if (!DUMP_DIR.exists()) { + DUMP_DIR.mkdirs(); + } + File threadleakdumpFile = + new File(DUMP_DIR, "threadleak" + datetimePart + endedTestClass.getName() + ".txt"); + out = new PrintWriter(threadleakdumpFile); + } catch (IOException e) { + LOG.error("Cannot write thread leak dump", e); + } + currentThreadKeys = compareThreads(capturedThreadKeys, endedTestClass, true, null, out); + if (out != null) { + out.close(); + } + if (COLLECT_THREADDUMP) { + File threaddumpFile = + new File(DUMP_DIR, "threaddump" + datetimePart + endedTestClass.getName() + ".txt"); + try { + Files.asCharSink(threaddumpFile, Charsets.UTF_8) + .write(ThreadDumpUtil.buildThreadDiagnosticString()); + } catch (IOException e) { + LOG.error("Cannot write thread dump", e); + } + } + } + } + capturedThreadKeys = currentThreadKeys; } - private static Set compareThreads(Set previousThreadKeys, Class endedTestClass) { + private static Set compareThreads(Set previousThreadKeys, Class endedTestClass, + boolean logDifference, MutableBoolean differenceDetected, + PrintWriter out) { Set threadKeys = Collections.unmodifiableSet(ThreadUtils.getAllThreads().stream() .map(ThreadKey::of) .collect(Collectors.>toCollection(LinkedHashSet::new))); if (endedTestClass != null && previousThreadKeys != null) { int newThreadsCounter = 0; - LOG.info("Checking for new threads created by {}.", endedTestClass.getName()); for (ThreadKey threadKey : threadKeys) { if (!previousThreadKeys.contains(threadKey)) { newThreadsCounter++; - LOG.warn("Tests in class {} created thread id {} with name '{}'", endedTestClass.getSimpleName(), - threadKey.getThreadId(), threadKey.getThreadName()); + if (differenceDetected != null) { + differenceDetected.setTrue(); + } + if (logDifference || out != null) { + String message = String.format("Tests in class %s created thread id %d with name '%s'", + endedTestClass.getSimpleName(), + threadKey.getThreadId(), threadKey.getThreadName()); + if (logDifference) { + LOG.warn(message); + } + if (out != null) { + out.println(message); + } + } } } - if (newThreadsCounter > 0) { - LOG.warn("Summary: Tests in class {} created {} new threads", endedTestClass.getName(), - newThreadsCounter); + if (newThreadsCounter > 0 && (logDifference || out != null)) { + String message = String.format( + "Summary: Tests in class %s created %d new threads. There are now %d threads in total.", + endedTestClass.getName(), newThreadsCounter, threadKeys.size()); + if (logDifference) { + LOG.warn(message); + } + if (out != null) { + out.println(message); + } } } diff --git a/buildtools/src/main/java/org/apache/pulsar/tests/TraceTestResourceCleanupListener.java b/buildtools/src/main/java/org/apache/pulsar/tests/TraceTestResourceCleanupListener.java new file mode 100644 index 00000000000000..5692d94bcf15b3 --- /dev/null +++ b/buildtools/src/main/java/org/apache/pulsar/tests/TraceTestResourceCleanupListener.java @@ -0,0 +1,96 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +package org.apache.pulsar.tests; + +import com.google.common.base.Charsets; +import com.google.common.io.Files; +import java.io.File; +import java.time.ZonedDateTime; +import java.time.format.DateTimeFormatter; +import org.testng.IExecutionListener; + +/** + * A TestNG listener that traces test resource cleanup by creating a thread dump, heap histogram and heap dump + * (when mode is 'full') before the TestNG JVM exits. + * The heap dump could help detecting memory leaks in tests or the sources of resource leaks that cannot be + * detected with the ThreadLeakDetectorListener. + */ +public class TraceTestResourceCleanupListener implements IExecutionListener { + enum TraceTestResourceCleanupMode { + OFF, + ON, + FULL // includes heap dump + } + + private static final TraceTestResourceCleanupMode MODE = + TraceTestResourceCleanupMode.valueOf( + System.getenv().getOrDefault("TRACE_TEST_RESOURCE_CLEANUP", "off").toUpperCase()); + private static final File DUMP_DIR = new File( + System.getenv().getOrDefault("TRACE_TEST_RESOURCE_CLEANUP_DIR", "target/trace-test-resource-cleanup")); + private static final long WAIT_BEFORE_DUMP_MILLIS = + Long.parseLong(System.getenv().getOrDefault("TRACE_TEST_RESOURCE_CLEANUP_DELAY", "5000")); + + static { + if (MODE != TraceTestResourceCleanupMode.OFF) { + Runtime.getRuntime().addShutdownHook(new Thread(TraceTestResourceCleanupListener::createDumps)); + } + } + + static void createDumps() { + if (!DUMP_DIR.isDirectory()) { + DUMP_DIR.mkdirs(); + } + try { + Thread.sleep(WAIT_BEFORE_DUMP_MILLIS); + } catch (InterruptedException e) { + // ignore + } + + String datetimePart = + DateTimeFormatter.ofPattern("yyyyMMdd-HHmmss.SSS").format(ZonedDateTime.now()); + try { + String threadDump = ThreadDumpUtil.buildThreadDiagnosticString(); + File threaddumpFile = new File(DUMP_DIR, "threaddump" + datetimePart + ".txt"); + Files.asCharSink(threaddumpFile, Charsets.UTF_8).write(threadDump); + } catch (Throwable t) { + System.err.println("Error dumping threads"); + t.printStackTrace(System.err); + } + + try { + String heapHistogram = HeapHistogramUtil.buildHeapHistogram(); + File heapHistogramFile = new File(DUMP_DIR, "heaphistogram" + datetimePart + ".txt"); + Files.asCharSink(heapHistogramFile, Charsets.UTF_8).write(heapHistogram); + } catch (Throwable t) { + System.err.println("Error dumping heap histogram"); + t.printStackTrace(System.err); + } + + if (MODE == TraceTestResourceCleanupMode.FULL) { + try { + File heapdumpFile = new File(DUMP_DIR, "heapdump" + datetimePart + ".hprof"); + HeapDumpUtil.dumpHeap(heapdumpFile, true); + } catch (Throwable t) { + System.err.println("Error dumping heap"); + t.printStackTrace(System.err); + } + } + } +} diff --git a/pom.xml b/pom.xml index 2ac82aaee76186..bfb2a113da02d4 100644 --- a/pom.xml +++ b/pom.xml @@ -1579,7 +1579,7 @@ flexible messaging model and an intuitive client API. listener - org.apache.pulsar.tests.PulsarTestListener,org.apache.pulsar.tests.JacocoDumpListener,org.apache.pulsar.tests.AnnotationListener,org.apache.pulsar.tests.FailFastNotifier,org.apache.pulsar.tests.MockitoCleanupListener,org.apache.pulsar.tests.FastThreadLocalCleanupListener,org.apache.pulsar.tests.ThreadLeakDetectorListener,org.apache.pulsar.tests.SingletonCleanerListener + org.apache.pulsar.tests.PulsarTestListener,org.apache.pulsar.tests.JacocoDumpListener,org.apache.pulsar.tests.TraceTestResourceCleanupListener,org.apache.pulsar.tests.AnnotationListener,org.apache.pulsar.tests.FailFastNotifier,org.apache.pulsar.tests.MockitoCleanupListener,org.apache.pulsar.tests.FastThreadLocalCleanupListener,org.apache.pulsar.tests.ThreadLeakDetectorListener,org.apache.pulsar.tests.SingletonCleanerListener diff --git a/pulsar-common/src/main/java/org/apache/pulsar/common/util/ThreadDumpUtil.java b/pulsar-common/src/main/java/org/apache/pulsar/common/util/ThreadDumpUtil.java index 2916269209d86c..ca9ca0794e05f5 100644 --- a/pulsar-common/src/main/java/org/apache/pulsar/common/util/ThreadDumpUtil.java +++ b/pulsar-common/src/main/java/org/apache/pulsar/common/util/ThreadDumpUtil.java @@ -25,7 +25,7 @@ import java.lang.management.MonitorInfo; import java.lang.management.ThreadInfo; import java.lang.management.ThreadMXBean; -import java.time.LocalDateTime; +import java.time.ZonedDateTime; import java.time.format.DateTimeFormatter; import java.util.Map; import javax.management.JMException; @@ -65,7 +65,7 @@ static String buildThreadDump() { // fallback to using JMX for creating the thread dump StringBuilder dump = new StringBuilder(); - dump.append(String.format("Timestamp: %s", DateTimeFormatter.ISO_OFFSET_DATE_TIME.format(LocalDateTime.now()))); + dump.append(String.format("Timestamp: %s", DateTimeFormatter.ISO_OFFSET_DATE_TIME.format(ZonedDateTime.now()))); dump.append("\n\n"); Map stackTraces = Thread.getAllStackTraces();