Quarkus 3.0 PicoCli native speed same as jar speed? was Quarkus 3.0 alpha 6 native build doesn't build native binary?

[kenyee]

I ran

./gradlew build -Dquarkus.package.type=native

and it claims it produced these artifacts:

Produced artifacts:
 /Users/keny/Downloads/projectmeta-cli/build/projectmeta-cli-1.0.0-SNAPSHOT-native-image-source-jar/projectmeta-cli-1.0.0-SNAPSHOT-runner (executable)
 /Users/keny/Downloads/projectmeta-cli/build/projectmeta-cli-1.0.0-SNAPSHOT-native-image-source-jar/projectmeta-cli-1.0.0-SNAPSHOT-runner-build-output-stats.json (json)
 /Users/keny/Downloads/projectmeta-cli/build/projectmeta-cli-1.0.0-SNAPSHOT-native-image-source-jar/projectmeta-cli-1.0.0-SNAPSHOT-runner-timing-stats.json (raw)
 /Users/keny/Downloads/projectmeta-cli/build/projectmeta-cli-1.0.0-SNAPSHOT-native-image-source-jar/projectmeta-cli-1.0.0-SNAPSHOT-runner.build_artifacts.txt (txt)

but what's in the directory is:

ls -l /Users/keny/Downloads/projectmeta-cli/build/projectmeta-cli-1.0.0-SNAPSHOT-native-image-source-jar
total 984
drwxr-xr-x@ 131 keny  staff    4192 Mar 16 09:51 lib
-rw-r--r--@   1 keny  staff     816 Mar 16 09:52 projectmeta-cli-1.0.0-SNAPSHOT-runner-build-output-stats.json
-rw-r--r--@   1 keny  staff    3291 Mar 16 09:52 projectmeta-cli-1.0.0-SNAPSHOT-runner-timing-stats.json
-rw-r--r--@   1 keny  staff      52 Mar 16 09:52 projectmeta-cli-1.0.0-SNAPSHOT-runner.build_artifacts.txt
-rw-r--r--@   1 keny  staff  489581 Mar 16 09:51 projectmeta-cli-1.0.0-SNAPSHOT-runner.jar

Looks like only the jar file got built...not the graalvm native image 🤔

Also, the directory seems like an odd place to put the result. Why is it in a directory named "/Users/keny/Downloads/projectmeta-cli/build/projectmeta-cli-1.0.0-SNAPSHOT-native-image-source-jar"?

There's also:
/Users/keny/Downloads/projectmeta-cli/build/quarkus-app/app
but the only thing in that directory is the .jar file

% ls -l build/quarkus-app/app
total 352
-rw-r--r--  1 keny  staff  176372 Mar 16 11:36 projectmeta-cli-1.0.0-SNAPSHOT.jar

[gsmet]

Does it work with Alpha5?

Do you see something odd in the log from the build?

[kenyee]

I didn't see anything odd in the build and also haven't tried Alpha5 (I'm testing Quarkus3 for the first time). I was just trying to create a pico-cli project to see how small a file it generated (trying to see how useful quarkus is for building command line shell script alternatives).
It has pretty minimal stuff in it...pico-cli and the resteasy-client-reactive extensions. I've attached the project.
quarkus3_alpha6_native_gen_bug.zip

[kenyee]

FYI, retried this w/ Quarkus 2.16 and it built a native executable as expected though startup took longer than I expected (thought I could use this as a nice dev environment for a pico-cli tool but it takes 5sec to run:

% time build/testnative-1.0.0-SNAPSHOT-runner
...
build/testnative-1.0.0-SNAPSHOT-runner  0.02s user 0.02s system 0% cpu 5.049 total
% time build/testnative-1.0.0-SNAPSHOT-runner -h
Usage: greeting [-hV] <name>
      <name>      Your name.
  -h, --help      Show this help message and exit.
  -V, --version   Print version information and exit.
2023-03-17 14:31:45,194 INFO  [io.quarkus] (main) testnative stopped in 0.002s
build/testnative-1.0.0-SNAPSHOT-runner -h  0.02s user 0.03s system 0% cpu 5.056 total

Attached the zip file if you're curious.
testnative.zip

[kenyee]

FYI, I tried this with 3.0.0-beta1 and it seems to work... added extensions for pico-cli, resteasy-client, and resteasy-client-kotlin-serialization

% time ./build/test-1.0.0-SNAPSHOT-runner -help
....
2023-03-25 20:23:03,225 WARN [io.qua.net.run.NettyRecorder] (Thread-1) Netty DefaultChannelId initialization (with io.netty.machineId system property set to 37:f0:1a:14:0a:b0:87:f9) took more than a second
2023-03-25 20:23:03,245 INFO [io.quarkus] (main) test 1.0.0-SNAPSHOT native (powered by Quarkus 3.0.0.Beta1) started in 5.040s. Listening on: http://0.0.0.0:8080
...
2023-03-25 20:19:51,277 INFO [io.quarkus] (main) test stopped in 0.002s
./build/test-1.0.0-SNAPSHOT-runner -help 0.02s user 0.02s system 0% cpu 5.047 total

A bit puzzled by the 5sec startup time but it at least builds a binary :-)

[kenyee]

Trimmed the project down a bit more and apparently the Resteasy Client is what causes the 5sec startup time 😮 🤔

If I want the picocli CLI command to be able to make JSON API calls, it seems like the RestEasy Client should not be used (probably should be mentioned in the picocli documentation). Will look at lighter JSON frameworks like Retrofit.

Quarkus does look like a nice way to do native CLI command builds :-)

