Very slow startup on Windows Subsystem for Linux without -Xmx option

[keithc-ca]

I built OpenJ9 using the Windows Subsytem for Linux available in Windows 10.
The output from java -version shows SHAs from today.

openjdk version "9-internal"
OpenJDK Runtime Environment (build 9-internal+0-adhoc.keithc.openj9-openjdk-jdk9)
Eclipse OpenJ9 VM (build 2.9, JRE 9 Linux amd64-64 Compressed References 20180117_000000 (JIT enabled, AOT enabled)
OpenJ9   - e49c539
OMR      - 3cda7d8
OpenJDK  - be5903d based on jdk-9+181)

There is a significant difference in runtime if the -Xmx option is present vs. omitted.
It seems to be entirely in the initialization stage ALL_LIBRARIES_LOADED for j9gc29.
With -Xmx4M:

Running initialization stage ALL_LIBRARIES_LOADED
	for library j9gc29...
		completed with rc=0 in 6846000 nano sec.

Without -Xmx:

Running initialization stage ALL_LIBRARIES_LOADED
	for library j9gc29...
		completed with rc=0 in 26027322000 nano sec.

[pshipton]

FYI #270 and #739 for some history

[mpirvu]

I tried to reproduce this issue on my Thinkpad using the most recent OpenJDK9+OpenJ9 build available from AdoptOpenJDK but everything runs ok for me:

mpirvu@LAPTOP-3BI10H90:~/sdks/OpenJDK9-OPENJ9_x64_Linux_20180502/jdk-9+181$ time /home/mpirvu/sdks/OpenJDK9-OPENJ9_x64_Linux_20180502/jdk-9+181/bin/java -version
openjdk version "9-internal"
OpenJDK Runtime Environment (build 9-internal+0-adhoc.jenkins.openjdk)
Eclipse OpenJ9 VM (build 2.9, JRE 9 Linux amd64-64 Compressed References 20180205_104 (JIT enabled, AOT enabled)
OpenJ9   - aba80293
OMR      - 9a5ea01e
JCL      - e27ea6d6d based on jdk-9+181)

real    0m0.204s
user    0m0.234s
sys     0m0.063s

As Peter Shipton hinted above, this could be related to GC trying to allocate the Java heap at a specified address, failing and then repeatedly trying with larger addresses in 4K increments.
In #270 I have used -Xtrace:print="omrport.499-509" to see a long stream of allocation attempts.

[keithc-ca]

Thanks. I'll give it another spin. I haven't noticed any changes in OMR or OpenJ9 that might explain that better behavior. Maybe Microsoft fixed WSL?

[keithc61]

I downloaded the same version from adopt. Notice that most of the 26 seconds is before the first tracepoint: the time must be spent elsewhere.

% date ; time ./bin/java -Xtrace:"print=omrport.499-509" -version
Mon Feb  5 20:28:44 EST 2018
01:29:10.922*0xc74a00         omrport.504      > omrvmem_reserve_memory requestedAddress=00007FA4D5000000 byteAmount=268435456 pageSize=4096
01:29:10.922 0xc74a00         omrport.499      > default_pageSize_reserve_memory requestedAddress=00007FA4D5000000 byteAmount=268435456
01:29:10.923 0xc74a00         omrport.503      < default_pageSize_reserve_memory returns 00007FA4C7B70000 requestedAddress=00007FA4D5000000 byteAmount=268435456
01:29:10.923 0xc74a00         omrport.509      < omrvmem_reserve_memory returns 00007FA4C7B70000 requestedAddress=00007FA4D5000000
01:29:10.924*0xc78600         omrport.504      > omrvmem_reserve_memory requestedAddress=0000000000000000 byteAmount=16777216 pageSize=4096
01:29:10.924 0xc78600         omrport.499      > default_pageSize_reserve_memory requestedAddress=0000000000000000 byteAmount=16777216
01:29:10.925 0xc78600         omrport.503      < default_pageSize_reserve_memory returns 00007FA4C6A60000 requestedAddress=0000000000000000 byteAmount=16777216
01:29:10.925 0xc78600         omrport.509      < omrvmem_reserve_memory returns 00007FA4C6A60000 requestedAddress=0000000000000000
openjdk version "9-internal"
OpenJDK Runtime Environment (build 9-internal+0-adhoc.jenkins.openjdk)
Eclipse OpenJ9 VM (build 2.9, JRE 9 Linux amd64-64 Compressed References 20180205_104 (JIT enabled, AOT enabled)
OpenJ9   - aba80293
OMR      - 9a5ea01e
JCL      - e27ea6d6d based on jdk-9+181)
01:29:11.061*0xc74a00         omrport.504      > omrvmem_reserve_memory requestedAddress=0000000000000000 byteAmount=1048576 pageSize=4096
01:29:11.061 0xc74a00         omrport.499      > default_pageSize_reserve_memory requestedAddress=0000000000000000 byteAmount=1048576
01:29:11.061 0xc74a00         omrport.503      < default_pageSize_reserve_memory returns 00007FA4C7960000 requestedAddress=0000000000000000 byteAmount=1048576
01:29:11.061 0xc74a00         omrport.509      < omrvmem_reserve_memory returns 00007FA4C7960000 requestedAddress=0000000000000000

