Graal: [native-image] Command `native-image` is slow

Created on 20 Apr 2018 · 11Comments · Source: oracle/graal

I follow the HelloWorld.java example and native-image HelloWorld takes 10 minutes or so. Is it just so slow or something wrong with my environment?

➜  ~ javac -version
javac 1.8.0_161
➜  ~ java -version
java version "1.8.0_161"
Java(TM) SE Runtime Environment (build 1.8.0_161-b12)
GraalVM 1.0.0-rc1 (build 25.71-b01-internal-jvmci-0.42, mixed mode)

Set JAVA_HOME to GraalVM installation directory, GraalVM version is GraalVM based on JDK8, preview for macOS (1.0.0 RC1)

native-image

Source

TisonKun

Most helpful comment

Does native-image search all sub-directories of current directory to cover all potential dependence?

It does if you have . on the classpath (which is the default if you do not specify a custom cp).

olpaw on 24 Apr 2018

😄6

All 11 comments

Well, it seems like something wrong with my env. Just now I try to reproduce this and get

➜  Documents native-image HelloWorld
Build on Server(pid: 92315, port: 26682)*
   classlist:  29,312.19 ms
       (cap):   3,708.56 ms
       setup:   5,498.66 ms
  (typeflow):   6,807.01 ms
   (objects):   3,393.40 ms
  (features):      53.51 ms
    analysis:  10,375.17 ms
    universe:     450.43 ms
     (parse):   2,215.45 ms
    (inline):   1,882.86 ms
   (compile):  17,827.29 ms
     compile:  22,563.15 ms
       image:   2,058.85 ms
       write:   2,073.65 ms
     [total]:  72,416.40 ms

TisonKun on 20 Apr 2018

But wait, I've saw the time others cost, it is still too long for me, that build a native-image of HelloWorld costs a minutes.

TisonKun on 20 Apr 2018

@W4anD0eR96 that is definitely too long. On my laptop it takes about 15 sec to build HelloWorld (and a subsequent build takes only about 7 seconds due to reuse of the already warmed up build server).

pwoegere@olpaw:~/Downloads/graalvm-1.0.0-rc1> bin/native-image HelloWorld
Build on Server(pid: 4988, port: 26681)*
   classlist:     763.61 ms
       (cap):   1,266.36 ms
       setup:   2,019.71 ms
  (typeflow):   4,392.66 ms
   (objects):   2,229.36 ms
  (features):      43.95 ms
    analysis:   6,766.69 ms
    universe:     282.92 ms
     (parse):     723.04 ms
    (inline):     687.66 ms
   (compile):   3,825.82 ms
     compile:   5,616.74 ms
       image:     870.27 ms
       write:     183.28 ms
     [total]:  16,565.22 ms
pwoegere@olpaw:~/Downloads/graalvm-1.0.0-rc1> bin/native-image HelloWorld
Build on Server(pid: 4988, port: 26681)
   classlist:     142.66 ms
       (cap):     611.28 ms
       setup:     831.86 ms
  (typeflow):   2,361.25 ms
   (objects):     986.72 ms
  (features):      24.84 ms
    analysis:   3,452.04 ms
    universe:     135.95 ms
     (parse):     311.16 ms
    (inline):     431.17 ms
   (compile):   1,735.06 ms
     compile:   2,700.00 ms
       image:     366.57 ms
       write:     136.69 ms
     [total]:   7,789.82 ms

May I ask what system-configuration (RAM and CPU) you have?

olpaw on 20 Apr 2018

@W4anD0eR96 I can't reproduce your issue on OSX. I tried with the following machine

      Model Name: Mac mini
      Model Identifier: Macmini7,1
      Processor Name: Intel Core i7
      Processor Speed: 3 GHz
      Number of Processors: 1
      Total Number of Cores: 2
      L2 Cache (per Core): 256 KB
      L3 Cache: 4 MB
      Memory: 16 GB

with

ProductName:    Mac OS X
ProductVersion: 10.11.4

Can you try if this is related to build-server use? Please try again to build HelloWorld with

bin/native-image --no-server HelloWorld

You should get something like

   classlist:   1,682.15 ms
       (cap):   1,330.70 ms
       setup:   2,557.02 ms
  (typeflow):   5,931.70 ms
   (objects):   2,487.36 ms
  (features):     144.81 ms
    analysis:   8,671.94 ms
    universe:     297.49 ms
     (parse):   1,591.99 ms
    (inline):   1,593.00 ms
   (compile):  16,468.96 ms
     compile:  20,053.80 ms
       image:   1,559.88 ms
       write:   1,026.59 ms
     [total]:  35,933.14 ms

