Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fails to start on Windows Subsystem for Linux (WSL) #270

Closed
Maldivia opened this issue Oct 10, 2017 · 19 comments
Closed

Fails to start on Windows Subsystem for Linux (WSL) #270

Maldivia opened this issue Oct 10, 2017 · 19 comments

Comments

@Maldivia
Copy link

The AdoptOpenJDK builds of OpenJ9+OpenJDK fails to start on WSL, they just hang during startup.
IBM JVM 8 SR5 also fails to start.

For comparison, IBM 8 SR4 FP11 starts up fine, as does Oracle 9 and Zulu 9, see -version output below (all Linux x86_64 binaries):

$ jvm/ibm8sr4fp11/bin/java -version
java version "1.8.0"
Java(TM) SE Runtime Environment (build pxa6480sr4fp11-20170823_01(SR4 FP11))
IBM J9 VM (build 2.8, JRE 1.8.0 Linux amd64-64 Compressed References 20170812_360168 (JIT enabled, AOT enabled)
J9VM - R28_20170812_0201_B360168
JIT  - tr.r14.java_20170812_360168
GC   - R28_20170812_0201_B360168_CMPRSS
J9CL - 20170812_360168)
JCL - 20170726_01 based on Oracle jdk8u144-b01

$ jvm/ibm8sr5/bin/java -version
^C

$ jvm/j9-jdk-9+181/bin/java -version
^C

$ jvm/oracle-9.0.0/bin/java -version
java version "9"
Java(TM) SE Runtime Environment (build 9+181)
Java HotSpot(TM) 64-Bit Server VM (build 9+181, mixed mode)

$ jvm/zulu9.0.0.15-jdk9.0.0-linux_x64/bin/java -version
openjdk version "9.0.0.15"
OpenJDK Runtime Environment (Zulu build 9.0.0.15+181)
OpenJDK 64-Bit Server VM (Zulu build 9.0.0.15+181, mixed mode)

Also reported this a few weeks back on the WSL github, but only today tested with IBM 8 SR5, so figured I should better report it here to.
The WSL report has strace output attached to it for trying to start up OpenJ9.
microsoft/WSL#2498

@pshipton
Copy link
Member

pshipton commented Oct 10, 2017

Thanks for opening an Issue.

I tried it and it did start for me, but it takes a while (30 sec). Seems there is a search happening from omrvmem_reserve_memory() for 256MB of memory, where its searching one page at a time, which is taking a long time.

@Maldivia
Copy link
Author

Yes, I can confirm that some patience does help, just not used to java -version not being near instant -- especially not taking 35sec, or 3m39sec.

$ time jvm/ibm8sr5/bin/java -version
java version "1.8.0_144"
Java(TM) SE Runtime Environment (build 8.0.5.0 - pxa6480sr5-20170905_01(SR5))
IBM J9 VM (build 2.9, JRE 1.8.0 Linux amd64-64 Compressed References 20170901_363591 (JIT enabled, AOT enabled)
J9VM - d56eb84
JIT  - tr.open_20170901_140853_d56eb84
OMR  - b033a01)
JCL - 20170823_01 based on Oracle jdk8u144-b01

real    0m35.961s
user    0m0.125s
sys     0m35.703s

$ time jvm/j9-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 20170915_6 (JIT enabled, AOT enabled)
J9VM - cea1ed7
JIT  - cea1ed7
OMR  - 617de12
OpenJDK  - 83f5cd0 based on )

real    3m39.172s
user    0m0.219s
sys     3m36.406s

@pshipton
Copy link
Member

pshipton commented Oct 10, 2017

I'm guessing the problem is in findAvailableMemoryBlockNoMalloc()

@pshipton
Copy link
Member

pshipton commented Oct 10, 2017

@mpirvu The problem allocation is coming from the JIT. First it uses a startAddress, which fails but takes a long time, and then it retries without a specified startAddress. It should work better if the VMEM_ALLOC_QUICK flag is specified.

Also it seems the port library can be improved for this case. The allocated address is before the requested startAddress, and the search direction is forward. The port library continuously increments the startAddress until it reaches the endAddress, which takes some time, always getting the same allocated memory which is before the requested startAddress. Opened eclipse-omr/omr#1800.

@mpirvu
Copy link
Contributor

mpirvu commented Oct 10, 2017

