Re: 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 <rob...@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.