[native-image] Startup time of native compiled with graalvm 20.1-dev is noticably slower than 19.3.0 on macOS

[borkdude]

Given a simple class like:

public class Foo {

    public static void main(String [] args) {
        System.out.println("Hello");
    }
}

$ javac Foo.java

$ brew install Tenzer/tap/multitime

$ export GRAALVM_HOME=/Users/borkdude/Downloads/graalvm-ce-java8-19.3.0/Contents/Home
$GRAALVM_HOME/bin/native-image Foo --no-server
$ multitime -n100 ./foo

===> multitime results
1: ./foo
            Mean        Std.Dev.    Min         Median      Max
real        0.007       0.001       0.005       0.008       0.009
user        0.002       0.000       0.002       0.002       0.003
sys         0.002       0.000       0.001       0.002       0.004

$ export GRAALVM_HOME=/Users/borkdude/Downloads/graalvm-ce-java8-20.1.0-dev/Contents/Home
$GRAALVM_HOME/bin/native-image Foo --no-server
$ multitime -n100 ./foo

===> multitime results
1: ./foo
            Mean        Std.Dev.    Min         Median      Max
real        0.015       0.001       0.011       0.015       0.016
user        0.007       0.001       0.005       0.007       0.008
sys         0.005       0.000       0.004       0.005       0.006

I noticed this when trying out 20.1-dev jdk8 with babashka, a scripting tool made with GraalVM. On GraalVM 19.3.0 java8 it has a startup time of around 14ms, but when I was trying GraalVM 20.1-dev it became 24ms which is 10ms slower.

$ export GRAALVM_HOME=/Users/borkdude/Downloads/graalvm-ce-java8-19.3.0/Contents/Home
$ script/compile 
$ multitime -n100 ./bb '(System/getProperty "java.vm.version")'

===> multitime results
1: ./bb "(System/getProperty \"java.vm.version\")"
            Mean        Std.Dev.    Min         Median      Max
real        0.014       0.001       0.012       0.014       0.016
user        0.005       0.000       0.004       0.005       0.006
sys         0.006       0.001       0.004       0.006       0.008

$ export GRAALVM_HOME=/Users/borkdude/Downloads/graalvm-ce-java8-20.1.0-dev/Contents/Home
$ script/compile 
$ multitime -n100 ./bb '(System/getProperty "java.vm.version")'

===> multitime results
1: ./bb "(System/getProperty \"java.vm.version\")"
            Mean        Std.Dev.    Min         Median      Max
real        0.024       0.002       0.018       0.024       0.026
user        0.011       0.001       0.008       0.011       0.011
sys         0.010       0.001       0.007       0.010       0.012

To build babashka:

$ git clone https://github.com/borkdude/babashka --recursive

Install lein, a Clojure build tool.

Set GRAALVM_HOME to either 19 or 20 with java8.

Then run script/compile (on linux or macos).

This will produce a bb executable.

[borkdude]

This does not seem to be the case on linux, so it seems to be mac specific:

On linux:

19:

1: ./bb -e "(+ 1 2 3)"
            Mean        Std.Dev.    Min         Median      Max
real        0.015       0.010       0.005       0.010       0.035       
user        0.008       0.006       0.000       0.006       0.023       
sys         0.008       0.007       0.000       0.005       0.031      

20:

1: ./bb -e "(+ 1 2 3)"
            Mean        Std.Dev.    Min         Median      Max
real        0.014       0.009       0.006       0.010       0.037       
user        0.006       0.005       0.000       0.005       0.024       
sys         0.008       0.006       0.000       0.006       0.027  

This data was provided to me by @sogaiu.

[olpaw]

@borkdude thanks for your bug report. I will take a look.

[borkdude]

@olpaw I re-tested with the newly released 20.0.0 java8 version, but the problem is still there. If it helps, this is an uberjar of babashka:

https://github.com/borkdude/babashka/releases/download/v0.0.70/babashka-0.0.70-standalone.jar

It is provided which each new release:

https://github.com/borkdude/babashka/releases

This is the part of the compilation script using that jar:

if [ -z "$BABASHKA_XMX" ]; then
    export BABASHKA_XMX="-J-Xmx3g"
fi

$BABASHKA_VERSION=0.0.70