I agree in both respects:
(1) The JIT should use the VMEM_ALLOC_QUICK flag which looks at smaps to find a suitable place. We were thinking of doing something similar based on smaps I am glad the supporting routine is already implemented.
(2) If findAvailableMemoryBlockNoMalloc() fails, then apply strategy 2 where, if the OS gives us an address lower than the starting point, stop the search.

@pshipton
Copy link
Member

I'm also wondering where the startAddress comes from. I wasn't able to find it in the code. Or why a start address is used at all. It would also work if the requested startAddress was lower in memory such that the memory allocation was in range.

@mpirvu
Copy link
Contributor

mpirvu commented Oct 11, 2017

The start address is determined by J9::CodeCacheManager::chooseCacheStartAddress(size_t repositorySize)
The whole point of requiring a specific address is to have the code cache repository in the vicinity of the JIT dll so that trampoline helpers can be eliminated. The code for chooseCacheStartAddress takes the address of some symbol in the JIT dll, subtracts some SAFE_DISTANCE_REPOSITORY_JITLIBRARY value (which accounts for the possible size of the JIT dll) and the size of the code cache repository.

@pshipton
Copy link
Member

For the record, in one particular run the startAddress was 00007F66EFA00000 and the OS returned memory at 00007F66CF0D0000. The port library cycled through addresses in 4K increments to 00007F66F1200000 before failing.

@harryyu1994
Copy link
Contributor

@mpirvu Hi Marius, could you please point to me the code to set the VMEM_ALLOC_QUICK flag?

@mpirvu
Copy link
Contributor

mpirvu commented Oct 31, 2017

@harryyu1994 The allocation of the code cache repository happens in this function:

TR::CodeCacheMemorySegment *
J9::CodeCacheManager::allocateCodeCacheSegment(size_t segmentSize,
                                              size_t &codeCacheSizeToAllocate,
                                              void *preferredStartAddress)

There is a local variable J9PortVmemParams vmemParams; that is the passed to the VM.
You need to add that specific flag to vmemParams->options:

   if (preferredStartAddress)
      {
      vmemParams.options |= VMEM_ALLOC_QUICK

Then let's verify that this is enough to fix this issue and that there is no startup regression on native linux platforms due to parsing of smaps file

@mpirvu
Copy link
Contributor

mpirvu commented Nov 1, 2017

I evaluated a JIT dll compiled by Harry that uses VMEM_ALLOC_QUICK, but there is no improvement. The time to print the version is the same ~35 seconds

mpirvu@LAPTOP-3BI10H90:~/sdks$ time pxa6480sr6-20171027_01/jre/bin/java -XXjitdirectory=Original -version
java version "1.8.0_151"
Java(TM) SE Runtime Environment (build 8.0.6.0 - pxa6480sr6-20171027_01(SR6))
IBM J9 VM (build 2.9, JRE 1.8.0 Linux amd64-64 Compressed References 20171026_368574 (JIT enabled, AOT enabled)
OpenJ9   - 08c9cc6
OMR      - 470bcf7
IBM      - 59c3d96)
JCL - 20170927_01 based on Oracle jdk8u151-b12

real    0m35.126s
user    0m0.078s
sys     0m34.984s
mpirvu@LAPTOP-3BI10H90:~/sdks$ time pxa6480sr6-20171027_01/jre/bin/java -XXjitdirectory=VMEM_QUICK_ALLOC -version
java version "1.8.0_151"
Java(TM) SE Runtime Environment (build 8.0.6.0 - pxa6480sr6-20171027_01(SR6))
IBM J9 VM (build 2.9, JRE 1.8.0 Linux amd64-64 Compressed References 20171026_368574 (JIT enabled, AOT enabled)
OpenJ9   - 08c9cc6
OMR      - 470bcf7
IBM      - 59c3d96)
JCL - 20170927_01 based on Oracle jdk8u151-b12

real    0m35.242s
user    0m0.141s
sys     0m35.016s

I will do some tracing.

@mpirvu
Copy link
Contributor

mpirvu commented Nov 1, 2017

I have run with -Xtrace:print="omrport.499-509" and got the following trace:

16:48:19.554*0x160fa00         omrport.504      > omrvmem_reserve_memory requestedAddress=00007F1965800000 byteAmount=268435456 pageSize=4096
16:48:19.584 0x160fa00         omrport.499      > default_pageSize_reserve_memory requestedAddress=0000000000000000 byteAmount=268435456
16:48:19.591 0x160fa00         omrport.503      < default_pageSize_reserve_memory returns 00007F1963C80000 requestedAddress=0000000000000000 byteAmount=268435456
16:48:19.591 0x160fa00         omrport.499      > default_pageSize_reserve_memory requestedAddress=00007F1965800000 byteAmount=268435456
16:48:19.597 0x160fa00         omrport.503      < default_pageSize_reserve_memory returns 00007F1963C80000 requestedAddress=00007F1965800000 byteAmount=268435456
16:48:19.599 0x160fa00         omrport.499      > default_pageSize_reserve_memory requestedAddress=00007F1965801000 byteAmount=268435456
16:48:19.605 0x160fa00         omrport.503      < default_pageSize_reserve_memory returns 00007F1963C80000 requestedAddress=00007F1965801000 byteAmount=268435456
16:48:19.605 0x160fa00         omrport.499      > default_pageSize_reserve_memory requestedAddress=00007F1965802000 byteAmount=268435456
16:48:19.610 0x160fa00         omrport.503      < default_pageSize_reserve_memory returns 00007F1963C80000 requestedAddress=00007F1965802000 byteAmount=268435456
16:48:19.610 0x160fa00         omrport.499      > default_pageSize_reserve_memory requestedAddress=00007F1965803000 byteAmount=268435456
16:48:19.616 0x160fa00         omrport.503      < default_pageSize_reserve_memory returns 00007F1963C80000 requestedAddress=00007F1965803000 byteAmount=268435456
.............

So what happens is:

  1. We get into getMemoryInRangeForDefaultPages() with a requested address of 00007F1965800000. This tests the OMRPORT_VMEM_ALLOC_QUICK flag and executes findAvailableMemoryBlockNoMalloc. 2) 'findAvailableMemoryBlockNoMalloc` looks at smaps but find no solution so it returns 0.
  2. The code then calls allocatedAddress = default_pageSize_reserve_memory(...); with the NULL address returned by findAvailableMemoryBlockNoMalloc. We should probably not do that because it's just a waste of time.
    The flag MAP_FIXED is not set so the address passed to mmap is just a hint. default_pageSize_reserve_memory returns 00007F1963C80000 which is not good for us.
  3. Because the returned address is outside the range we desire, we free it and then go through the loop that calls default_pageSize_reserve_memory repeatedly incrementing the startAddress one page at a time.

