High memory usage / leaks was: Best mailing list for JVM embedding

Mon Jan 21 18:48:37 UTC 2019

On 1/21/19 8:25 AM, Robert Marcano wrote:
> On 1/21/19 5:19 AM, Volker Simonis wrote:
>> -- Moved to hotspot-dev --
>>
>> Hi Robert,
>>
>> You can use "-XX:+PrintFlagsFinal" and compare the output for the two
>> variants to see if for some reason there are differing option
>> settings.
> 
> Thanks, compared the output of that on a java launcher call and my 
> launcher and get the same flagsa values, so it doesn't look like 
> different defaults isn't the problem

When testing this, trying to discard some weird Rust / OpenJDK 11 
interactions, I wrote a simpler test case using the JVM invocation API 
from plain C. Noticed the same pattern of high memory usage, but it 
allowed me to detect there was a difference when using the provided java 
launcher and our custom launcher.

Every VM option was the same (as strings), including the classpath. Both 
have something like -Djava.class.path=../lib/a.jar:../lib/b.jar

But for some error in the configuration of our test environment, ../lib 
pointed to different directories for both launchers. Different ../lib 
directories with the same JARs, the difference between them is that the 
use for the java launcher are unsigned and ../lib for the custom 
launcher are signed. These jars are signed because they come from a JNLP 
application, the new launcher is part of our migration out of JNLP.

So I managed to replicate the high memory usage using the standard java 
launcher.

So the question now is, why signed jars could affect the memory usage of 
an application (we aren't doing JAR verification on our custom launcher, 
yet), just by being on the java.class.path? IIRC the initial application 
classpath JARs were never verified previously (by the java launcher 
alone, without JNLP around).

Note: Tested with JARs signed with a self signed certificate and with 
one signed with a private CA. At most, signing the JARs could slow down 
the start up if it is now expected to these being verified by the java 
launcher (is it true?) but not higher memory usage and no reductions 
after a GC cycle but constants heap size increases.