[kenyee]

Hmm...even without the Resteasy Client, the total run time of the simple picocli extension native image is still 5sec even though startup is claimed to be 0.010s for the first thing it prints out 🤔
The time difference is between the start point and the activated point...

2023-03-25 21:03:18,571 INFO  [io.quarkus] (main) test 0.0.1 native (powered by Quarkus 3.0.0.Beta1) started in 0.007s.
2023-03-25 21:03:23,577 INFO  [io.quarkus] (main) Profile prod activated.
2023-03-25 21:03:23,577 INFO  [io.quarkus] (main) Installed features: [cdi, kotlin, picocli]
2023-03-25 21:03:23,579 INFO  [io.quarkus] (main) test stopped in 0.000s

Note the timestamp difference between started and profile activated 🤔

[kenyee]

what's interesting is that the overall time for running the jar is similar:

2023-03-25 21:10:58,658 INFO  [io.quarkus] (main) test 0.0.1 on JVM (powered by Quarkus 3.0.0.Beta1) started in 5.195s.
2023-03-25 21:10:58,670 INFO  [io.quarkus] (main) Profile prod activated.
2023-03-25 21:10:58,671 INFO  [io.quarkus] (main) Installed features: [cdi, kotlin, picocli]
Hello picocli, go go commando!
2023-03-25 21:10:58,713 INFO  [io.quarkus] (main) test stopped in 0.005s

0.58s user 0.07s system 12% cpu 5.328 total

compared to running the native binary with time:
0.01s user 0.02s system 0% cpu 5.282 total

it's puzzling that the overall run time is similar despite the different in user time 🤔
This makes it not worth using graalvm native mode for picocli apps...

[gsmet]

My guess is that you have a problem with your DNS setup and it takes a while to resolve something.

[kenyee]

No issues w/ DNS that I know of. I tried turning off wifi which should make everything resolve/fail quicker and timing is the same.

Also tried running the native binary w/ debug logging (by passing the -Dquarkus.log.level=DEBUG param) and there's no info about what it's doing in that weird 5sec started to activated time window but there's a tiny bit more info on the shutdown:

2023-03-26 08:38:48,098 INFO  [io.quarkus] (main) test 0.0.1 native (powered by Quarkus 3.0.0.Beta1) started in 0.007s.
2023-03-26 08:38:53,105 INFO  [io.quarkus] (main) Profile prod activated.
2023-03-26 08:38:53,105 INFO  [io.quarkus] (main) Installed features: [cdi, kotlin, picocli]
Usage: greeting [-hV] <name>
      <name>      Your name.
  -h, --help      Show this help message and exit.
  -V, --version   Print version information and exit.
2023-03-26 08:38:53,108 DEBUG [io.qua.run.Application] (main) Stopping application
2023-03-26 08:38:53,108 DEBUG [io.qua.run.shu.ShutdownRecorder] (main) Attempting to gracefully shutdown.
2023-03-26 08:38:53,109 DEBUG [io.qua.arc.impl] (main) ArC DI container shut down
2023-03-26 08:38:53,109 DEBUG [io.qua.thread-pool] (main) loop: 1, remaining: 60000000000, intervalRemaining: 5000000000, interruptRemaining: 10000000000
2023-03-26 08:38:53,109 INFO  [io.quarkus] (main) test stopped in 0.000s

You folks are probably busy getting 3.0 released but this makes picocli not very useful if every command takes an extra 5sec to run...
A regular JBang or picocli script doesn't have this weird 5sec delay.