Best mailing list for JVM embedding

Mon Jan 21 12:25:16 UTC 2019

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

> 
> 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.
>>
>>