Note that the difference between what we want (00007F1965800000) and what mmap returns (00007F1963C80000) is 28,835,840 bytes (~28MB). This should probably be good for us as the code cache is still close to the JIT dll.

@mpirvu
Copy link
Contributor

mpirvu commented Nov 1, 2017

Using a wider range for startAddress may solve this issue, though if mmap really cannot find anything suitable we are going to waste even more time.

@mpirvu
Copy link
Contributor

mpirvu commented Nov 1, 2017

Increasing the range searching range from 28MB to 64MB reduces the execution time for java -version to 0.375 sec

mpirvu@LAPTOP-3BI10H90:~/sdks$ time pxa6480sr6-20171027_01/jre/bin/java -XXjitdirectory=VMEM_QUICK_ALLOC -version
java version "1.8.0_151"
Java(TM) SE Runtime Environment (build 8.0.6.0 - pxa6480sr6-20171027_01(SR6))
IBM J9 VM (build 2.9, JRE 1.8.0 Linux amd64-64 Compressed References 20171026_368574 (JIT enabled, AOT enabled)
OpenJ9 - 08c9cc6
OMR - 470bcf7
IBM - 59c3d96)
JCL - 20170927_01 based on Oracle jdk8u151-b12

real 0m0.375s
user 0m0.141s
sys 0m0.203s

@mpirvu
Copy link
Contributor

mpirvu commented Nov 2, 2017

I evaluated the proposed solution on native Linux using Liberty startup as a benchmark.
For the sufpdt3 configuration there was a 0.5% startup regression (over 240 runs)
For the tradeLite configuration there was a 1.6% startup over 240 runs. Since the fluctuations were rather high I repeated this experiment and got a 0.4% startup regression over 400 runs (the 95% confidence interval was 0.2%)

All in all there is a small regression, most likely from opening the smaps file and parsing it. I will think at something else.

@sunnythepooh
Copy link

I have instrumented the getMemoryInRangeForDefaultPages further and it seems that WSL just ignore addr or unable to allocate pages anywhere near the suggested address:

