native-image hangs with very high cpu on all threads

[hickst]

If I try to build the polyglot example (Getting Started/Native Images), the native-image --language:js PrettyPrintJSON command gets past the setup phase but then spikes the CPU usage of every thread on the machine to 90+% and never finishes the build:

/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/bin/java \
-Xbootclasspath/a:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/boot/graal-sdk.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/boot/graaljs-scriptengine.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/truffle/truffle-api.jar \
-cp \
/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/svm/builder/graal-llvm.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/svm/builder/javacpp.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/svm/builder/llvm-platform-specific.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/svm/builder/llvm-wrapper.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/svm/builder/objectfile.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/svm/builder/pointsto.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/svm/builder/svm-llvm.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/svm/builder/svm.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/jvmci/graal-management.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/jvmci/graal.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/jvmci/jvmci-api.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/jvmci/jvmci-hotspot.jar \
-XX:+UnlockExperimentalVMOptions \
-XX:+EnableJVMCI \
-XX:-UseJVMCICompiler \
-Dtruffle.TrustAllTruffleRuntimeProviders=true \
-Dtruffle.TruffleRuntime=com.oracle.truffle.api.impl.DefaultTruffleRuntime \
-Dgraalvm.locatorDisabled=true \
-d64 \
-XX:-UseJVMCIClassLoader \
-Xss10m \
-Duser.country=US \
-Duser.language=en \
-Dgraalvm.version=1.0.0-rc15 \
-Dorg.graalvm.version=1.0.0-rc15 \
-Dorg.graalvm.config=CE \
-Dcom.oracle.graalvm.isaot=true \
-Djvmci.class.path.append=/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/jvmci/graal.jar \
-Dtruffle.TruffleRuntime=com.oracle.svm.truffle.api.SubstrateTruffleRuntime \
-Dpolyglot.engine.PreinitializeContexts=js \
-Xmx14g \
-Xms1g \
com.oracle.svm.hosted.server.NativeImageBuildServer \
-port=0 \
-logFile=/Users/hickst/.native-image/machine-id-hostid-0/session-id-5fa1/server-id-8db26f8643025992df9b0b59dad265aeede4b47b0b794bc2aef2db49399f0d28278a23615c41165928b38e1e0ba2a498d96abdb2c9c54b2b59fb2b7e41f256bd/server.log
]
Build on Server(pid: 71843, port: 56323)*
SendBuildRequest [
-task=com.oracle.svm.hosted.NativeImageGeneratorRunner
-imagecp
/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/svm/builder/graal-llvm.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/svm/builder/javacpp.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/svm/builder/llvm-platform-specific.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/svm/builder/llvm-wrapper.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/svm/builder/objectfile.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/svm/builder/pointsto.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/svm/builder/svm-llvm.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/svm/builder/svm.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/jvmci/graal-management.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/jvmci/graal.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/jvmci/jvmci-api.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/jvmci/jvmci-hotspot.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/boot/graal-sdk.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/boot/graaljs-scriptengine.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/truffle/truffle-api.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/svm/library-support.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/tools/regex/tregex.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/languages/js/asm-6.2.1.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/languages/js/asm-analysis-6.2.1.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/languages/js/asm-commons-6.2.1.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/languages/js/asm-tree-6.2.1.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/languages/js/asm-util-6.2.1.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/languages/js/graaljs.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/languages/js/icu4j.jar:/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/languages/js/trufflenode.jar:/Users/hickst/lang/typescript
-H:Path=/Users/hickst/lang/typescript
-H:Features=com.oracle.svm.truffle.TruffleFeature
-H:MaxRuntimeCompileMethods=9900
-H:CLibraryPath=/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/jre/lib/svm/clibraries/darwin-amd64
-H:Class=PrettyPrintJSON
-H:Name=prettyprintjson
]
[prettyprintjson:71843]    classlist:   5,184.33 ms
[prettyprintjson:71843]        (cap):   2,289.45 ms
[prettyprintjson:71843]        setup:   4,070.67 ms

[hickst]

@olpaw commented:

@hickst can you try if the following helps:

Create an empty subdir and copy the PrettyPrintJSON.class into that directory

graalvm-ce-1.0.0-rc15> mkdir classpathdir
graalvm-ce-1.0.0-rc15> cp PrettyPrintJSON.class classpathdir

Build the image with an explicit -cp argument

graalvm-ce-1.0.0-rc15> bin/native-image -cp classpathdir --language:js PrettyPrintJSON

With this you should get something like:

