Memory leak in Wily Introscope

Wygląda na to, że agent Introscope ma wycieki pamięci w natywnym kodzie:

[tomcat@swa158 ~]$ jrcmd 0 print_memusage
18130:
[JRockit] memtrace is collecting data...
[JRockit] *** 0th memory utilization report
(all numbers are in kbytes)
Total mapped                         ;;;;;;;1192600
; Total in-use                        ;;;;;;1182252
;;  executable                         ;;;;;  12260
;;;   java code                         ;;;;   7680;   62.6%
;;;;    used                             ;;;   5763;   75.0%
;;  shared modules (exec+ro+rw)        ;;;;;   4540
;;  guards                             ;;;;;   1056
;;  readonly                           ;;;;;     68
;;  rw-memory                          ;;;;;1177604
;;;   Java-heap                         ;;;; 393216;   33.4%
;;;   Stacks                            ;;;;  22871;   1.9%
;;;   Native-memory                     ;;;; 761516;   64.7%
;;;;    java-heap-overhead               ;;;  12342
;;;;    codegen memory                   ;;;    904
;;;;    classes                          ;;;  29696;   3.9%
;;;;;     method bytecode                 ;;   2927
;;;;;     method structs                  ;;   3278    (#69939)
;;;;;     constantpool                    ;;  11117
;;;;;     classblock                      ;;   1488
;;;;;     class                           ;;   3060    (#8698)
;;;;;     other classdata                 ;;   4942
;;;;;     overhead                        ;;    280
;;;;    threads                          ;;;    107;   0.0%
;;;;    malloc:ed memory                 ;;;  24265;   3.2%
;;;;;     codeinfo                        ;;   1047
;;;;;     codeinfotrees                   ;;    438
;;;;;     exceptiontables                 ;;    591
;;;;;     metainfo/livemaptable           ;;   9324
;;;;;     codeblock structs               ;;      3
;;;;;     constants                       ;;      6
;;;;;     livemap global tables           ;;   2091
;;;;;     callprof cache                  ;;      0
;;;;;     paraminfo                       ;;     88    (#1284)
;;;;;     strings                         ;;   4991    (#92449)
;;;;;     strings(jstring)                ;;      0
;;;;;     typegraph                       ;;   1593
;;;;;     interface implementor list      ;;     48
;;;;;     thread contexts                 ;;     81
;;;;;     jar/zip memory                  ;;   5451
;;;;;     native handle memory            ;;     39
;;;;    unaccounted for memory           ;;; 694309;   91.2%;28.61
---------------------!!!

16612:
[JRockit] memtrace is collecting data...
[JRockit] *** 0th memory utilization report
(all numbers are in kbytes)
Total mapped                         ;;;;;;;1192932
; Total in-use                        ;;;;;;1181960
;;  executable                         ;;;;;  12004
;;;   java code                         ;;;;   7424;   61.8%
;;;;    used                             ;;;   5796;   78.1%
;;  shared modules (exec+ro+rw)        ;;;;;   4540
;;  guards                             ;;;;;   1068
;;  readonly                           ;;;;;     68
;;  rw-memory                          ;;;;;1177312
;;;   Java-heap                         ;;;; 393216;   33.4%
;;;   Stacks                            ;;;;  23003;   2.0%
;;;   Native-memory                     ;;;; 761092;   64.6%
;;;;    java-heap-overhead               ;;;  12342
;;;;    codegen memory                   ;;;    592
;;;;    classes                          ;;;  28928;   3.8%
;;;;;     method bytecode                 ;;   2911
;;;;;     method structs                  ;;   3256    (#69475)
;;;;;     constantpool                    ;;  10845
;;;;;     classblock                      ;;   1441
;;;;;     class                           ;;   2938    (#8350)
;;;;;     other classdata                 ;;   4923
;;;;;     overhead                        ;;     61
;;;;    threads                          ;;;    109;   0.0%
;;;;    malloc:ed memory                 ;;;  24479;   3.2%
;;;;;     codeinfo                        ;;   1019
;;;;;     codeinfotrees                   ;;    420
;;;;;     exceptiontables                 ;;    585
;;;;;     metainfo/livemaptable           ;;   9489
;;;;;     codeblock structs               ;;      3
;;;;;     constants                       ;;      7
;;;;;     livemap global tables           ;;   2183
;;;;;     callprof cache                  ;;      0
;;;;;     paraminfo                       ;;     89    (#1288)
;;;;;     strings                         ;;   4997    (#92452)
;;;;;     strings(jstring)                ;;      0
;;;;;     typegraph                       ;;   1527
;;;;;     interface implementor list      ;;     47
;;;;;     thread contexts                 ;;     82
;;;;;     jar/zip memory                  ;;   5451
;;;;;     native handle memory            ;;     41
;;;;    unaccounted for memory           ;;; 694751;   91.3%;28.38
---------------------!!!

[tomcat@swa158 ~]$

Tomcaty są skonfigurowane z -Xmx384M a pamięć wirtualna (VSZ) dla procesu po dwóch tygodniach wynosi 1192MB, RSS 900MB. Czyli o 500-800MB za dużo. Sama diagnostyka JRockita pokazuje unaccounted for memory 91.3%. Ta sama aplikacja chodząca bez Wily’ego zachowuje się poprawnie. Średnio na dzień wycieka około 50MB pamięci.
W rezultacie po pewnym czasie na produkcji wchodzimy w swapa (co już Wily pokazuje jako wydłużenie się requestów). Jedyne rozwiązanie to cotygodniowy restart tomcatów.

Wyciek mamy w natywnym kodzie. Znajdźmy jakieś natywne biblioteczki:

tomcat@swa175:~/tomcatDiag1/wily> find . -name *.so
./ext/libIntroscopeAIX4PSeries32Stats.so
./ext/libIntroscopeSolarisSparc64Stats.so
./ext/libIntroscopeRedHatStats.so
./ext/libIntroscopeHpuxParisc32Stats.so
./ext/libIntroscopeSolarisSparc32Stats.so
./ext/libIntroscopeSolarisAmd64Stats.so
./ext/libIntroscopeAIX52PSeries64Stats.so
./ext/libIntroscopeAIX53PSeries64Stats.so
./ext/libIntroscopeSolarisAmd32Stats.so
./ext/libIntroscopeHpuxItaniumStats.so
./ext/libIntroscopeAIX5PSeries32Stats.so
./ext/libIntroscopeAIX4PSeries64Stats.so

Zobaczmy jaki kod Javy odwołuje się do libIntroscopeRedHatStats.so:

tomcat@swa175:~/tomcatDiag1/wily> nm ./ext/libIntroscopeRedHatStats.so | grep Java
000015e2 T Java_com_wily_introscope_agent_platform_linux_LinuxPlatformStatisticsBackEnd_getAggregateCPUUsage
0000158e T Java_com_wily_introscope_agent_platform_linux_LinuxPlatformStatisticsBackEnd_getParentProcessID
000011c6 T Java_com_wily_introscope_agent_platform_linux_LinuxPlatformStatisticsBackEnd_getProcessCPUUsage
0000153a T Java_com_wily_introscope_agent_platform_linux_LinuxPlatformStatisticsBackEnd_getProcessID
00001524 T Java_com_wily_introscope_agent_platform_linux_LinuxPlatformStatisticsBackEnd_getProtocolVersion
000017a0 T Java_com_wily_introscope_agent_platform_linux_LinuxPlatformStatisticsBackEnd_getThreadCpuTime
0000148a T Java_com_wily_introscope_agent_platform_linux_LinuxPlatformStatisticsBackEnd_getTotalClockTicks
0000152e T Java_com_wily_introscope_agent_platform_linux_LinuxPlatformStatisticsBackEnd_init
00001796 T Java_com_wily_introscope_agent_platform_linux_LinuxPlatformStatisticsBackEnd_isThreadCpuTimeEnabled
00001534 T Java_com_wily_introscope_agent_platform_linux_LinuxPlatformStatisticsBackEnd_term

Zdekompilujmy JAD-em LinuxPlatformStatisticsBackEnd.class i poszukajmy podejrzanych metod ze słowem kluczowym native:

private native long[] getAggregateCPUUsage(String s)
throws PlaformStatUnavailableException;

Założę się, że char* wyjęte ze Stringa javowego nie jest zwalniane.

Podłączamy IBM JDK z parametrem -Xcheck:jni:all i widzimy:

JVMJNCK071W JNI warning: Memory at 0x080C22A0 acquired by GetStringUTFChars was not released before returning from native. This is probably a memory leak.
JVMJNCK078W Warning detected in com/wily/introscope/agent/platform/linux/LinuxPlatformStatisticsBackEnd.getAggregateCPUUsage(Ljava/lang/String;)[J

czyli Wily faktycznie ma wycieki pamięci. Shame on you CA!

Summary: One of Wily native libraries has improper interactions with Java VM via JNI - it doesn't free memory used for accessing Java strings. I have rewritten the library - sources and binary .so file are avalilable here (archive is protected with password).