Add JVM Profiling #189

lancelui-amzn · 2024-06-20T14:20:13Z

Description of changes:

Use async-profiler to profile java virtual machines and generate flamegraphs. The flamegraph tab is modified to allow the selection between perf and async-profiler flamegraphs.
--profile-java option added to enable and pass args for JVM profiling, specify JVMs by comma separated PIDs or names
Datatypes have new is_profile_option bool field that flags whether the datatype can be enabled and disabled by the profile subcommand (applicable to perf_profile, flamegraph, and java_profile datatypes).
InitParams and CollectorParams now also contain profiler arguments.

Test Cases:
14 test cases were run with varying options and JVM setups. Tests were evaluated visually through the aperf report.

record
record with java profile, 2 JVMs in background
record with java profile, specify 1 of 2 JVMs in background
record with java profile, specify 2 of 2 JVMs in background
record with java profile, 2 JVMs in background and 1 started at 7 seconds
record with profile
record with profile and java profile, 2 JVMs in background
record with java profile, specify 1 of 2 JVMs in background by name
record with java profile, specify 2 of 2 JVMs in background by name and pid
record with java profile, specify 2 JVMs in background and 1 started at 2 seconds (should not record last JVM)
record with java profile, no JVMs on system
record with java profile, 2 JVMs with disabled perf shared mem
record with perf and java profile, 0 JVMs
record with perf and java profile, 3 JVMS started during and 1 ended early

Example of output:

By submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice.

janaknat · 2024-06-26T15:31:06Z

src/data/java_profile.rs

