Upgrade async-profiler to v2.8.1 & use mcache (#363)

Upgrade async-profiler to latest release v2.8.1, and use the new mcache option to retain jmethodID -> method name across profiling sessions (because in some JVM versions, this translation is expensive).

Author: Jongy

gprofiler/gprofiler_types.py

@@ -5,7 +5,7 @@
 
 from collections import Counter
 from dataclasses import dataclass
-from typing import Any, Dict, MutableMapping, Optional, Union
+from typing import Any, Callable, Dict, MutableMapping, Optional, Union
 
 import configargparse
 
@@ -44,3 +44,15 @@ def nonnegative_integer(value_str: str) -> int:
     if value < 0:
         raise configargparse.ArgumentTypeError("invalid non-negative integer value: {!r}".format(value))
     return value
+
+
+def integer_range(min_range: int, max_range: int) -> Callable[[str], int]:
+    def integer_range_check(value_str: str) -> int:
+        value = int(value_str)
+        if value < min_range or value >= max_range:
+            raise configargparse.ArgumentTypeError(
+                f"invalid integer value {value!r} (out of range {min_range!r}-{max_range!r})"
+            )
+        return value
+
+    return integer_range_check

gprofiler/profilers/java.py

@@ -38,7 +38,13 @@
 
 from gprofiler import merge
 from gprofiler.exceptions import CalledProcessError, CalledProcessTimeoutError, NoRwExecDirectoryFoundError
-from gprofiler.gprofiler_types import ProcessToProfileData, ProfileData, StackToSampleCount, positive_integer
+from gprofiler.gprofiler_types import (
+    ProcessToProfileData,
+    ProfileData,
+    StackToSampleCount,
+    integer_range,
+    positive_integer,
+)
 from gprofiler.kernel_messages import get_kernel_messages_provider
 from gprofiler.log import get_logger_adapter
 from gprofiler.metadata import application_identifiers
@@ -261,6 +267,8 @@ class AsyncProfiledProcess:
     _FDTRANSFER_TIMEOUT = 10
     _JATTACH_TIMEOUT = 30  # higher than jattach's timeout
 
+    _DEFAULT_MCACHE = 30  # arbitrarily chosen, not too high & not too low.
+
     def __init__(
         self,
         process: Process,
@@ -271,6 +279,7 @@ def __init__(
         ap_safemode: int,
         ap_args: str,
         jattach_timeout: int = _JATTACH_TIMEOUT,
+        mcache: int = 0,
     ):
         self.process = process
         self._stop_event = stop_event
@@ -317,6 +326,7 @@ def __init__(
         self._ap_safemode = ap_safemode
         self._ap_args = ap_args
         self._jattach_timeout = jattach_timeout
+        self._mcache = mcache
 
     def _find_rw_exec_dir(self, available_dirs: Sequence[str]) -> str:
         """
@@ -439,7 +449,7 @@ def _get_start_cmd(self, interval: int, ap_timeout: int) -> List[str]:
 
     def _get_stop_cmd(self, with_output: bool) -> List[str]:
         return self._get_base_cmd() + [
-            f"stop,log={self._log_path_process}"
+            f"stop,log={self._log_path_process},mcache={self._mcache}"
             + (self._get_ap_output_args() if with_output else "")
             + self._get_extra_ap_args()
         ]
@@ -614,9 +624,8 @@ def parse_jvm_version(version_string: str) -> JvmVersion:
         ProfilerArgument(
             "--java-async-profiler-safemode",
             dest="java_async_profiler_safemode",
-            type=int,
             default=JAVA_ASYNC_PROFILER_DEFAULT_SAFEMODE,
-            choices=range(0, 128),
+            type=integer_range(0, 128),
             metavar="[0-127]",
             help="Controls the 'safemode' parameter passed to async-profiler. This is parameter denotes multiple"
             " bits that describe different stack recovery techniques which async-profiler uses (see StackRecovery"
@@ -645,6 +654,15 @@ def parse_jvm_version(version_string: str) -> JvmVersion:
             default=AsyncProfiledProcess._JATTACH_TIMEOUT,
             help="Timeout for jattach operations (start/stop AP, etc)",
         ),
+        ProfilerArgument(
+            "--java-async-profiler-mcache",
+            dest="java_async_profiler_mcache",
+            # this is "unsigned char" in AP's code
+            type=integer_range(0, 256),
+            metavar="[0-255]",
+            default=AsyncProfiledProcess._DEFAULT_MCACHE,
+            help="async-profiler mcache option (defaults to %(default)s)",
+        ),
     ],
 )
 class JavaProfiler(ProcessProfilerBase):
@@ -679,6 +697,7 @@ def __init__(
         java_async_profiler_args: str,
         java_safemode: str,
         java_jattach_timeout: int,
+        java_async_profiler_mcache: int,
         java_mode: str,
     ):
         assert java_mode == "ap", "Java profiler should not be initialized, wrong java_mode value given"
@@ -694,6 +713,7 @@ def __init__(
         self._ap_safemode = java_async_profiler_safemode
         self._ap_args = java_async_profiler_args
         self._jattach_timeout = java_jattach_timeout
+        self._ap_mcache = java_async_profiler_mcache
         self._init_java_safemode(java_safemode)
         self._should_profile = True
         # if set, profiling is disabled due to this safemode reason.
@@ -894,6 +914,7 @@ def _profile_process_stackcollapse(self, process: Process) -> StackToSampleCount
             self._ap_safemode,
             self._ap_args,
             self._jattach_timeout,
+            self._ap_mcache,
         ) as ap_proc:
             return self._profile_ap_process(ap_proc, comm)
 

scripts/async_profiler_build_shared.sh

@@ -5,8 +5,8 @@
 #
 set -euo pipefail
 
-VERSION=v2.7g2
-GIT_REV="6541b573294c3c9e8efb633bc830440a6f2e13d0"
+VERSION=v2.8.1g1
+GIT_REV="a54f956ad4f9ee7601fcfce1a968abdca9921a6d"
 
 git clone --depth 1 -b "$VERSION" https://github.com/Granulate/async-profiler.git && cd async-profiler && git reset --hard "$GIT_REV"
 source "$1"

scripts/async_profiler_env_glibc.sh

@@ -6,4 +6,4 @@
 set -euo pipefail
 
 yum install -y centos-release-scl
-yum install -y devtoolset-7-toolchain make java-1.8.0-openjdk-devel glibc-static git
+yum install -y devtoolset-7-toolchain make java-11-openjdk-devel glibc-static git

scripts/async_profiler_env_musl.sh

@@ -5,4 +5,4 @@
 #
 set -euo pipefail
 
-apk add make gcc g++ openjdk8 musl-dev linux-headers bash git
+apk add make gcc g++ openjdk11 musl-dev linux-headers bash git

tests/test_java.py

@@ -50,9 +50,13 @@ def get_libjvm_path(application_pid: int) -> str:
     return get_lib_path(application_pid, "/libjvm.so")
 
 
+def _read_pid_maps(pid: int) -> str:
+    return Path(f"/proc/{pid}/maps").read_text()
+
+
 def is_libjvm_deleted(application_pid: int) -> bool:
     # can't use get_libjvm_path() - psutil removes "deleted" if the file actually exists...
-    return "/libjvm.so (deleted)" in Path(f"/proc/{application_pid}/maps").read_text()
+    return "/libjvm.so (deleted)" in _read_pid_maps(application_pid)
 
 
 # adds the "status" command to AsyncProfiledProcess from gProfiler.
@@ -340,13 +344,12 @@ def test_sanity_j9(
         assert_collapsed(process_collapsed)
 
 
-@pytest.mark.xfail(
-    reason="AP 2.7 doesn't support, see https://github.com/jvm-profiling-tools/async-profiler/issues/572"
-    " we will fix after that's closed."
-)
 # test only once. in a container, so that we don't mess up the environment :)
 @pytest.mark.parametrize("in_container", [True])
-def test_java_deleted_libjvm(tmp_path: Path, application_pid: int, assert_collapsed: AssertInCollapsed) -> None:
+@pytest.mark.xfail(reason="In CI, file doesn't appear as deleted for some reason... works on my machine :shrug:")
+def test_java_deleted_libjvm(
+    tmp_path: Path, application_pid: int, application_docker_container: Container, assert_collapsed: AssertInCollapsed
+) -> None:
     """
     Tests that we can profile processes whose libjvm was deleted, e.g because Java was upgraded.
     """
@@ -357,7 +360,9 @@ def test_java_deleted_libjvm(tmp_path: Path, application_pid: int, assert_collap
     shutil.copy(libjvm, libjvm_tmp)
     os.unlink(libjvm)
     os.rename(libjvm_tmp, libjvm)
-    assert is_libjvm_deleted(application_pid)
+    assert is_libjvm_deleted(
+        application_pid
+    ), f"Not (deleted) after deleting? libjvm={libjvm} maps={_read_pid_maps(application_pid)}"
 
     with make_java_profiler(storage_dir=str(tmp_path), duration=3) as profiler:
         process_collapsed = snapshot_one_collapsed(profiler)

tests/utils.py

@@ -137,6 +137,7 @@ def make_java_profiler(
     java_async_profiler_args: str = "",
     java_safemode: str = JAVA_SAFEMODE_ALL,
     java_jattach_timeout: int = AsyncProfiledProcess._JATTACH_TIMEOUT,
+    java_async_profiler_mcache: int = AsyncProfiledProcess._DEFAULT_MCACHE,
     java_mode: str = "ap",
 ) -> JavaProfiler:
     assert storage_dir is not None
@@ -152,6 +153,7 @@ def make_java_profiler(
         java_async_profiler_args=java_async_profiler_args,
         java_safemode=java_safemode,
         java_jattach_timeout=java_jattach_timeout,
+        java_async_profiler_mcache=java_async_profiler_mcache,
         java_mode=java_mode,
     )