While this is slower than on Linux its still much faster than what you see. Especially the classlist phase in your case is way out of proportion.

olpaw on 20 Apr 2018

  Model Name: MacBook Air
  Processor Name: MacBookAir7,2
  Processor Name: Intel Core i7
  Processor Speed: 2.2 GHz
  Number of Processors:  1
  Total Number of Cores: 2
  L2 Cache (per Core): 256 KB
  L3 Cache: 4 MB
  Memory: 8 GB

with

  System Version: macOS 10.12.6 (16G1036)
  Kernel Version: Darwin 16.7.0

It produces

➜  Documents native-image --no-server HelloWorld
   classlist:  19,145.61 ms
       (cap):   2,989.24 ms
       setup:   5,066.42 ms
  (typeflow):   6,077.69 ms
   (objects):   3,306.68 ms
  (features):      64.67 ms
    analysis:   9,577.88 ms
    universe:     346.86 ms
     (parse):   2,308.73 ms
    (inline):   2,130.32 ms
   (compile):  19,619.97 ms
     compile:  24,670.50 ms
       image:   2,159.53 ms
       write:   1,831.74 ms
     [total]:  62,896.62 ms

TisonKun on 20 Apr 2018

Ok, then it's probably the 8GB of RAM. You could try if forcing a higher heap size improves the situation, e.g. try

bin/native-image -J-Xmx8G -J-Xms6G --no-server HelloWorld

olpaw on 20 Apr 2018

➜  Documents native-image -J-Xmx8G -J-Xms6G --no-server HelloWorld
   classlist:  17,599.53 ms
       (cap):   2,688.17 ms
       setup:   4,685.23 ms
  (typeflow):   5,889.80 ms
   (objects):   2,773.20 ms
  (features):      52.13 ms
    analysis:   8,854.52 ms
    universe:     389.21 ms
     (parse):   1,977.17 ms
    (inline):   1,388.89 ms
   (compile):  16,323.11 ms
     compile:  20,191.70 ms
       image:   1,859.66 ms
       write:   1,797.68 ms
     [total]:  55,467.88 ms

Works anyway.

TisonKun on 20 Apr 2018

@W4anD0eR96 can you try if the following makes the runtime of the classlist phase normal:

Create a new directory
Change the current working directory to that new directory
Put the HelloWorld.java program in there
Build the HelloWorld.class file with javac
Build the helloworld native image.

I suspect that that the runtime of classlist phase very much depends on the amount of sub-directories that are reachable from your current working directory when you call native-image.

olpaw on 23 Apr 2018

Well, I do what you suggest. Now the runtime of classlist phase looks normal.

$ native-image --no-server HelloWorld
   classlist:   1,838.63 ms
       (cap):   2,027.92 ms
       setup:   3,498.79 ms
  (typeflow):   6,965.22 ms
   (objects):   2,770.26 ms
  (features):      50.86 ms
    analysis:  10,021.54 ms
    universe:     321.72 ms
     (parse):   2,094.78 ms
    (inline):   2,137.53 ms
   (compile):  19,271.51 ms
     compile:  24,037.59 ms
       image:   1,946.82 ms
       write:   1,272.60 ms
     [total]:  43,025.58 ms

$ native-image HelloWorld           
Build on Server(pid: 34857, port: 26681)*
   classlist:   1,735.35 ms
       (cap):   1,376.76 ms
       setup:   2,924.74 ms
  (typeflow):   7,022.15 ms
   (objects):   2,920.49 ms
  (features):     103.69 ms
    analysis:  10,213.30 ms
    universe:     355.97 ms
     (parse):   2,301.46 ms
    (inline):   1,951.33 ms
   (compile):  21,961.38 ms
     compile:  26,784.66 ms
       image:   2,295.49 ms
       write:   1,581.17 ms
     [total]:  45,993.15 ms

$ native-image -J-Xmx8G -J-Xms6G --no-server HelloWorld
   classlist:   2,486.73 ms
       (cap):   3,111.71 ms
       setup:   5,143.08 ms
  (typeflow):   7,623.74 ms
   (objects):   4,947.94 ms
  (features):      89.77 ms
    analysis:  12,882.15 ms
    universe:     479.19 ms
     (parse):   2,815.01 ms
    (inline):   2,728.18 ms
   (compile):  27,895.11 ms
     compile:  34,210.33 ms
       image:   3,587.22 ms
       write:   2,609.28 ms
     [total]:  61,511.81 ms

TisonKun on 23 Apr 2018

👍1

Does native-image search all sub-directories of current directory to cover all potential dependence?

TisonKun on 23 Apr 2018