java - Understanding Jeprofile output

Question

I was able to generate the Jeprofile output as follows based on the descriptions present here jemalloc post

Please find the jemalloc output and the graph.

> Using local file /bin/java. Using local file jeprof.57473.0.f.heap.
> Total: 79372091 B 78084060  98.4%  98.4% 78084060  98.4%
> je_prof_backtrace  1288031   1.6% 100.0%  1474342   1.9%
> Java_java_util_zip_ZipFile_getZipMessage
>        0   0.0% 100.0%  6889972   8.7% 0x00007f3d5ebac3e6
>        0   0.0% 100.0%   270421   0.3% 0x00007f3d5ebb8a79
>        0   0.0% 100.0%   727762   0.9% 0x00007f3d5ebb8a87
>        0   0.0% 100.0%   589239   0.7% 0x00007f3d5ebb9ab2
>        0   0.0% 100.0%   854269   1.1% 0x00007f3d5ebb9ac0
>        0   0.0% 100.0%   270421   0.3% 0x00007f3d5ebb9cb7
>        0   0.0% 100.0%   135210   0.2% 0x00007f3d5ebbc5fa
>        0   0.0% 100.0%   135210   0.2% 0x00007f3d5ebbc768
>        0   0.0% 100.0%   135210   0.2% 0x00007f3d5ee57146
>        0   0.0% 100.0%   143743   0.2% 0x00007f3d5ee8bc25
>        0   0.0% 100.0%   444413   0.6% 0x00007f3d5ef13945
>        0   0.0% 100.0%   136258   0.2% 0x00007f3d5ef764fb
>        0   0.0% 100.0%  8463202  10.7% 0x00007f3d5efbdb8a
>        0   0.0% 100.0%   143743   0.2% 0x00007f3d5f220c67
>        0   0.0% 100.0%   135210   0.2% 0x00007f3d5f3a5c65
>        0   0.0% 100.0% 55473738  69.9% AsyncGetCallTrace
>        0   0.0% 100.0% 48103708  60.6% JLI_GetStdArgc
>        0   0.0% 100.0% 48103708  60.6% JNI_CreateJavaVM
>        0   0.0% 100.0% 11897251  15.0% JNI_GetCreatedJavaVMs
>        0   0.0% 100.0% 11897251  15.0% JVM_DefineClassWithSource
>        0   0.0% 100.0%   271469   0.3% JVM_FindClassFromBootLoader
>        0   0.0% 100.0%   431486   0.5% JVM_FindClassFromCaller
>        0   0.0% 100.0%   131120   0.2% JVM_FindLoadedClass
>        0   0.0% 100.0% 76994237  97.0% JVM_FindSignal
>        0   0.0% 100.0%   148137   0.2% JVM_GetCPMethodClassNameUTF
>        0   0.0% 100.0%   148137   0.2% JVM_GetCPMethodSignatureUTF
>        0   0.0% 100.0%   135210   0.2% JVM_GetClassDeclaredFields
>        0   0.0% 100.0%   405631   0.5% JVM_GetClassName
>        0   0.0% 100.0%   143743   0.2% JVM_IHashCode
>        0   0.0% 100.0%   143743   0.2% JVM_MonitorWait
>        0   0.0% 100.0%   431486   0.5% JVM_RawMonitorExit
>        0   0.0% 100.0%   659324   0.8% JVM_StartThread
>        0   0.0% 100.0% 77220036  97.3% JVM_handle_linux_signal
>        0   0.0% 100.0% 11897251  15.0% Java_java_lang_ClassLoader_defineClass1
>        0   0.0% 100.0%   271469   0.3% Java_java_lang_ClassLoader_findBootstrapClass
>        0   0.0% 100.0%   431486   0.5% Java_java_lang_Class_forName0
>        0   0.0% 100.0%   592551   0.7% Java_java_util_zip_Inflater_inflateBytes
>        0   0.0% 100.0%   134688   0.2% Java_java_util_zip_Inflater_init
>        0   0.0% 100.0%  1117359   1.4% Java_java_util_zip_ZipFile_open
>        0   0.0% 100.0% 75438262  95.0% SUNWprivate_1.1
>        0   0.0% 100.0%   296275   0.4% VerifyClassForMajorVersion
>        0   0.0% 100.0%   356982   0.4% ZIP_Open
>        0   0.0% 100.0%  1474342   1.9% ZIP_Unlock
>        0   0.0% 100.0%   176271   0.2% _GLOBAL__sub_I_eh_alloc.cc
>        0   0.0% 100.0%   176271   0.2% _GLOBAL__sub_I_eh_alloc.cc (inline)
>        0   0.0% 100.0% 59721527  75.2% __clone
>        0   0.0% 100.0%   176271   0.2% __static_initialization_and_destruction_0 (inline)
>        0   0.0% 100.0%   176271   0.2% _dl_init_internal
>        0   0.0% 100.0%   176271   0.2% _dl_start_user
>        0   0.0% 100.0%   131184   0.2% fork1
>        0   0.0% 100.0% 78084060  98.4% imalloc (inline)
>        0   0.0% 100.0% 78084060  98.4% imalloc_body (inline)
>        0   0.0% 100.0%   592551   0.7% inflate
>        0   0.0% 100.0%   592551   0.7% inflateBackEnd
>        0   0.0% 100.0%   134688   0.2% inflateInit2_
>        0   0.0% 100.0% 78084060  98.4% je_malloc_default
>        0   0.0% 100.0% 78084060  98.4% prof_alloc_prep (inline)
>        0   0.0% 100.0% 59721527  75.2% start_thread

The graph is also attached

Need some help in understanding where the problem is?

Enviornment is: Centos 7 Java 1.8.0 GCC 9

Thank!

Answer 1

1. In your jemalloc output, JVM_FindSignal is accounted for 97% of allocations. This can't be true, since JVM_FindSignal does not allocate anything.

   This must be the result of the issue that JVM has no debug symbols. Install the package with JDK debug symbols as descibed in this answer, or use JDK with built-in debug symbols, e.g. Liberica JDK.

2. jemalloc does not know anything about Java methods. It can't translate the addresses in JIT compiled code to Java method names. Hence so many addresses (hex numbers) in your jemalloc output.

   There is a Java profiler, async-profiler, that can trace native memory allocations down to Java code, and show Java stack traces as Flame Graphs. Profiling malloc, mprotect and mmap calls with async-profiler can be helpful in finding native memory leaks. See this answer for details.

   There is a presentation video showing an example of profiling native allocations with both jemalloc and async-profiler.