Build on Server(pid: 10487, port: 33369)
[prettyprintjson:10487]    classlist:   1,883.69 ms
[prettyprintjson:10487]        (cap):     545.22 ms
[prettyprintjson:10487]        setup:     821.53 ms
[prettyprintjson:10487]   (typeflow):  20,463.52 ms
[prettyprintjson:10487]    (objects):  28,121.23 ms
[prettyprintjson:10487]   (features):   5,638.85 ms
[prettyprintjson:10487]     analysis:  55,889.52 ms
8594 method(s) included for runtime compilation
[prettyprintjson:10487]     universe:   1,682.66 ms
[prettyprintjson:10487]      (parse):   3,395.78 ms
[prettyprintjson:10487]     (inline):  10,232.08 ms
[prettyprintjson:10487]    (compile):  19,208.10 ms
[prettyprintjson:10487]      compile:  36,167.97 ms
[prettyprintjson:10487]        image:   5,836.29 ms
[prettyprintjson:10487]        write:     656.03 ms
[prettyprintjson:10487]      [total]: 103,306.49 ms

[olpaw]

@hickst I changed the title to indicate that I was not able to reproduce the problem on Linux (as already shown in #1158 (comment))

[hickst]

@olpaw Thanks for the idea but it didn't help. native-image starts, it passes the setup stage and just hangs with all threads showing very high usage (see attached screenshot). It never finishes and, after a few minutes, I have to force kill the java process.

[twelf:test () 1069] => which native-image
/Library/Java/JavaVirtualMachines/graalvm-ce-1.0.0-rc15/Contents/Home/bin/native-image
[twelf:test () 1070] => native-image -cp cpdir --language:js PrettyPrintJSON
Build on Server(pid: 2908, port: 53596)*
[prettyprintjson:2908]    classlist:   5,648.05 ms
[prettyprintjson:2908]        (cap):   2,370.81 ms
[prettyprintjson:2908]        setup:   4,139.49 ms

[olpaw]

@hickst do you get the same behavior if you run with --no-server ?

> native-image --server-shutdown-all # Ensure all build servers are shut down.
> native-image --no-server -cp cpdir --language:js PrettyPrintJSON

[olpaw]

Also how much RAM does you machine have?

[hickst]

My Mac has 128G but your question made me examine the memory issue....so I increased the heap size from 2G to 16G and it successfully compiled the (17 line) PrettyPrintJSON program in 2.5 minutes:

[twelf:graal () 250] => native-image --no-server -cp cpdir --language:js PrettyPrintJSON
Picked up _JAVA_OPTIONS: -Xms1024m -Xmx16g
[prettyprintjson:7860]    classlist:   5,117.96 ms
[prettyprintjson:7860]        (cap):   1,672.38 ms
[prettyprintjson:7860]        setup:   3,409.85 ms
[prettyprintjson:7860]   (typeflow):  24,928.64 ms
[prettyprintjson:7860]    (objects):  40,697.99 ms
[prettyprintjson:7860]   (features):   9,756.91 ms
[prettyprintjson:7860]     analysis:  77,430.69 ms
8606 method(s) included for runtime compilation
[prettyprintjson:7860]     universe:   2,926.35 ms
[prettyprintjson:7860]      (parse):   4,693.89 ms
[prettyprintjson:7860]     (inline):  11,567.74 ms
[prettyprintjson:7860]    (compile):  28,875.52 ms
[prettyprintjson:7860]      compile:  50,180.27 ms
[prettyprintjson:7860]        image:   9,767.38 ms
[prettyprintjson:7860]        write:   2,325.55 ms
[prettyprintjson:7860]      [total]: 152,440.35 ms
1323.832u 92.618s 2:33.73 921.3%	0+0k 50+26io 36712pf+0w

However, the native executable does not work correctly: the JSON is not pretty printed:

[twelf:graal () 252] => ./prettyprintjson <test.json
{"GraalVM":{"description":"Language Abstraction Platform","supports":["combining languages","embedding languages","creating native images"],"languages":["Java","JavaScript","Node.js","Python","Ruby","R","LLVM"]}}

Also, this is not just a Mac issue: here's the failure on Ubuntu 16.04, using 2G of heap:

[esne:graal () 252] => native-image --no-server -cp cpdir --language:js PrettyPrintJSON                                              Picked up _JAVA_OPTIONS: -Xms512m -Xmx2048m
[prettyprintjson:29950]    classlist:   2,641.65 ms
[prettyprintjson:29950]        (cap):     676.81 ms
[prettyprintjson:29950]        setup:   1,607.46 ms
[prettyprintjson:29950]     analysis: 559,475.51 ms
Exception in thread "native-image pid watcher" java.lang.OutOfMemoryError: Java heap space

but a successful compilation (albeit in 1:45 minutes) with 16G of heap (out of 32G total memory):

[esne:graal () 273] => native-image --no-server -cp cpdir --language:js PrettyPrintJSON
Picked up _JAVA_OPTIONS: -Xms1024m -Xmx16g
[prettyprintjson:13013]    classlist:   2,325.44 ms
[prettyprintjson:13013]        (cap):     648.47 ms
[prettyprintjson:13013]        setup:   1,626.23 ms
[prettyprintjson:13013]   (typeflow):  24,679.90 ms
[prettyprintjson:13013]    (objects):  21,982.53 ms
[prettyprintjson:13013]   (features):   4,849.85 ms
[prettyprintjson:13013]     analysis:  52,863.64 ms
8606 method(s) included for runtime compilation
[prettyprintjson:13013]     universe:   1,666.76 ms
[prettyprintjson:13013]      (parse):   3,363.65 ms
[prettyprintjson:13013]     (inline):   6,417.83 ms
[prettyprintjson:13013]    (compile):  27,755.25 ms
[prettyprintjson:13013]      compile:  40,215.26 ms
[prettyprintjson:13013]        image:   4,787.47 ms
[prettyprintjson:13013]        write:     602.84 ms
[prettyprintjson:13013]      [total]: 104,707.87 ms
515.576u 3.408s 1:45.05 494.0%	0+0k 0+295464io 1pf+0w

and, again, the program does not pretty print the input JSON:

[esne:graal () 280] => ./prettyprintjson < test.json
{"GraalVM":{"description":"Language Abstraction Platform","supports":["combining languages","embedding languages","creating native images"],"languages":["Java","JavaScript","Node.js","Python","Ruby","R","LLVM"]}}

The issue is very consistent but I cannot discount the possibility that I've installed or configured the GraalVM incorrectly, somehow, on both machines. Do you have any suggestions for what parts of my environment I should check?

[hickst]

Using the server again shaved 45 seconds off of the build:

[esne:graal () 290] => native-image -cp cpdir --language:js PrettyPrintJSON
Build on Server(pid: 4174, port: 38402)*
[prettyprintjson:4174]    classlist:   2,236.05 ms
[prettyprintjson:4174]        (cap):     637.44 ms
[prettyprintjson:4174]        setup:   1,540.30 ms
[prettyprintjson:4174]   (typeflow):  19,901.79 ms
[prettyprintjson:4174]    (objects):  25,400.25 ms
[prettyprintjson:4174]   (features):   4,997.36 ms
[prettyprintjson:4174]     analysis:  51,615.16 ms
8606 method(s) included for runtime compilation
[prettyprintjson:4174]     universe:   1,645.83 ms
[prettyprintjson:4174]      (parse):   3,556.94 ms
[prettyprintjson:4174]     (inline):   8,231.27 ms
[prettyprintjson:4174]    (compile):  24,927.06 ms
[prettyprintjson:4174]      compile:  39,472.29 ms
[prettyprintjson:4174]        image:   4,735.48 ms
[prettyprintjson:4174]        write:     593.24 ms
[prettyprintjson:4174]      [total]: 102,496.65 ms

and reducing the heap memory to 8G was similarily successful. But, still no luck on the pretty printing:

[esne:graal () 329] => ./prettyprintjson < test.json
{"GraalVM":{"description":"Language Abstraction Platform","supports":["combining languages","embedding languages","creating native images"],"languages":["Java","JavaScript","Node.js","Python","Ruby","R","LLVM"]}}

[olpaw]

Building an image that contains graaljs with less than 4G for image building is not really a good idea. Image building requires large amounts of memory, especially if you build large images with truffle included.

For server-based image building we allow to use 80% of your reported physical RAM for all servers together (keeping max 2 servers alive is currently hardcoded). But never more than 14GB per server (see

graal/substratevm/src/com.oracle.svm.driver/src/com/oracle/svm/driver/NativeImage.java

Line 1374 in 556bed6

protected String getXmxValue(int maxInstances) {

for details)
If you run with --no-server you get the whole 80% of what is reported as physical RAM as baseline. (In this mode additionally provided -Xmx args are respected.)

[olpaw]

But, still no luck on the pretty printing:

Hmm, the image behaves exactly the same as running PrettyPrintJSON on the JVM:

cat <<EOF > sample.json
{
  "firstName": "John",
  "lastName": "Smith",
  "age": 25,
  "address": {
    "streetAddress": "21 2nd Street",
    "city": "New York",
    "state": "NY",
    "postalCode": "10021"
  },
  "phoneNumber": [
    {
      "type": "home",
      "number": "212 555-1234"
    },
    {
      "type": "fax",
      "number": "646 555-4567"
    }
  ],
  "gender": {
    "type": "male"
  }
}
EOF

When running on JVM (via the java command):

> bin/java PrettyPrintJSON < sample.json
{"firstName":"John","lastName":"Smith","age":25,"address":{"streetAddress":"21 2nd Street","city":"New York","state":"NY","postalCode":"10021"},"phoneNumber":[{"type":"home","number":"212 555-1234"},{"type":"fax","number":"646 555-4567"}],"gender":{"type":"male"}}

when running as native image:

> ./prettyprintjson < sample.json
{"firstName":"John","lastName":"Smith","age":25,"address":{"streetAddress":"21 2nd Street","city":"New York","state":"NY","postalCode":"10021"},"phoneNumber":[{"type":"home","number":"212 555-1234"},{"type":"fax","number":"646 555-4567"}],"gender":{"type":"male"}}

The only difference I can see is that it executes much faster when running as image
... but that's the beauty of it 😁

> time bin/java PrettyPrintJSON < sample.json > /dev/null
real	0m0.647s

vs.

> time ./prettyprintjson < sample.json > /dev/null
real	0m0.007s

[hickst]

Building an image that contains graaljs with less than 4G for image building is not really a good idea. Image building requires large amounts of memory, especially if you build large images with truffle included.

For server-based image building we allow to use 80% of your reported physical RAM for all servers together (keeping max 2 servers alive is currently hardcoded). But never more than 14GB per server (see

graal/substratevm/src/com.oracle.svm.driver/src/com/oracle/svm/driver/NativeImage.java

Line 1374 in 556bed6

protected String getXmxValue(int maxInstances) {
for details)
If you run with --no-server you get the whole 80% of what is reported as physical RAM as baseline. (In this mode additionally provided -Xmx args are respected.)

Thanks for the clarification: this is all good to know. But, did I miss this requirement documented somewhere in the Getting Started guide? Documentation seems especially important since the maximum heap size (listed by Oracle documentation for Java 8) is "Smaller of 1/4th of the physical memory or 1GB.", which will be insufficient to build the native-image.

[hickst]

Hmm, the image behaves exactly the same as running PrettyPrintJSON on the JVM:

When running on JVM (via the java command):

> bin/java PrettyPrintJSON < sample.json
{"firstName":"John","lastName":"Smith","age":25,"address":{"streetAddress":"21 2nd Street","city":"New York","state":"NY","postalCode":"10021"},"phoneNumber":[{"type":"home","number":"212 555-1234"},{"type":"fax","number":"646 555-4567"}],"gender":{"type":"male"}}

when running as native image:

> ./prettyprintjson < sample.json
{"firstName":"John","lastName":"Smith","age":25,"address":{"streetAddress":"21 2nd Street","city":"New York","state":"NY","postalCode":"10021"},"phoneNumber":[{"type":"home","number":"212 555-1234"},{"type":"fax","number":"646 555-4567"}],"gender":{"type":"male"}}

But...but....but it's supposed to actually pretty print the JSON!, as illustrated in the example from the Getting Started guide:

[hickst]

I just updated to RC16 (on both OSX and Ubuntu) and the issues remain: it takes 2:5+ minutes to build a native image from the 1830 byte PrettyPrintJSON.class file and the result doesn't correctly pretty print the given JSON.

[thomaswue]

This is not just building that PrettyPrintJSON class, but includes building a JavaScript engine and the GraalVM compiler when creating that image; so probably more than 10000 classes.

We will update the documentation to include heap requirements when adding a dynamic scripting language including compiler to a native image and fix the illustration output to match the program output.

[hickst]

Thanks, those steps seem reasonable to close this issue. But, I'm still confused....why use a pretty print example if it wasn't intended to really pretty print?

[thomaswue]

It does pretty print, just without indentation. If you want indentation, you can specify this as the third parameter to the JSON.stringify method call:
Value result = stringify.execute(parse.execute(input), null, 2);

We will make sure that output and program exactly matches with respect to pretty printing parameters.

[hickst]

Ah, I see! Tested and confirmed. Thank-you for promising to fix the documentation so new users like me are no longer confused. :)

[thomaswue]

Excellent! Thanks for the report! We will close the issue when the documentation fix is propagated.

[olyagpl]

@hickst, please find heap requirements in https://www.graalvm.org/docs/reference-manual/aot-compilation/#prerequisites section. The JSON.stringify method of the example program has been updated too.
Thank you for the feedback