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 5 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,128 @@

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 hotSpotBeanName = "com.sun.management:type=HotSpotDiagnostic";
ravinperera00 marked this conversation as resolved.
Show resolved Hide resolved
private static volatile HotSpotDiagnosticMXBean hotSpotDiagnosticMXBean;
private static final String workingDir = System.getProperty("user.dir") + "/";
private static final String filename = "threadDump" + LocalDateTime.now();
private static final String virtualThreadIdentifier = "virtual";
private static final String isolatedWorkerIdentifier = "io.ballerina.runtime.internal.scheduling." +
"Scheduler.lambda$startIsolatedWorker";
private static final String nonIsolatedWorkerIdentifier = "io.ballerina.runtime.internal.scheduling." +
"Scheduler.lambda$startNonIsolatedWorker";
private static final String javaTracePattern = "java\\.|\\.java(?::\\d+)?"; // .java, java., .java:(any number)
private static final String balTracePattern = "\\.bal:\\d+"; // .bal:(any number)

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(workingDir + 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(javaTracePattern);
Pattern balPattern = Pattern.compile(balTracePattern);
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(virtualThreadIdentifier)) {
balTraceItems.add("\tStrand " + lines[0].replace(virtualThreadIdentifier, ":") + "\n\t\tat");
String prefix = " ";
for (String line : lines) {
if (!javaPattern.matcher(line).find() && !line.contains("\" " + virtualThreadIdentifier)) {
balTraceItems.add(prefix + line + "\n");
prefix = "\t\t ";
if (balPattern.matcher(line).find()) {
balStrand = true;
}
} else {
if (line.contains(isolatedWorkerIdentifier)) {
isolatedWorkerList.add(id);
} else if (line.contains(nonIsolatedWorkerIdentifier)) {
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) {
synchronized (StrandDump.class) {
ravinperera00 marked this conversation as resolved.
Show resolved Hide resolved
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, hotSpotBeanName, 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