JVM_FindSignal function continuously allocates nat

2020-02-14 06:23发布

问题:

My java web application deployed in tomcat8 on a linux machine has been leaking native memory, I've tried to detect the source of the leak by using jemalloc profiling as described here: https://github.com/jeffgriffith/native-jvm-leaks Output of the profiling tool with a heap dump on a server running for > 24 hours:

    Total: 794708494 B
789734456  99.4%  99.4% 789987533  99.4% JVM_FindSignal
 3421211   0.4%  99.8%  3421211   0.4% Java_java_util_zip_ZipFile_getZipMessage
 1036965   0.1%  99.9%  1036965   0.1% inflateBackEnd
  262784   0.0% 100.0%   262784   0.0% __GI__dl_allocate_tls
  253077   0.0% 100.0% 598675182  75.3% SUNWprivate_1.1
       0   0.0% 100.0%   938397   0.1% 0x00007fb133688ef8
       0   0.0% 100.0%   131136   0.0% 0x00007fb133696c2e
       0   0.0% 100.0%  6146839   0.8% 0x00007fb13369b553
       0   0.0% 100.0%   135210   0.0% 0x00007fb1336a63f5
       0   0.0% 100.0%   131136   0.0% 0x00007fb1336a6403
       0   0.0% 100.0%   266290   0.0% 0x00007fb1336a7819
       0   0.0% 100.0%   296275   0.0% 0x00007fb1336a7827
       0   0.0% 100.0%   139434   0.0% 0x00007fb1336a845a
       0   0.0% 100.0%  1221269   0.2% 0x00007fb1336a87e9
       0   0.0% 100.0%   663829   0.1% 0x00007fb1336a87f7
       0   0.0% 100.0%   148137   0.0% 0x00007fb1336a89f7
       0   0.0% 100.0%   143743   0.0% 0x00007fb1336a9068
       0   0.0% 100.0%   270421   0.0% 0x00007fb1336ab23d
       0   0.0% 100.0%   135210   0.0% 0x00007fb1336ab24b
       0   0.0% 100.0%   135210   0.0% 0x00007fb1336ab38b
       0   0.0% 100.0%   132613   0.0% 0x00007fb1336cb294
       0   0.0% 100.0%   131232   0.0% 0x00007fb1336f04da
       0   0.0% 100.0%   136258   0.0% 0x00007fb133925efe
       0   0.0% 100.0%   135210   0.0% 0x00007fb133927cc6
       0   0.0% 100.0%  2012412   0.3% 0x00007fb133929d07
       0   0.0% 100.0% 159413372  20.1% 0x00007fb1339be9a5
       0   0.0% 100.0%   279249   0.0% 0x00007fb1339e897b
       0   0.0% 100.0%   148137   0.0% 0x00007fb133a94545
       0   0.0% 100.0%   131232   0.0% 0x00007fb133a980d4
       0   0.0% 100.0%   266346   0.0% 0x00007fb133ab523b
       0   0.0% 100.0%   444413   0.1% 0x00007fb133ac8727
       0   0.0% 100.0%  4622703   0.6% 0x00007fb133b4c74a
       0   0.0% 100.0%   270666   0.0% 0x00007fb133b91ee7
       0   0.0% 100.0% 28347870   3.6% 0x00007fb133c61c4a
       0   0.0% 100.0%   135210   0.0% 0x00007fb133c94425
       0   0.0% 100.0%  3064228   0.4% 0x00007fb133d7c611
       0   0.0% 100.0%   131080   0.0% 0x00007fb133dfc067
       0   0.0% 100.0%   270421   0.0% 0x00007fb133dfc9f3
       0   0.0% 100.0%   136258   0.0% 0x00007fb1340590c9
       0   0.0% 100.0%   136258   0.0% 0x00007fb1340f60fc
       0   0.0% 100.0%   676053   0.1% 0x00007fb13447aba7
       0   0.0% 100.0%   968594   0.1% 0x00007fb13467ff67
       0   0.0% 100.0%   136258   0.0% 0x00007fb134b8eba6
       0   0.0% 100.0%   431231   0.1% 0x00007fb134c861a7
       0   0.0% 100.0%   136258   0.0% 0x00007fb135122400
       0   0.0% 100.0%   136258   0.0% 0x00007fb1352166b4
       0   0.0% 100.0%   136258   0.0% 0x00007fb135807a38
       0   0.0% 100.0%   136258   0.0% 0x00007fb135807ed1
       0   0.0% 100.0%   136258   0.0% 0x00007fb135822eaf
       0   0.0% 100.0%   297823   0.0% 0x00007fb135f85154
       0   0.0% 100.0%   136258   0.0% 0x00007fb1368a7c42
       0   0.0% 100.0%  1313955   0.2% 0x00007fb136e464e5
       0   0.0% 100.0%   922058   0.1% 0x00007fb137245e69
       0   0.0% 100.0%   408775   0.1% 0x00007fb13734a4aa
       0   0.0% 100.0%  1226327   0.2% 0x00007fb13734a4d3
       0   0.0% 100.0%   272517   0.0% 0x00007fb137e0760f
       0   0.0% 100.0%   681293   0.1% 0x00007fb137e07624
       0   0.0% 100.0%   272517   0.0% 0x00007fb137ea88f5
       0   0.0% 100.0%   136258   0.0% 0x00007fb137ea8aa4
       0   0.0% 100.0%   136258   0.0% 0x00007fb13876c9e9
       0   0.0% 100.0%   136258   0.0% 0x00007fb138c0e8f0
       0   0.0% 100.0%   272517   0.0% 0x00007fb138dca6f7
       0   0.0% 100.0%   272517   0.0% 0x00007fb138dca70c
       0   0.0% 100.0%   272517   0.0% 0x00007fb138dcb5ca
       0   0.0% 100.0%   136258   0.0% 0x00007fb138f0dba8
       0   0.0% 100.0%   136258   0.0% 0x00007fb138fe8f2e
       0   0.0% 100.0%   136258   0.0% 0x00007fb13948cd05
       0   0.0% 100.0%   136258   0.0% 0x00007fb139ee2f9c
       0   0.0% 100.0%   408775   0.1% 0x00007fb13a03f0be
       0   0.0% 100.0%   545034   0.1% 0x00007fb13a04e468
       0   0.0% 100.0%   272517   0.0% 0x00007fb13a04e64e
       0   0.0% 100.0%   136258   0.0% 0x00007fb13a920fca
       0   0.0% 100.0%   136258   0.0% 0x00007fb13a92130b
       0   0.0% 100.0%   136258   0.0% 0x00007fb13af0b151
       0   0.0% 100.0%   136258   0.0% 0x00007fb13b7609a2
       0   0.0% 100.0%   136258   0.0% 0x00007fb13b770cb0
       0   0.0% 100.0%   408775   0.1% 0x00007fb13bd55409
       0   0.0% 100.0%   136258   0.0% 0x00007fb13c062aea
       0   0.0% 100.0%   136258   0.0% 0x00007fb13c06419a
       0   0.0% 100.0%   136258   0.0% 0x00007fb13d264f22
       0   0.0% 100.0%   136258   0.0% 0x00007fb13d264f37
       0   0.0% 100.0%   136258   0.0% 0x00007fb13d265fc4
       0   0.0% 100.0%   408775   0.1% 0x00007fb13d3fb048
       0   0.0% 100.0% 698085685  87.8% AsyncGetCallTrace
       0   0.0% 100.0% 162799014  20.5% JNI_CreateJavaVM
       0   0.0% 100.0% 35102689   4.4% JNI_GetCreatedJavaVMs
       0   0.0% 100.0%   131296   0.0% JNU_NewObjectByName
       0   0.0% 100.0%  4766447   0.6% JVM_DefineClass
       0   0.0% 100.0% 29155153   3.7% JVM_DefineClassWithSource
       0   0.0% 100.0%  1204712   0.2% JVM_DoPrivileged
       0   0.0% 100.0%   444413   0.1% JVM_FillInStackTrace
       0   0.0% 100.0%   266346   0.0% JVM_FindClassFromBootLoader
       0   0.0% 100.0%   270421   0.0% JVM_FindClassFromCaller
       0   0.0% 100.0%   279249   0.0% JVM_FindLoadedClass
       0   0.0% 100.0%   131080   0.0% JVM_GetClassDeclaredConstructors
       0   0.0% 100.0%   824436   0.1% JVM_GetClassDeclaredFields
       0   0.0% 100.0%   942399   0.1% JVM_GetClassDeclaredMethods
       0   0.0% 100.0%   135210   0.0% JVM_GetClassName
       0   0.0% 100.0% 159413372  20.1% JVM_InternString
       0   0.0% 100.0%   253077   0.0% JVM_LoadLibrary
       0   0.0% 100.0%   431231   0.1% JVM_MonitorWait
       0   0.0% 100.0%   409855   0.1% JVM_RawMonitorExit
       0   0.0% 100.0%  1707451   0.2% JVM_StartThread
       0   0.0% 100.0% 714622614  89.9% JVM_handle_linux_signal
       0   0.0% 100.0%   253077   0.0% Java_java_lang_ClassLoader_00024NativeLibrary_load
       0   0.0% 100.0% 29155153   3.7% Java_java_lang_ClassLoader_defineClass1
       0   0.0% 100.0%   266346   0.0% Java_java_lang_ClassLoader_findBootstrapClass
       0   0.0% 100.0%   270421   0.0% Java_java_lang_Class_forName0
       0   0.0% 100.0%   444413   0.1% Java_java_lang_Throwable_fillInStackTrace
       0   0.0% 100.0%   131136   0.0% Java_java_lang_reflect_Proxy_defineClass0
       0   0.0% 100.0%  1036965   0.1% Java_java_util_zip_Inflater_inflateBytes
       0   0.0% 100.0%  3064228   0.4% Java_java_util_zip_ZipFile_open
       0   0.0% 100.0%   131296   0.0% Java_sun_management_Flag_getFlags
       0   0.0% 100.0%   356982   0.0% ZIP_Open
       0   0.0% 100.0%  3421211   0.4% ZIP_Unlock
       0   0.0% 100.0% 569857981  71.7% __clone
       0   0.0% 100.0%   253077   0.0% __dlopen_check
       0   0.0% 100.0%   262784   0.0% __pthread_create_2_1
       0   0.0% 100.0%   253077   0.0% _dl_catch_error
       0   0.0% 100.0%   253077   0.0% _dl_init_internal
       0   0.0% 100.0%   253077   0.0% _dl_open
       0   0.0% 100.0%   253077   0.0% _dlerror_run
       0   0.0% 100.0%   253077   0.0% dl_open_worker
       0   0.0% 100.0%   253077   0.0% dlopen_doit
       0   0.0% 100.0%   393920   0.0% fork1
       0   0.0% 100.0%  1036965   0.1% inflate
       0   0.0% 100.0% 569857981  71.7% start_thread