calling with startAddress (nil), endaddress 0x2331000, byteAmount 4258066432
    startAddress (nil), currentAddress 0x2331000, endAddress 0x2331000, direction -1 -     memoryPointer returned = 0x7f543ef20000
    startAddress (nil), currentAddress 0x2330000, endAddress 0x2331000, direction -1 -     memoryPointer returned = 0x7f543ef20000
    startAddress (nil), currentAddress 0x232f000, endAddress 0x2331000, direction -1 -     memoryPointer returned = 0x7f543ef20000
    startAddress (nil), currentAddress 0x232e000, endAddress 0x2331000, direction -1 -     memoryPointer returned = 0x7f543ef20000
    startAddress (nil), currentAddress 0x232d000, endAddress 0x2331000, direction -1 -     memoryPointer returned = 0x7f543ef20000
    startAddress (nil), currentAddress 0x232c000, endAddress 0x2331000, direction -1 -     memoryPointer returned = 0x7f543ef20000
    startAddress (nil), currentAddress 0x232b000, endAddress 0x2331000, direction -1 -     memoryPointer returned = 0x7f543ef20000
    startAddress (nil), currentAddress 0x232a000, endAddress 0x2331000, direction -1 -     memoryPointer returned = 0x7f543ef20000
    startAddress (nil), currentAddress 0x2329000, endAddress 0x2331000, direction -1 -     memoryPointer returned = 0x7f543ef20000
    startAddress (nil), currentAddress 0x2328000, endAddress 0x2331000, direction -1 -     memoryPointer returned = 0x7f543ef20000
    startAddress (nil), currentAddress 0x2327000, endAddress 0x2331000, direction -1 -     memoryPointer returned = 0x7f543ef20000
    startAddress (nil), currentAddress 0x2326000, endAddress 0x2331000, direction -1 -     memoryPointer returned = 0x7f543ef20000
    startAddress (nil), currentAddress 0x2325000, endAddress 0x2331000, direction -1 -     memoryPointer returned = 0x7f543ef20000

I think we should to modify the code so that it will check if multiple calls to mmap returns the same address it will bail out from the loop.

@mpirvu
Copy link
Contributor

mpirvu commented Nov 16, 2017

My proposal for a fix is the following:

  • add a new Virtual Memory Option, something like OMRPORT_VMEM_ADDRESS_HINT
  • change getMemoryInRangeForDefaultPages() so that, when OMRPORT_VMEM_ADDRESS_HINT is used, instead of trying page after page to allocate in the desired region, we stop after the first attempt and return whatever default_pageSize_reserve_memory() gives us
  • change the JIT to do the following:
    1. try to allocate memory providing a desired address and setting OMRPORT_VMEM_ADDRESS_HINT
    2. If the address returned by the OS is not within 2GB of the JIT dll, then try again by setting OMRPORT_VMEM_ALLOC_QUICK and a very large address range, but not setting OMRPORT_VMEM_STRICT_ADDRESS, and accept whatever we get back

The proposal above is based on the observation that when mmap is asked to allocate memory at a given address it may return an address that is close enough for our purposes.
I have not tested this for large pages (getMemoryInRangeForLargePages) which uses shmat instead of mmap. Also, for large pages OMRPORT_VMEM_ALLOC_QUICK is not used. I don't see a reason why findAvailableMemoryBlockNoMalloc() cannot be used in a similar fashion as for regular pages.

@mpirvu
Copy link
Contributor

mpirvu commented Nov 30, 2017

I evaluated the prototype written by Harry.
On WSL the long startup time disappears.
On native linux (x86-64 CentOS 7.2) startup of Liberty slightly improves by 0.5%, but this could be just fluctuations because the 95% confidence interval was also 0.5%.