> 
>>
>> Regards,
>> Volker
>>
>> On Sat, Jan 19, 2019 at 6:23 PM Robert Marcano 
>> <robert at marcanoonline.com> wrote:
>>>
>>> Greetings, which is the best mailing list for discussions about
>>> embedding the JVM (via JNI_CreateJavaVM)?
>>>
>>> The JVM is being embedded for desktop integration issues, for example to
>>> show the appropriate application name on the process list instead of
>>> java/java.exe, among many other things.
>>>
>>> I am experiencing what looks like higher memory usage and/or failure to
>>> garbage collect correctly when OpenJDK 11 is the embedded JVM. Starting
>>> a test application using the java launcher, I get a GC log like this:
>>>
>>>> [0.007s][info][gc] Using G1
>>>> [0.389s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 10M->8M(124M) 8.661ms
>>>> [0.705s][info][gc] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 13M->10M(124M) 6.148ms
>>>> Jan 19, 2019 1:04:26 PM test.Test init
>>>> FINE: Starting application
>>>> [1.376s][info][gc] GC(3) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 18M->10M(40M) 4.763ms
>>>> [2.288s][info][gc] GC(4) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 23M->12M(40M) 6.382ms
>>>> [2.444s][info][gc] GC(5) Pause Young (Concurrent Start) (Metadata GC 
>>>> Threshold) 18M->12M(48M) 7.579ms
>>>> [2.444s][info][gc] GC(6) Concurrent Cycle
>>>> [2.481s][info][gc] GC(6) Pause Remark 13M->13M(48M) 5.255ms
>>>> [2.498s][info][gc] GC(6) Pause Cleanup 13M->13M(48M) 0.090ms
>>>> [2.499s][info][gc] GC(6) Concurrent Cycle 54.811ms
>>>> [2.905s][info][gc] GC(7) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 26M->13M(48M) 12.726ms
>>>> [3.204s][info][gc] GC(8) Pause Young (Normal) (GCLocker Initiated 
>>>> GC) 29M->15M(48M) 11.216ms
>>>> [3.462s][info][gc] GC(9) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 30M->17M(48M) 18.043ms
>>>> [3.679s][info][gc] GC(10) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 31M->18M(64M) 15.195ms
>>>> [3.933s][info][gc] GC(11) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 38M->20M(64M) 9.412ms
>>>> [4.230s][info][gc] GC(12) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 40M->21M(64M) 16.319ms
>>>> [4.536s][info][gc] GC(13) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 41M->23M(64M) 23.897ms
>>>> [4.750s][info][gc] GC(14) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 43M->24M(94M) 8.776ms
>>>> [5.180s][info][gc] GC(15) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 58M->26M(94M) 15.610ms
>>>> [5.546s][info][gc] GC(16) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 67M->27M(94M) 18.075ms
>>>> [6.058s][info][gc] GC(17) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 69M->30M(94M) 32.625ms
>>>> [7.268s][info][gc] GC(18) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 71M->31M(156M) 18.999ms
>>>> [7.458s][info][gc] GC(19) Pause Young (Concurrent Start) (Metadata 
>>>> GC Threshold) 40M->31M(156M) 20.217ms
>>>> [7.459s][info][gc] GC(20) Concurrent Cycle
>>>> [7.676s][info][gc] GC(20) Pause Remark 35M->35M(156M) 19.304ms
>>>> [7.748s][info][gc] GC(20) Pause Cleanup 36M->36M(156M) 0.183ms
>>>> [7.782s][info][gc] GC(20) Concurrent Cycle 323.765ms
>>>> [8.899s][info][gc] GC(21) Pause Young (Concurrent Start) (G1 
>>>> Evacuation Pause) 84M->40M(156M) 69.976ms
>>>> [8.899s][info][gc] GC(22) Concurrent Cycle
>>>> [9.152s][info][gc] GC(22) Pause Remark 47M->47M(156M) 21.133ms
>>>> [9.244s][info][gc] GC(22) Pause Cleanup 49M->49M(156M) 0.127ms
>>>> [9.247s][info][gc] GC(22) Concurrent Cycle 348.256ms
>>>> [10.203s][info][gc] GC(23) Pause Young (Normal) (G1 Evacuation 
>>>> Pause) 97M->55M(156M) 74.572ms
>>>> [11.102s][info][gc] GC(24) Pause Full (System.gc()) 100M->21M(77M) 
>>>> 115.166ms
>>>> [15.382s][info][gc] GC(25) Pause Young (Normal) (G1 Evacuation 
>>>> Pause) 48M->22M(154M) 6.371ms
>>>
>>> When the same Java 11 JVM is loaded via JNI, with the same VM arguments
>>> than using the java launcher, the log look like this (to reach the same
>>> point at startup)
>>>
>>>> [0.015s][info][gc] Using G1
>>>> [0.501s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 6M->1M(124M) 8.550ms
>>>> [0.785s][info][gc] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 8M->3M(124M) 6.533ms
>>>> [0.940s][info][gc] GC(2) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 14M->7M(124M) 17.822ms
>>>> [1.212s][info][gc] GC(3) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 22M->10M(124M) 11.145ms
>>>> [1.462s][info][gc] GC(4) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 29M->15M(180M) 16.451ms
>>>> [1.695s][info][gc] GC(5) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 47M->25M(180M) 38.828ms
>>>> [2.041s][info][gc] GC(6) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 55M->30M(180M) 22.151ms
>>>> [2.346s][info][gc] GC(7) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 80M->49M(180M) 53.093ms
>>>> Jan 19, 2019 1:01:05 PM test.Test init
>>>> FINE: Starting application
>>>> [4.094s][info][gc] GC(9) Pause Young (Concurrent Start) (Metadata GC 
>>>> Threshold) 64M->40M(258M) 50.663ms
>>>> [4.094s][info][gc] GC(10) Concurrent Cycle
>>>> [4.480s][info][gc] GC(10) Pause Remark 48M->48M(258M) 7.442ms
>>>> [4.652s][info][gc] GC(10) Pause Cleanup 55M->55M(258M) 0.186ms
>>>> [4.656s][info][gc] GC(10) Concurrent Cycle 562.009ms
>>>> [5.174s][info][gc] GC(11) Pause Young (Concurrent Start) (G1 
>>>> Evacuation Pause) 82M->46M(258M) 24.726ms
>>>> [5.174s][info][gc] GC(12) Concurrent Cycle
>>>> [5.513s][info][gc] GC(12) Pause Remark 56M->56M(258M) 11.695ms
>>>> [5.657s][info][gc] GC(12) Pause Cleanup 62M->62M(258M) 0.176ms
>>>> [5.660s][info][gc] GC(12) Concurrent Cycle 486.466ms
>>>> [6.430s][info][gc] GC(13) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 107M->58M(258M) 55.665ms
>>>> [7.538s][info][gc] GC(14) Pause Young (Normal) (G1 Evacuation Pause) 
>>>> 107M->63M(258M) 58.642ms
>>>> [8.724s][info][gc] GC(15) Pause Young (Concurrent Start) (Metadata 
>>>> GC Threshold) 91M->68M(496M) 47.374ms
>>>> [8.724s][info][gc] GC(16) Concurrent Cycle
>>>> [9.417s][info][gc] GC(16) Pause Remark 79M->79M(496M) 19.350ms
>>>> [9.557s][info][gc] GC(16) Pause Cleanup 81M->81M(496M) 0.340ms
>>>> [9.575s][info][gc] GC(16) Concurrent Cycle 850.788ms
>>>> [10.954s][info][gc] GC(17) Pause Young (Concurrent Start) (G1 
>>>> Evacuation Pause) 134M->85M(496M) 162.779ms
>>>> [10.954s][info][gc] GC(18) Concurrent Cycle
>>>> [11.389s][info][gc] GC(19) Pause Young (Normal) (G1 Evacuation 
>>>> Pause) 99M->90M(496M) 79.954ms
>>>> [11.519s][info][gc] GC(18) Pause Remark 93M->92M(496M) 24.636ms
>>>> [11.896s][info][gc] GC(18) Pause Cleanup 102M->102M(496M) 0.326ms
>>>> [11.903s][info][gc] GC(18) Concurrent Cycle 949.231ms
>>>> [17.356s][info][gc] GC(22) Pause Young (Concurrent Start) (G1 
>>>> Humongous Allocation) 131M->81M(365M) 56.745ms
>>>> [17.357s][info][gc] GC(23) Concurrent Cycle
>>>> [17.706s][info][gc] GC(23) Pause Remark 116M->113M(365M) 31.351ms
>>>> [18.008s][info][gc] GC(23) Pause Cleanup 117M->117M(365M) 0.250ms
>>>> [18.018s][info][gc] GC(23) Concurrent Cycle 661.284ms
>>>> [18.888s][info][gc] GC(24) Pause Young (Normal) (G1 Evacuation 
>>>> Pause) 205M->91M(365M) 93.737ms
>>>> [20.355s][info][gc] GC(25) Pause Young (Normal) (G1 Evacuation 
>>>> Pause) 324M->136M(378M) 125.037ms
>>>> [21.091s][info][gc] GC(26) Pause Young (Normal) (G1 Evacuation 
>>>> Pause) 295M->150M(378M) 93.607ms
>>>> [21.631s][info][gc] GC(27) Pause Young (Concurrent Start) (G1 
>>>> Humongous Allocation) 261M->164M(516M) 77.013ms
>>>> [21.631s][info][gc] GC(28) Concurrent Cycle
>>>> [21.981s][info][gc] GC(28) Pause Remark 212M->169M(516M) 43.679ms
>>>> [22.243s][info][gc] GC(28) Pause Cleanup 214M->214M(516M) 0.257ms
>>>> [22.250s][info][gc] GC(28) Concurrent Cycle 619.296ms
>>>> [22.827s][info][gc] GC(29) Pause Young (Normal) (G1 Evacuation 
>>>> Pause) 321M->155M(516M) 106.789ms
>>>> [23.758s][info][gc] GC(30) Pause Young (Normal) (G1 Evacuation 
>>>> Pause) 363M->187M(516M) 121.025ms
>>>> [24.957s][info][gc] GC(31) Pause Young (Normal) (GCLocker Initiated 
>>>> GC) 386M->207M(516M) 111.118ms
>>>> [25.697s][info][gc] GC(32) Pause Young (Concurrent Start) (G1 
>>>> Humongous Allocation) 346M->222M(656M) 104.765ms
>>>> [25.697s][info][gc] GC(33) Concurrent Cycle
>>>> [26.128s][info][gc] GC(33) Pause Remark 270M->192M(656M) 55.681ms
>>>> [26.342s][info][gc] GC(33) Pause Cleanup 203M->203M(656M) 0.371ms
>>>> [26.349s][info][gc] GC(33) Concurrent Cycle 651.801ms
>>>> [27.421s][info][gc] GC(34) Pause Young (Prepare Mixed) (G1 
>>>> Evacuation Pause) 380M->180M(656M) 195.335ms
>>>> [27.543s][info][gc] GC(35) Pause Young (Mixed) (G1 Evacuation Pause) 
>>>> 195M->172M(656M) 38.254ms
>>>> [28.694s][info][gc] GC(36) Pause Young (Normal) (G1 Evacuation 
>>>> Pause) 427M->214M(656M) 107.817ms
>>>> [31.109s][info][gc] GC(37) Pause Young (Normal) (G1 Evacuation 
>>>> Pause) 486M->239M(656M) 117.275ms
>>>
>>> Notice, the higher memory usage. If a more complex applications is
>>> started, the heap continue to grow indefinitely, with long GC pauses and
>>> a growing heap. It is my understanding that the JVM should setup default
>>> GC and or memory related configuration by itself, be it from the java
>>> launcher or JNI_CreateJavaVM.
>>>
>>> The same custom launcher does not experience this when the embedded JVM
>>> is version 8.
>>>
>>> Note: the launcher is a simple Rust program, not a complex thing, just
>>> locate libjvm.so/jvm.dll, build the VM options, Use JNI_CreateJavaVM,
>>> locate the main class and invoke the main method. These logs are for the
>>> Linux version.
>>>
>>> Any help is appreciated, or a pointer to the correct mailing list.
>>>
>>>
> 