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

[David Holmes]

Hi Robert,

I've cc'd core-libs-dev as this is now about signed-jars and the launcher.

David

On 22/01/2019 4:48 am, Robert Marcano wrote:
> 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.
>>>>
>>>>
>>
>