$GRAALVM_HOME/bin/native-image \
  -jar target/babashka-$BABASHKA_VERSION-standalone.jar \
  -H:Name=bb \
  -H:+ReportExceptionStackTraces \
  -J-Dclojure.spec.skip-macros=true \
  -J-Dclojure.compiler.direct-linking=true \
  "-H:IncludeResources=BABASHKA_VERSION" \
  "-H:IncludeResources=SCI_VERSION" \
  -H:ReflectionConfigurationFiles=reflection.json \
  --initialize-at-run-time=java.lang.Math\$RandomNumberGeneratorHolder \
  --initialize-at-build-time \
  -H:Log=registerResource: \
  -H:EnableURLProtocols=http,https \
  --enable-all-security-services \
  -H:+JNI \
  --verbose \
  --no-fallback \
  --no-server \
  "$BABASHKA_XMX"

[borkdude]

@olpaw Some additional data related to general performance, not only startup time.

With 20.0.0-java8 on macOS:

$ time ./bb "(loop [val 0 cnt 1000000] (if (pos? cnt) (recur (inc val) (dec cnt)) val))"
1000000
./bb    1.98s  user 0.10s system 99% cpu 2.089 total

With 19.3.1-java8 on macOS:

$ time ./bb "(loop [val 0 cnt 1000000] (if (pos? cnt) (recur (inc val) (dec cnt)) val))"
1000000
./bb    1.59s  user 0.08s system 99% cpu 1.676 total

That's a 25% loss in performance for v20.

[borkdude]

On linux the performance on version 20-java8 is slightly worse (6%) but not as noticeable as with macOS:

19.3.1:
$ multitime -n10 -s1 -q ./bb "(loop [val 0 cnt 1000000] (if (pos? cnt) (recur (inc val) (dec cnt)) val))"
===> multitime results
1: -q ./bb "(loop [val 0 cnt 1000000] (if (pos? cnt) (recur (inc val) (dec cnt)) val))"
            Mean        Std.Dev.    Min         Median      Max
real        1.785       0.037       1.737       1.780       1.873       
user        1.709       0.039       1.653       1.716       1.797       
sys         0.076       0.015       0.040       0.080       0.092    
12:44 AM

20.0.0:
$ multitime -n10 -s1 -q ./bb "(loop [val 0 cnt 1000000] (if (pos? cnt) (recur (inc val) (dec cnt)) val))"
===> multitime results
1: -q ./bb "(loop [val 0 cnt 1000000] (if (pos? cnt) (recur (inc val) (dec cnt)) val))"
            Mean        Std.Dev.    Min         Median      Max
real        1.897       0.055       1.837       1.872       1.988       
user        1.819       0.044       1.762       1.800       1.889       
sys         0.078       0.015       0.052       0.078       0.100  

This data was provided by @sogaiu who uses linux.

[olpaw]

With 20.0.0-java8 on macOS

Thanks for checking with latest releases!

[olpaw]

Atm, this is my prime subject:

> otool -L hellojava_19.3.1 
hellojava_19.3.1:
	/usr/lib/libSystem.B.dylib (compatibility version 1.0.0, current version 1252.200.5)
	/System/Library/Frameworks/CoreFoundation.framework/Versions/A/CoreFoundation (compatibility version 150.0.0, current version 1535.12.0)
	/usr/lib/libz.1.dylib (compatibility version 1.0.0, current version 1.2.11)
> otool -L hellojava_latest 
hellojava_latest:
	/System/Library/Frameworks/CoreServices.framework/Versions/A/CoreServices (compatibility version 1.0.0, current version 921.2.0)
	/usr/lib/libSystem.B.dylib (compatibility version 1.0.0, current version 1252.200.5)
	/System/Library/Frameworks/CoreFoundation.framework/Versions/A/CoreFoundation (compatibility version 150.0.0, current version 1535.12.0)
	/usr/lib/libz.1.dylib (compatibility version 1.0.0, current version 1.2.11)

We are now additionally dynamically linking to CoreServices and this likely adds to the startup time.

[olpaw]

Yep, that's it. If I comment out

graal/substratevm/src/com.oracle.svm.hosted/src/com/oracle/svm/hosted/jdk/JNIRegistrationJava.java

Line 139 in 9a53453

if (isDarwin()) {

I'm back to the startup characteristics of 19.3.1.

While we cannot fully eliminate this dynamic dependency we could make the dependency conditional on actual requirement instead of unconditional linking. @eginez please take this one from here and implement the conditional linking so that we only have to pay for the increased startup time if we actually need it.

[borkdude]

@olpaw That's good news! Is this also the cause of the general performance regression of about 25% on macOS? #2136 (comment)