real    0m26.383s
user    0m0.063s
sys     0m26.203s

An instance built on WSL has similar behavior.

% date ; time ./jdk/bin/java -Xtrace:print="omrport.499-509" -version
Mon Feb  5 20:23:05 EST 2018
01:23:32.045*0xe71a00         omrport.504      > omrvmem_reserve_memory requestedAddress=00007FD82FC00000 byteAmount=268435456 pageSize=4096
01:23:32.045 0xe71a00         omrport.499      > default_pageSize_reserve_memory requestedAddress=00007FD82FC00000 byteAmount=268435456
01:23:32.046 0xe71a00         omrport.503      < default_pageSize_reserve_memory returns 00007FD8226C0000 requestedAddress=00007FD82FC00000 byteAmount=268435456
01:23:32.046 0xe71a00         omrport.509      < omrvmem_reserve_memory returns 00007FD8226C0000 requestedAddress=00007FD82FC00000
01:23:32.047*0xe75600         omrport.504      > omrvmem_reserve_memory requestedAddress=0000000000000000 byteAmount=16777216 pageSize=4096
01:23:32.047 0xe75600         omrport.499      > default_pageSize_reserve_memory requestedAddress=0000000000000000 byteAmount=16777216
01:23:32.048 0xe75600         omrport.503      < default_pageSize_reserve_memory returns 00007FD8215B0000 requestedAddress=0000000000000000 byteAmount=16777216
01:23:32.048 0xe75600         omrport.509      < omrvmem_reserve_memory returns 00007FD8215B0000 requestedAddress=0000000000000000
openjdk version "9-internal"
OpenJDK Runtime Environment (build 9-internal+0-adhoc.keithc.openj9-openjdk-jdk9)
Eclipse OpenJ9 VM (build 2.9, JRE 9 Linux amd64-64 Compressed References 20180205_000000 (JIT enabled, AOT enabled)
OpenJ9   - aba8029
OMR      - 9a5ea01
JCL      - e27ea6d based on jdk-9+181)
01:23:32.173*0xe71a00         omrport.504      > omrvmem_reserve_memory requestedAddress=0000000000000000 byteAmount=1048576 pageSize=4096
01:23:32.173 0xe71a00         omrport.499      > default_pageSize_reserve_memory requestedAddress=0000000000000000 byteAmount=1048576
01:23:32.174 0xe71a00         omrport.503      < default_pageSize_reserve_memory returns 00007FD8224B0000 requestedAddress=0000000000000000 byteAmount=1048576
01:23:32.174 0xe71a00         omrport.509      < omrvmem_reserve_memory returns 00007FD8224B0000 requestedAddress=0000000000000000

real    0m26.498s
user    0m0.203s
sys     0m26.266s

[keithc-ca]

A build based on eclipse-omr/omr#2743 seems much better (performance does not appear to be dependent on whether -Xmx is used nor the value used with that option).

% time ./images/jdk/bin/java -version
openjdk version "9.0.4-internal"
OpenJDK Runtime Environment (build 9.0.4-internal+0-adhoc.keithc.jdk09)
Eclipse OpenJ9 VM (build master-4dd67e3, JRE 9 Linux amd64-64-Bit Compressed References 20180718_000000 (JIT enabled, AOT enabled)
OpenJ9   - 4dd67e3
OMR      - 4991c87
JCL      - 428fef7 based on jdk-9.0.4+12)

real    0m0.559s
user    0m0.141s
sys     0m0.438s

[keithc-ca]

I'm satisfied that this is fixed by eclipse-omr/omr#2743 which is now merged: closing.