As graph:

I have also used Java Native Memory Tracking tool to pinpoint the leak https://docs.oracle.com/javase/8/docs/technotes/guides/vm/nmt-8.html The NMT reported memory to be leaked under 'Internal' section. The call graph suggests that the JVM_FindSignal is called as a result of start_thread, however, NMT diff tool reported that amount of application threads is almost constant and stays at ~300.

JVM options:

    -Xms24920m -Xmx24920m -XX:MaxMetaspaceSize=512m -XX:+AlwaysPreTouch 
    -XX:+UseG1GC -XX:G1HeapWastePercent=10 
-XX:+UseTLAB 
-XX:+ScavengeBeforeFullGC -verbose:gc 
-XX:+PrintGCDetails 
    -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution 
    -XX:+PrintGCApplicationConcurrentTime 
-XX:+PrintGCApplicationStoppedTime 
    -Djava.rmi.server.hostname=XXXXX 
-Dcom.sun.management.jmxremote.port=XXXXX 
-Dcom.sun.management.jmxremote.ssl=false

So, JVM_FindSignal has allocated and not released 789 Megabytes of native memory, does anyone has an idea of what JVM_FindSignal does and why would it be continuously allocating memory?

回答1:

JVM_FindSignal does not allocate memory at all. And this function is not typically called often at application run-time.

It seems your JDK installation does not include debug symbols, so that jemalloc profiler cannot find the correct function name and just takes the nearest public symbol from libjvm.so. JVM_FindSignal is just one of these random symbols. Other entries in the profile also look wrong. E.g. AsyncGetCallTrace which is accounted for 87.8% also allocates nothing at all.

Installing a separate package with JDK debug symbols might help.

On Debian / Ubuntu:

apt install openjdk-8-dbg

On RHEL / CentOS:

debuginfo-install java-1.8.0-openjdk