Results for JDK=/home/mpirvu/sdks/pxa6480sr6-20171130_02 jvmOpts=-Xquickstart -Xshareclasses:enableBCI,name=liberty -Xscmx60M -Xscmaxaot8m -Xmx256m
StartupTime     avg=3621        min=3412        max=4074        stdDev=142.8    maxVar=19.4%    confInt=0.52%   samples=159
Footprint       avg=152561      min=145332      max=164500      stdDev=3917.7   maxVar=13.2%    confInt=0.33%   samples=160
CThreadTime     avg= 892        min= 717        max=1229        stdDev=114.6    maxVar=71.4%    confInt=1.68%   samples=160
ProcessTime     avg=5367        min=4960        max=6090        stdDev=235.5    maxVar=22.8%    confInt=0.57%   samples=160
Results for JDK=/home/mpirvu/sdks/jvmxa6480_harry jvmOpts=-Xquickstart -Xshareclasses:enableBCI,name=liberty -Xscmx60M -Xscmaxaot8m -Xmx256m
StartupTime     avg=3605        min=3364        max=4089        stdDev=152.0    maxVar=21.5%    confInt=0.55%   samples=158
Footprint       avg=152582      min=145868      max=164676      stdDev=3841.6   maxVar=12.9%    confInt=0.33%   samples=160
CThreadTime     avg= 897        min= 722        max=1186        stdDev=112.9    maxVar=64.3%    confInt=1.64%   samples=160
ProcessTime     avg=5372        min=4940        max=6060        stdDev=222.4    maxVar=22.7%    confInt=0.54%   samples=159

I will also verify the behavior when large pages are enabled.

@mpirvu
Copy link
Contributor

mpirvu commented Dec 1, 2017

With large pages turned on, on the same HW setup as above, the prototype improves startup time by 1.2%. I can't put my finger on what could cause an improvement in this case, but I'll take it.

Results for JDK=/home/mpirvu/sdks/pxa6480sr6-20171130_02 jvmOpts=-Xquickstart -Xshareclasses:enableBCI,name=liberty -Xscmx60M -Xscmaxaot8m -Xmx256m
StartupTime     avg=3616        min=3401        max=4187        stdDev=149.8    maxVar=23.1%    confInt=0.44%   samples=237
Footprint       avg=152853      min=145796      max=164568      stdDev=3484.9   maxVar=12.9%    confInt=0.24%   samples=238
CThreadTime     avg= 899        min= 703        max=1230        stdDev=107.0    maxVar=75.0%    confInt=1.27%   samples=240
ProcessTime     avg=5362        min=4970        max=6130        stdDev=229.7    maxVar=23.3%    confInt=0.46%   samples=240
Results for JDK=/home/mpirvu/sdks/jvmxa6480_harry jvmOpts=-Xquickstart -Xshareclasses:enableBCI,name=liberty -Xscmx60M -Xscmaxaot8m -Xmx256m
StartupTime     avg=3572        min=3379        max=4117        stdDev=137.5    maxVar=21.8%    confInt=0.41%   samples=238
Footprint       avg=153747      min=147260      max=167196      stdDev=3906.3   maxVar=13.5%    confInt=0.27%   samples=239
CThreadTime     avg= 877        min= 693        max=1193        stdDev=108.0    maxVar=72.2%    confInt=1.31%   samples=240
ProcessTime     avg=5325        min=5030        max=6080        stdDev=224.0    maxVar=20.9%    confInt=0.45%   samples=240

harryyu1994 added a commit to harryyu1994/openj9 that referenced this issue Dec 20, 2017
On the OMR side: add a new Virtual Memory Option called OMRPORT_VMEM_ADDRESS_HINT
Change the method getMemoryInRangeForDefaultPages() to do the following:
- when OMRPORT_VMEM_ADDRESS_HINT is used, instead of trying page by page to allocate in the desired region, we stop after the first attempt and return whatever default_pageSize_reserve_memory() gives us
- when doing OMRPORT_VMEM_ALLOC_QUICK, do not try the slow search with mmap if the fast search with smaps failed
- when doing OMRPORT_VMEM_ALLOC_QUICK, avoid doing the range check when OMRPORT_VMEM_ADDRESS_STRICT is not set

On the OpenJ9 side: change the JIT to do the following during code cache allocation
- try to allocate memory providing a desired address and setting OMRPORT_VMEM_ADDRESS_HINT
- if the address returned by the OS is not within (2GB - 24MB) of the JIT dll, then try again by setting OMRPORT_VMEM_ALLOC_QUICK and a much larger address range(the full 2GB - 24MB from JIT dll address range), but not setting OMRPORT_VMEM_STRICT_ADDRESS and accept whatever we get back
- refactor redundant code into functions and change the order of operation inside J9::CodeCacheManager::allocateCodeCacheSegment to make the code cleaner

The OpenJ9 side change is dependent on the OMR side change, therefore pull in the OMR side change first.

Closes: eclipse-openj9#270
Signed-off-by: Harry Yu <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

5 participants