+
+impl CollectData for JavaProfileRaw {
+    fn prepare_data_collector(&mut self, params: CollectorParams) -> Result<()> {
+        let jps_out = Command::new("jps").output().expect("'jps' command failed.");


Can we propagate the error?

janaknat · 2024-06-26T15:31:45Z

src/data/java_profile.rs

+        let jps: Vec<&str> = jps_str.split_whitespace().collect();
+        let mut process_map: HashMap<String, Vec<String>> = HashMap::new();
+        for i in (0..jps.len()).step_by(2) {
+            if jps[i + 1] != "Jps" {


What is the output of the jps command?

Default jps lists the PID and name for each JVM separated by a newline:

<PID> <NAME> <PID> <NAME> ... <PID> <NAME>

janaknat · 2024-06-26T15:32:51Z

src/data/java_profile.rs

+        }
+
+        let mut jids: Vec<String> = Vec::new();
+        let jprofile = params.profile.get(JAVA_PROFILE_FILE_NAME).unwrap().as_str();


What happens when the get fails and we blindly unwrap()?

Java profile is only enabled when params.profile has JAVA_PROFILE_NAME so it is not possible for unwrap to fail.

janaknat · 2024-06-26T15:34:18Z

src/data/java_profile.rs

+                    if !jps.contains(&arg) {
+                        error!("No JVM with name/PID '{}'.", arg);
+                        continue;
+                    } else if jps.iter().position(|&r| r == arg).unwrap()


Is this so the user can provide either a pid or a name? Would it make sense to simplify it and only allow pids?

Yes right now the user can specify either pids or names. We could simplify but that would diverge from the functionality of async-profiler, which allows this.

src/data/java_profile.rs

janaknat · 2024-06-26T15:46:20Z

src/data/java_profile.rs

+
+            process_map
+                .entry(process)
+                .and_modify(|v| v.push(html.len().to_string()));


Why do we need this?

This saves the filesize with the PID and Name for here.

src/html_files/index.ts

janaknat · 2024-06-26T15:49:00Z

src/html_files/index.html

 			<div id="flamegraphs" class="tabcontent">
+				<div class="extra">
+					<button class="flamegraphs-select" id="flamegraphs"> perf </button>
+					<button class="flamegraphs-select" id="javaprofile"> java </button>


These buttons exists even if there are no javaprofiles? What happens if the user clicks it when no javaprofiles exist?

It displays "No data collected." similar to the perf flamegraph.

src/html_files/index.ts

janaknat · 2024-06-26T15:49:55Z

src/html_files/index.ts

 function display_tab(name) {
 	let datatype = DataTypes.get(name);
-	if (datatype.hideClass != "") {
+	if(datatype.hideClass == "flamegraphsSelection"){


Why do we special case the flamegraphsSelection? This can go inside the hideclass != "" check.

The flamegraph datatype callback takes a string, while the other ones take a bool or nothing.

janaknat · 2024-07-02T17:01:48Z

src/data/java_profile.rs

+                jps_str = String::from_utf8(jps_out.stdout).unwrap_or_default();
+                let jps: Vec<&str> = jps_str.split_whitespace().collect();
+                for i in (0..jps.len()).step_by(2) {
+                    if jps[i + 1] != "Jps" {


Add a print for the new JVM with name and JID. Both this and the print at the start of the function should be debug.

New JVM/JID info is printed at the trace level when async-profiler is successfully launched. Should that be changed to debug?

src/data/java_profile.rs

wash-amzn

It would help the review if the PR description included the cases tested and the corresponding outputs (at least snippets of them that are relevant to the case).

wash-amzn · 2024-07-10T13:51:02Z

README.md

 - Network stats
 - Meminfo
 - Profile data (if enabled with `--profile` and `perf` binary present)
+- JVM profile data with `jps` command and [async-profiler](https://github.com/async-profiler/async-profiler/tree/master) binary


Just 'JVM profile data with async profiler', no need to mention the jps detail

wash-amzn · 2024-07-10T14:01:01Z

src/data.rs

    pub fn collect_data(&mut self) -> Result<()> {
        trace!("Collecting Data...");
-        self.data.collect_data()?;
+        self.data.collect_data(self.collector_params.clone())?;


These should be passable as a reference instead of cloning them every time.

Definitely would help avoid having so many .clone() calls all over the place

Makes sense, this is matched with the other stages of record (prepare_data_collector, finish_data_collection, after_data_collection). Should we change those too?

Data types should be able to figure out all of this kind of thing at prepare time, and then just store it in their own fields.

DataTypes store this in their own fields, they are passed to the respective Data enums when their functions are called.

wash-amzn · 2024-07-10T14:06:29Z

src/data/diskstats.rs

+        let params = CollectorParams::new();
+
+        stat.collect_data(params).unwrap();


Having to do this in places suggests that this is probably the wrong approach (re-passing params down to collectors on every collect_data call). There should be a way to get this to the collectors just once at initialization/setup time.

It does get passed to the DataType, but not Data where these functions are called. Adding params to the Data itself kind of breaks the Data enum pattern. Passable by reference seems like a better approach?

wash-amzn · 2024-07-10T14:09:50Z

src/html_files/index.ts

+	if(datatype.hideClass == "flamegraphsSelection") {
+		datatype.callback(name);
+	} else if (datatype.hideClass != "") {


This is definitely looking like we need a different kind of change, instead of abusing an existing attribute and having to start special-casing certain values of it.

Will use union type to remove this special case in index.

wash-amzn · 2024-07-10T14:37:05Z

src/lib.rs

                    continue;
                }

+                datatype.collector_params.elapsed_time = start.elapsed().as_secs();


Is the part of this diff referencing times actually new, or is it an artifact of merging Janak's recent changes?

If it's new (well, even if it's merged), this appears to be doing things in seconds, (at least the new field it's stored in us u64, not floating-point), which can't be right.

This is not related to Janak's changes. start.elapsed() is a Duration that measures the seconds and we convert it to u64 with as_secs(). This is originally used to keep track of the time elapsed for the record and we are passing it to the collector_params so java profile knows the remaining time to launch new async-profilers.

wash-amzn · 2024-07-10T15:29:45Z

src/data/java_profile.rs

+                        error!("No JVM with name/PID '{}'.", arg);
+                        continue;


We have to figure out what the behavior is here. I would say specifying a pid that doesn't exist should be fatal, but names are not as clear-cut. We may want to keep looking for only that name to appear during recording.

What are the names, anyway? Can you provide examples?

Names are either the classname or JAR file name that the JVM was launched on. For example, if I compile and run program.java, I can specify it with the java profile flag: ./aperf record --profile-java program.

When providing multiple PIDs, what if some are valid but some aren't?

wash-amzn · 2024-07-10T15:31:42Z

src/data/java_profile.rs

+                        error!("Multiple JVMs with the name '{}', please provide PID.", arg);
+                        continue;


I think it might be better to just profile all of them. However, that depends on what name actually is, I might change my view if I saw them.

Similar to this example with program.java.
Running,

java program & java program & ./aperf record --profile-java program

will result in this error.

I think we want to profile all of them. Some workloads will be multiple JVMs (typically to have separate, smaller heaps for shorter GC pauses) running the same thing.

wash-amzn · 2024-07-10T15:34:31Z

src/data/java_profile.rs

+                    if let Some(jid) = self.get_jid(arg) {
+                        jids.push(jid);
+                    }


How would it be possible this is None, given the if statement a couple lines up? We need to be careful about the various data structures we have and how they can be inconsistent with respect to eachother.

And if this legitimately can happen, it should be reflected to the user somehow, not silently dropped.

You're right, it is not possible to be none. Changed to handle inside of get_jid function.

wash-amzn · 2024-07-10T15:36:19Z

src/data/java_profile.rs

+
+    fn launch_asprof(&self, jids: Vec<String>, params: CollectorParams) -> Result<()> {
+        let data_dir = PathBuf::from(params.data_dir.clone());
+        for jid in &jids {


jid is simply the pid of a (presumably) java process, right?

wash-amzn · 2024-07-10T15:38:16Z

src/data/java_profile.rs

+                Err(e) => {
+                    error!("'asprof' did not exit successfully: {}", e);
+                    return Ok(());
+                }


This happens if process is owned by another user, right?

I think so, and any other error when async-profiler is started properly.

Where does async-profiler's stderr output go in cases like that?

It is inherited from aperf process.

janaknat · 2024-07-12T19:28:22Z

src/data/java_profile.rs

+                ])
+                .spawn()
+            {
+                Err(e) => {


Do we want to fail here? The user java profiling but we are unable to do it. This might be also applicable to perf. Maybe something common could be done. It shouldn't be a blocker for now.

Also, we print this message for n JVMs? Async-profiler is unavailable and we have 10 JVMs, this is printed 10 times?

Yes, I think we do want to fail here. If not, then we should break out and remove the datatype on the first error.

What is the output on a panic? We want to fail gracefully.

This is the output when asprof is not downloaded:

thread 'main' panicked at src/data/java_profile.rs:53:25:
'asprof' command not found.
note: run with RUST_BACKTRACE=1 environment variable to display a backtrace

Can we return an Error defined in PDError? That should force aperf to remove the java collector.

This would allow aperf to continue right? Should we keep the panics on missing jps/pgrep?

Ah. I see. Yeah. We want to not continue.

janaknat · 2024-07-15T15:33:02Z

src/lib.rs

            match datatype.prepare_data_collector() {
                Err(e) => {
+                    if name == data::java_profile::JAVA_PROFILE_FILE_NAME
+                        || name == data::perf_profile::PERF_PROFILE_FILE_NAME


Can we use data.is_profile_option which was added in this? Then we won't have to specify a new profiler if/when we add it.

Yes, that will work. 👍

rajeshvandanapu · 2024-07-15T17:06:38Z

tests/test_aperf.rs

            interval: 1,
            period: 2,
            profile: false,
+            profile_java: None,


Why not add one more new test case to test Java profile ?

We cannot test the profile because of the asprof dependency and no java workload on the machine.

lancelui-amzn requested a review from a team as a code owner June 20, 2024 14:20

lancelui-amzn requested a review from janaknat June 20, 2024 18:20

janaknat reviewed Jun 26, 2024

View reviewed changes

lancelui-amzn force-pushed the java-profile branch from 2260931 to 6888c91 Compare June 26, 2024 21:01

janaknat reviewed Jul 2, 2024

View reviewed changes

lancelui-amzn force-pushed the java-profile branch from c247133 to ae6dcaa Compare July 3, 2024 16:15

lancelui-amzn requested a review from wash-amzn July 3, 2024 19:22

wash-amzn reviewed Jul 10, 2024

View reviewed changes

janaknat reviewed Jul 12, 2024

View reviewed changes

janaknat reviewed Jul 15, 2024

View reviewed changes

rajeshvandanapu reviewed Jul 15, 2024

View reviewed changes

janaknat approved these changes Jul 15, 2024

View reviewed changes

Added java virtual machine profiling and flamegraph generation

5fe4869

lancelui-amzn force-pushed the java-profile branch from 79dde64 to 5fe4869 Compare July 15, 2024 19:40

janaknat merged commit ef2dd06 into main Jul 15, 2024

		let params = CollectorParams::new();

		stat.collect_data(params).unwrap();

		error!("Multiple JVMs with the name '{}', please provide PID.", arg);
		continue;

Add JVM Profiling #189

Add JVM Profiling #189

Uh oh!

Conversation

lancelui-amzn commented Jun 20, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

wash-amzn left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

lancelui-amzn commented Jun 20, 2024 •

edited

Loading