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.

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

Implement new stand dump tool for virtual threads #43369

Merged
merged 7 commits into from
Sep 20, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
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
Original file line number Diff line number Diff line change
Expand Up @@ -18,59 +18,126 @@

package io.ballerina.runtime.internal.troubleshoot;

import io.ballerina.runtime.internal.scheduling.Strand;
import com.sun.management.HotSpotDiagnosticMXBean;

import java.io.File;
import java.io.IOException;
import java.lang.management.ManagementFactory;
import java.nio.file.Files;
import java.nio.file.Paths;
import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;
import java.util.HashMap;
import java.util.List;
import java.util.Map;
import java.util.ArrayList;
import java.util.HashSet;
import java.util.Set;
import java.util.regex.Pattern;

import javax.management.MBeanServer;


/**
* Used to get the status of current Ballerina strands.
*
* @since 2201.2.0
*/
public class StrandDump {
private static final String HOT_SPOT_BEAN_NAME = "com.sun.management:type=HotSpotDiagnostic";
private static final String WORKING_DIR = System.getProperty("user.dir") + "/";
private static final String FILENAME = "threadDump" + LocalDateTime.now();
private static final String VIRTUAL_THREAD_IDENTIFIER = "virtual";
private static final String ISOLATED_WORKER_IDENTIFIER = "io.ballerina.runtime.internal.scheduling." +
"Scheduler.lambda$startIsolatedWorker";
private static final String NON_ISOLATED_WORKER_IDENTIFIER = "io.ballerina.runtime.internal.scheduling." +
"Scheduler.lambda$startNonIsolatedWorker";
private static final String JAVA_TRACE_PATTERN = "java\\.|\\.java(?::\\d+)?"; // .java, java., .java:(any number)
private static final String BAL_TRACE_PATTERN = "\\.bal:\\d+"; // .bal:(any number)
private static volatile HotSpotDiagnosticMXBean hotSpotDiagnosticMXBean;

public static String getStrandDump() {
Map<Integer, Strand> availableStrands = new HashMap<>();
int createdStrandGroupCount = 0;
int createdStrandCount = 0;
int availableStrandCount = 0;
Map<Integer, List<String>> availableStrandGroups = new HashMap<>();

String strandDumpOutput = generateOutput(availableStrandGroups, availableStrandCount, createdStrandGroupCount,
createdStrandCount);
cleanUp(availableStrands, availableStrandGroups);
return strandDumpOutput;
String dump;
try {
getStrandDump(WORKING_DIR + FILENAME);
dump = new String(Files.readAllBytes(Paths.get(FILENAME)));
File fileObj = new File(FILENAME);
fileObj.delete();
} catch (Exception e) {
return "Error occurred during strand dump generation";
}
return generateOutput(dump);
}

private static String generateOutput(Map<Integer, List<String>> availableStrandGroups, int availableStrandCount,
int createdStrandGroupCount, int createdStrandCount) {
private static String generateOutput(String dump) {
String[] dumpItems = dump.split("\\n\\n");
int id = 0;
Set<Integer> isolatedWorkerList = new HashSet<>();
Set<Integer> nonIsolatedWorkerList = new HashSet<>();
ArrayList<ArrayList<String>> balTraces = new ArrayList<>();
Pattern javaPattern = Pattern.compile(JAVA_TRACE_PATTERN);
Pattern balPattern = Pattern.compile(BAL_TRACE_PATTERN);
for (String item : dumpItems) {
String[] lines = item.split("\\n");
String[] subitems = lines[0].split("\" ");
ArrayList<String> balTraceItems = new ArrayList<>();
boolean balStrand = false;
if (subitems.length > 1 && subitems[1].equals(VIRTUAL_THREAD_IDENTIFIER)) {
balTraceItems.add("\tStrand " + lines[0].replace(VIRTUAL_THREAD_IDENTIFIER, ":") + "\n\t\tat");
String prefix = " ";
for (String line : lines) {
if (!javaPattern.matcher(line).find() && !line.contains("\" " + VIRTUAL_THREAD_IDENTIFIER)) {
balTraceItems.add(prefix + line + "\n");
prefix = "\t\t ";
if (balPattern.matcher(line).find()) {
balStrand = true;
}
} else {
if (line.contains(ISOLATED_WORKER_IDENTIFIER)) {
isolatedWorkerList.add(id);
} else if (line.contains(NON_ISOLATED_WORKER_IDENTIFIER)) {
nonIsolatedWorkerList.add(id);
}
}
}
if (balStrand) {
balTraces.add(balTraceItems);
} else {
isolatedWorkerList.remove(id);
nonIsolatedWorkerList.remove(id);
}
id++;
}
}
StringBuilder outputStr = new StringBuilder("Ballerina Strand Dump [");
DateTimeFormatter dateTimeFormatter = DateTimeFormatter.ofPattern("yyyy/MM/dd HH:mm:ss");
LocalDateTime localDateTime = LocalDateTime.now();
outputStr.append(dateTimeFormatter.format(localDateTime));
outputStr.append("]\n===========================================\n\n");
outputStr.append("Total strand group count \t:\t").append(createdStrandGroupCount).append("\n");
outputStr.append("Total strand count \t:\t").append(createdStrandCount).append("\n");
outputStr.append("Active strand group count\t:\t").append(availableStrandGroups.size()).append("\n");
outputStr.append("Active strand count \t:\t").append(availableStrandCount).append("\n\n");
availableStrandGroups.forEach((strandGroupId, strandList) -> {
outputStr.append("group ").append(strandGroupId).append(" [").append(strandList.get(0)).append("]: [")
.append(strandList.size() - 1).append("]\n");
strandList.subList(1, strandList.size()).forEach(outputStr::append);
});
outputStr.append("===========================================\n");
outputStr.append("]\n===============================================================\n\n");
outputStr.append("Total Strand count \t\t\t:\t").append(balTraces.size()).append("\n\n");
outputStr.append("Total Isolated Worker count \t\t:\t").append(isolatedWorkerList.size()).append("\n\n");
outputStr.append("Total Non Isolated Worker count \t\t:\t").append(nonIsolatedWorkerList.size()).
append("\n\n");
outputStr.append("================================================================\n");
outputStr.append("\nIsolated Workers:\n\n");
for (int strandId: isolatedWorkerList) {
balTraces.get(strandId).forEach(outputStr::append);
outputStr.append("\n");
}
outputStr.append("Non Isolated Workers:\n\n");
for (int strandId: nonIsolatedWorkerList) {
balTraces.get(strandId).forEach(outputStr::append);
outputStr.append("\n");
}
return outputStr.toString();
}

private static void cleanUp(Map<Integer, Strand> availableStrands,
Map<Integer, List<String>> availableStrandGroups) {
availableStrands.clear();
availableStrandGroups.clear();
private static void getStrandDump(String fileName) throws IOException {
if (hotSpotDiagnosticMXBean == null) {
hotSpotDiagnosticMXBean = getHotSpotDiagnosticMXBean();
}
hotSpotDiagnosticMXBean.dumpThreads(fileName, HotSpotDiagnosticMXBean.ThreadDumpFormat.TEXT_PLAIN);
}

private StrandDump() {}
private static HotSpotDiagnosticMXBean getHotSpotDiagnosticMXBean() throws IOException {
MBeanServer mBeanServer = ManagementFactory.getPlatformMBeanServer();
return ManagementFactory.newPlatformMXBeanProxy(mBeanServer, HOT_SPOT_BEAN_NAME, HotSpotDiagnosticMXBean.class);
}
}
1 change: 1 addition & 0 deletions bvm/ballerina-runtime/src/main/java/module-info.java
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,7 @@
requires java.naming;
requires io.ballerina.identifier;
requires jdk.unsupported;
requires jdk.management;

// API exports
exports io.ballerina.runtime.api;
Expand Down
Original file line number Diff line number Diff line change
@@ -1,43 +1,56 @@
Ballerina Strand Dump \[\d*/\d*/\d* \d*:\d*:\d*\]
===========================================
===============================================================

Total strand group count \t:\t5
Total strand count \t:\t9
Active strand group count\t:\t3
Active strand count \t:\t9
Total Strand count \t\t\t:\t9

group \d* \[QUEUED\]: \[7\]
\tstrand \d* "main" \[\$anon...0:main\] \[BLOCKED\]:
\t\tat\tballerina.lang.runtime.\d*.\d*.\d*:sleep\(runtime.bal:\d*\)
\t\t \t\$anon...0.0.0:bar\(balProgram1.bal:86\)
\t\t \t\$anon...0.0.0:foo\(balProgram1.bal:27\)
\t\t \t\$anon...0.0.0:main\(balProgram1.bal:23\)
Total Isolated Worker count \t\t:\t2

\tstrand \d* "w3" \[\$anon...0:bar\]\[\d*\] \[BLOCKED ON WORKER MESSAGE SEND\]:
\t\tat\t\$anon...0.0.0:\$lambda\$_2\(balProgram1.bal:53\)
Total Non Isolated Worker count \t\t:\t7

\tstrand \d* "w4" \[\$anon...0:bar\]\[\d*\] \[BLOCKED\]:
\t\tat\tballerina.lang.runtime.\d*.\d*.\d*:sleep\(runtime.bal:\d*\)
\t\t \t\$anon...0.0.0:\$lambda\$_3\(balProgram1.bal:58\)
================================================================

\tstrand \d* "w5" \[\$anon...0:bar\]\[\d*\] \[BLOCKED ON WORKER MESSAGE FLUSH\]:
\t\tat\t\$anon...0.0.0:\$lambda\$_4\(balProgram1.bal:65\)
Isolated Workers:

\tstrand \d* "w6" \[\$anon...0:bar\]\[\d*\] \[BLOCKED\]:
\t\tat\tballerina.lang.runtime.\d*.\d*.\d*:sleep\(runtime.bal:\d*\)
\t\t \t\$anon...0.0.0:\$lambda\$_5\(balProgram1.bal:70\)
\tStrand #\d* \"\d*\" :
\t\tat balProgram1.\$lambda\$_0\(balProgram1.bal:\d*\)
\t\t lambdas.\$_generated1balProgram1.\$lambda\$_0\$lambda0\$\(balProgram1.bal:\d*\)

\tstrand \d* \[\$anon...0:bar\]\[\d*\] \[BLOCKED ON WORKER MESSAGE RECEIVE\]:
\t\tat\t\$anon...0.0.0:\$lambda\$_6\(balProgram1.bal:76\)
\tStrand #\d* \"\d*\" :
\t\tat balProgram1.\$lambda\$_1\(balProgram1.bal:\d*\)
\t\t lambdas.\$_generated1balProgram1.\$lambda\$_1\$lambda1\$\(balProgram1.bal:\d*\)

\tstrand \d* "w8" \[\$anon...0:bar\]\[\d*\] \[WAITING\]:
\t\tat\t\$anon...0.0.0:\$lambda\$_7\(balProgram1.bal:82\)
Non Isolated Workers:

group \d* \[RUNNABLE\]: \[1\]
\tstrand \d* "w1" \[\$anon...0:bar\]\[\d*\] \[RUNNABLE\]
\tStrand #\d* \"\d*\" :
\t\tat balProgram1.\$lambda\$_2\(balProgram1.bal:\d*\)
\t\t lambdas.\$_generated1balProgram1.\$lambda\$_2\$lambda2\$\(balProgram1.bal:\d*\)

group \d* \[QUEUED\]: \[1\]
\tstrand \d* "w2" \[\$anon...0:bar\]\[\d*\] \[WAITING FOR LOCK\]:
\t\tat\t\$anon...0.0.0:\$lambda\$_1\(balProgram1.bal:46\)
\tStrand #\d* \"\d*\" :
\t\tat ballerina.lang&0046runtime.0.runtime.sleep\(runtime.bal:\d*\)
\t\t balProgram1.\$lambda\$_3\(balProgram1.bal:\d*\)
\t\t lambdas.\$_generated1balProgram1.\$lambda\$_3\$lambda3\$\(balProgram1.bal:\d*\)

===========================================
\tStrand #\d* \"\d*\" :
\t\tat balProgram1.\$lambda\$_4\(balProgram1.bal:\d*\)
\t\t lambdas.\$_generated1balProgram1.\$lambda\$_4\$lambda4\$\(balProgram1.bal:\d*\)

\tStrand #\d* \"\d*\" :
\t\tat ballerina.lang&0046runtime.0.runtime.sleep\(runtime.bal:\d*\)
\t\t balProgram1.\$lambda\$_5\(balProgram1.bal:\d*\)
\t\t lambdas.\$_generated1balProgram1.\$lambda\$_5\$lambda5\$\(balProgram1.bal:\d*\)

\tStrand #\d* \"\d*\" :
\t\tat ballerina.lang&0046runtime.0.runtime.sleep\(runtime.bal:\d*\)
\t\t balProgram1.bar\(balProgram1.bal:\d*\)
\t\t balProgram1.foo\(balProgram1.bal:\d*\)
\t\t balProgram1.main\(balProgram1.bal:\d*\)
\t\t \$_init.\$moduleExecute\(.\)
\t\t \$_init.\$lambda\$\$moduleExecute\$\(.\)

\tStrand #\d* \"\d*\" :
\t\tat balProgram1.\$lambda\$_6\(balProgram1.bal:\d*\)
\t\t lambdas.\$_generated1balProgram1.\$lambda\$_6\$lambda6\$\(balProgram1.bal:\d*\)

\tStrand #\d* \"\d*\" :
\t\tat balProgram1.\$lambda\$_7\(balProgram1.bal:\d*\)
\t\t lambdas.\$_generated1balProgram1.\$lambda\$_7\$lambda7\$\(balProgram1.bal:\d*\)
Original file line number Diff line number Diff line change
@@ -1,53 +1,66 @@
Ballerina Strand Dump \[\d*/\d*/\d* \d*:\d*:\d*\]
===========================================

Total strand group count \t:\t3
Total strand count \t:\t8
Active strand group count\t:\t1
Active strand count \t:\t8

group \d* \[QUEUED\]: \[8\]
\tstrand \d* "main" \[testOrg.testPackageWithModules.0:main\] \[BLOCKED\]:
\t\tat\tballerina.lang.function.\d*.\d*.\d*:call\(function.bal:\d*\)
\t\t \tballerina.test.\d*.\d*.\d*:executeTestFunction\(serialExecuter.bal:\d*\)
\t\t \tballerina.test.\d*.\d*.\d*:executeNonDataDrivenTest\(serialExecuter.bal:\d*\)
\t\t \tballerina.test.\d*.\d*.\d*:executeTest\(serialExecuter.bal:\d*\)
\t\t \tballerina.test.\d*.\d*.\d*:executeTests\(execute.bal:\d*\)
\t\t \tballerina.test.\d*.\d*.\d*:startSuite\(execute.bal:\d*\)
\t\t \ttestOrg.testPackageWithModules.0.1.0:__execute__\(tests/test_execute-generated_1.bal:\d*\)
\t\t \t\$moduleExecute

\tstrand \d* \[ballerina.lang.function.\d*.\d*.\d*:call\]\[\d*\] \[WAITING\]:
\t\tat\ttestOrg.testPackageWithModules.0.1.0:bar\(main.bal:52\)
\t\t \ttestOrg.testPackageWithModules.0.1.0:foo\(main.bal:37\)
\t\t \ttestOrg.testPackageWithModules.0.1.0:foobar\(main.bal:33\)
\t\t \ttestOrg.testPackageWithModules.0.1.0:testStrandDump\(tests/main_test.bal:35\)

\tstrand \d* "w11" \[testOrg.testPackageWithModules.0:testStrandDump\]\[\d*\] \[WAITING\]:
\t\tat\ttestOrg.testPackageWithModules.anotherutils.0.1.0:func3\(anotherutils.bal:46\)
\t\t \ttestOrg.testPackageWithModules.anotherutils.0.1.0:func2\(anotherutils.bal:29\)
\t\t \ttestOrg.testPackageWithModules.anotherutils.0.1.0:func1\(anotherutils.bal:25\)
\t\t \ttestOrg.testPackageWithModules.anotherutils.0.1.0:entryfunc\(anotherutils.bal:21\)
\t\t \ttestOrg.testPackageWithModules.0.1.0:\$lambda\$_10\(tests/main_test.bal:26\)

\tstrand \d* "w22" \[testOrg.testPackageWithModules.0:testStrandDump\]\[\d*\] \[BLOCKED\]:
\t\tat\tballerina.lang.runtime.\d*.\d*.\d*:sleep\(runtime.bal:\d*\)
\t\t \ttestOrg.testPackageWithModules.0.1.0:\$lambda\$_11\(tests/main_test.bal:31\)

\tstrand \d* "w1" \[testOrg.testPackageWithModules.0:bar\]\[\d*\] \[BLOCKED\]:
\t\tat\tballerina.lang.runtime.\d*.\d*.\d*:sleep\(runtime.bal:\d*\)
\t\t \ttestOrg.testPackageWithModules.0.1.0:sleep_and_wait_nested\(main.bal:61\)
\t\t \ttestOrg.testPackageWithModules.0.1.0:sleep_and_wait\(main.bal:56\)
\t\t \ttestOrg.testPackageWithModules.0.1.0:\$lambda\$_0\(main.bal:42\)

\tstrand \d* "w2" \[testOrg.testPackageWithModules.0:bar\]\[\d*\] \[BLOCKED ON WORKER MESSAGE RECEIVE\]:
\t\tat\ttestOrg.testPackageWithModules.0.1.0:\$lambda\$_1\(main.bal:48\)

\tstrand \d* "w1" \[testOrg.testPackageWithModules.anotherutils.0:func3\]\[\d*\] \[BLOCKED\]:
\t\tat\tballerina.lang.runtime.\d*.\d*.\d*:sleep\(runtime.bal:\d*\)
\t\t \ttestOrg.testPackageWithModules.anotherutils.0.1.0:sleep_and_wait_nested\(anotherutils.bal:55\)
\t\t \ttestOrg.testPackageWithModules.anotherutils.0.1.0:sleep_and_wait\(anotherutils.bal:50\)
\t\t \ttestOrg.testPackageWithModules.anotherutils.0.1.0:\$lambda\$_0\(anotherutils.bal:34\)

\tstrand \d* "w2" \[testOrg.testPackageWithModules.anotherutils.0:func3\]\[\d*\] \[BLOCKED ON WORKER MESSAGE RECEIVE\]:
\t\tat\ttestOrg.testPackageWithModules.anotherutils.0.1.0:\$lambda\$_1\(anotherutils.bal:42\)
===============================================================

Total Strand count \t\t\t:\t7

Total Isolated Worker count \t\t:\t0

Total Non Isolated Worker count \t\t:\t7

================================================================

Isolated Workers:

Non Isolated Workers:

\tStrand #\d* \"\d*\" :
\t\tat testOrg.testPackageWithModules.0.main.bar\(main.bal:\d*\)
\t\t testOrg.testPackageWithModules.0.main.foo\(main.bal:\d*\)
\t\t testOrg.testPackageWithModules.0.main.foobar\(main.bal:\d*\)
\t\t testOrg.testPackageWithModules\$test.0.tests.main_test.testStrandDump\(tests/main_test.bal:\d*\)
\t\t testOrg.testPackageWithModules\$test.0.lambdas.\$_generated1tests.test_execute-generated_1.testStrandDump\$lambda0\$\(tests/test_execute-generated_1.bal:\d*\)
\t\t ballerina.lang&0046function.0.function.call\(function.bal:\d*\)
\t\t ballerina.test.0.serialExecuter.executeTestFunction\(serialExecuter.bal:\d*\)
\t\t ballerina.test.0.serialExecuter.executeNonDataDrivenTest\(serialExecuter.bal:\d*\)
\t\t ballerina.test.0.serialExecuter.executeTest\(serialExecuter.bal:\d*\)
\t\t ballerina.test.0.execute.executeTests\(execute.bal:\d*\)
\t\t ballerina.test.0.execute.startSuite\(execute.bal:\d*\)
\t\t testOrg.testPackageWithModules\$test.0.tests.test_execute-generated_1.__execute__\(tests/test_execute-generated_1.bal:\d*\)
\t\t testOrg.testPackageWithModules\$test.0.\$_init.\$moduleExecute\(testPackageWithModules\)
\t\t testOrg.testPackageWithModules\$test.0.\$_init.\$lambda\$\$moduleExecute\$\(testPackageWithModules\)

\tStrand #\d* \"\d*\" :
\t\tat ballerina.lang&0046runtime.0.runtime.sleep\(runtime.bal:\d*\)
\t\t testOrg.testPackageWithModules.0.main.sleep_and_wait_nested\(main.bal:\d*\)
\t\t testOrg.testPackageWithModules.0.main.sleep_and_wait\(main.bal:\d*\)
\t\t testOrg.testPackageWithModules.0.main.\$lambda\$_0\(main.bal:\d*\)
\t\t testOrg.testPackageWithModules.0.lambdas.\$_generated1main.\$lambda\$_0\$lambda3\$\(main.bal:\d*\)

\tStrand #\d* \"\d*\" :
\t\tat testOrg.testPackageWithModules.0.main.\$lambda\$_1\(main.bal:\d*\)
\t\t testOrg.testPackageWithModules.0.lambdas.\$_generated1main.\$lambda\$_1\$lambda4\$\(main.bal:\d*\)

\tStrand #\d* \"\d*\" :
\t\tat ballerina.lang&0046runtime.0.runtime.sleep\(runtime.bal:\d*\)
\t\t testOrg.testPackageWithModules&0046anotherutils.0.anotherutils.sleep_and_wait_nested\(anotherutils.bal:\d*\)
\t\t testOrg.testPackageWithModules&0046anotherutils.0.anotherutils.sleep_and_wait\(anotherutils.bal:\d*\)
\t\t testOrg.testPackageWithModules&0046anotherutils.0.anotherutils.\$lambda\$_0\(anotherutils.bal:\d*\)
\t\t testOrg.testPackageWithModules&0046anotherutils.0.lambdas.\$_generated1anotherutils.\$lambda\$_0\$lambda0\$\(anotherutils.bal:\d*\)

\tStrand #\d* \"\d*\" :
\t\tat testOrg.testPackageWithModules&0046anotherutils.0.anotherutils.\$lambda\$_1\(anotherutils.bal:\d*\)
\t\t testOrg.testPackageWithModules&0046anotherutils.0.lambdas.\$_generated1anotherutils.\$lambda\$_1\$lambda1\$\(anotherutils.bal:\d*\)

\tStrand #\d* \"\d*\" :
\t\tat testOrg.testPackageWithModules&0046anotherutils.0.anotherutils.func3\(anotherutils.bal:\d*\)
\t\t testOrg.testPackageWithModules&0046anotherutils.0.anotherutils.func2\(anotherutils.bal:\d*\)
\t\t testOrg.testPackageWithModules&0046anotherutils.0.anotherutils.func1\(anotherutils.bal:\d*\)
\t\t testOrg.testPackageWithModules&0046anotherutils.0.anotherutils.entryfunc\(anotherutils.bal:\d*\)
\t\t testOrg.testPackageWithModules\$test.0.tests.main_test.\$lambda\$_10\(tests/main_test.bal:\d*\)
\t\t testOrg.testPackageWithModules\$test.0.lambdas.\$_generated2tests.main_test.\$lambda\$_10\$lambda0\$\(tests/main_test.bal:\d*\)

\tStrand #\d* \"\d*\" :
\t\tat ballerina.lang&0046runtime.0.runtime.sleep\(runtime.bal:\d*\)
\t\t testOrg.testPackageWithModules\$test.0.tests.main_test.\$lambda\$_11\(tests/main_test.bal:\d*\)
\t\t testOrg.testPackageWithModules\$test.0.lambdas.\$_generated2tests.main_test.\$lambda\$_11\$lambda1\$\(tests/main_test.bal:\d*\)

Loading
Loading