search

oracle / graal

GraalVM compiles Java applications into native executables that start instantly, scale fast, and use fewer compute resources 🚀
https://www.graalvm.org
Other
20.44k stars 1.64k forks source link

[GR-55241] Performance regression of Scala compiler on GraalVM 17 -> 21 #9267

Open szeiger opened 4 months ago

szeiger commented 4 months ago

I am benchmarking our Bazel-based Scala compiler tooling on different JDKs and I see a significant loss of performance when upgrading from GraalVM 17 to 21 (539s -> 583s in our internal benchmark). I was able to reproduce this regression by simply building the Scala compiler with sbt, albeit to a lesser extent.

Test environment: EC2 m7i.24xlarge, Ubuntu 20.04, all JDKs downloaded with sdkman.

Test setup:

git clone https://github.com/scala/scala.git
cd scala
git checkout tags/v2.13.14
sbt compiler/compile

Test run:

sbt --no-colors "clean;compiler/compile; clean;compiler/compile; clean;compiler/compile; clean;compiler/compile; clean;compiler/compile; clean;compiler/compile; clean;compiler/compile; clean;compiler/compile; clean;compiler/compile; clean;compiler/compile" | grep -e "Total time:" -e "welcome to"

Run times measured as averages of 2 runs with 10 compilations each (i.e. warm-up time amortized over 10 compilations). When looking at the raw data, you can also easily see the difference both in cold and warm build times. Run-to-run consistency is high. Note that sbt only outputs the build time in full seconds which limits the precision a bit.

These are the results I get on the latest GraalVM CE 17 & 21 and GraalVM EE 17 & 21. I'm also adding the latest JDK22-based version of each (with results that are are pretty much the same as on 21), plus Temurin OpenJDK builds of 17 and 21 which show that this regression is specific to Graal. In fact, Temurin got significantly faster from 17 to 21 (but all versions of GraalVM that I benchmarked beat all non-Graal OpenJDK builds).

Distribution 17 21 22
Graal EE 30.0s 31.6s 31.65s
Graal CE 35.25s 35.8s 35.6s
Temurin 40.5s 38.7s

The exact versions are 17.0.11-graal, 21.0.3-graal, 22.0.1-graal, 17.0.9-graalce, 21.0.2-graalce, 22.0.1-graalce, 17.0.11-tem, 21.0.3-tem.

Our internal compiler tooling benchmarks were run with -XX:MaxInlineLevel=20 as the only performance-related option and otherwise identical configuration. The Scala compiler sbt build was run as-is with no additional JVM configuration.

selhagani commented 4 months ago

Hi @szeiger, thank you for reaching out to us about this.
We'll take a look at it and get back to you.

szeiger commented 4 months ago

For reference, this is the raw data I collected:

17.0.11-graal:

[info] welcome to sbt 1.9.9 (Oracle Corporation Java 17.0.11)
[success] Total time: 0 s, completed Jul 8, 2024, 4:28:53 PM
[success] Total time: 51 s, completed Jul 8, 2024, 4:29:43 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:29:44 PM
[success] Total time: 30 s, completed Jul 8, 2024, 4:30:14 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:30:14 PM
[success] Total time: 28 s, completed Jul 8, 2024, 4:30:43 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:30:43 PM
[success] Total time: 28 s, completed Jul 8, 2024, 4:31:10 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:31:11 PM
[success] Total time: 28 s, completed Jul 8, 2024, 4:31:39 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:31:39 PM
[success] Total time: 28 s, completed Jul 8, 2024, 4:32:06 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:32:06 PM
[success] Total time: 27 s, completed Jul 8, 2024, 4:32:34 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:32:34 PM
[success] Total time: 27 s, completed Jul 8, 2024, 4:33:01 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:33:01 PM
[success] Total time: 27 s, completed Jul 8, 2024, 4:33:28 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:33:28 PM
[success] Total time: 27 s, completed Jul 8, 2024, 4:33:56 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:33:56 PM

[success] Total time: 0 s, completed Jul 8, 2024, 4:34:59 PM
[success] Total time: 50 s, completed Jul 8, 2024, 4:35:49 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:35:49 PM
[success] Total time: 30 s, completed Jul 8, 2024, 4:36:19 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:36:19 PM
[success] Total time: 28 s, completed Jul 8, 2024, 4:36:48 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:36:48 PM
[success] Total time: 28 s, completed Jul 8, 2024, 4:37:15 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:37:16 PM
[success] Total time: 28 s, completed Jul 8, 2024, 4:37:43 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:37:43 PM
[success] Total time: 27 s, completed Jul 8, 2024, 4:38:11 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:38:11 PM
[success] Total time: 27 s, completed Jul 8, 2024, 4:38:38 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:38:38 PM
[success] Total time: 27 s, completed Jul 8, 2024, 4:39:05 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:39:05 PM
[success] Total time: 27 s, completed Jul 8, 2024, 4:39:32 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:39:33 PM
[success] Total time: 27 s, completed Jul 8, 2024, 4:40:00 PM

21.0.3-graal:

[info] welcome to sbt 1.9.9 (Oracle Corporation Java 21.0.3)
[success] Total time: 0 s, completed Jul 8, 2024, 4:42:34 PM
[success] Total time: 55 s, completed Jul 8, 2024, 4:43:30 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:43:30 PM
[success] Total time: 33 s, completed Jul 8, 2024, 4:44:03 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:44:03 PM
[success] Total time: 30 s, completed Jul 8, 2024, 4:44:33 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:44:33 PM
[success] Total time: 29 s, completed Jul 8, 2024, 4:45:02 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:45:02 PM
[success] Total time: 29 s, completed Jul 8, 2024, 4:45:30 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:45:31 PM
[success] Total time: 28 s, completed Jul 8, 2024, 4:45:59 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:45:59 PM
[success] Total time: 29 s, completed Jul 8, 2024, 4:46:28 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:46:28 PM
[success] Total time: 28 s, completed Jul 8, 2024, 4:46:56 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:46:56 PM
[success] Total time: 28 s, completed Jul 8, 2024, 4:47:24 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:47:24 PM
[success] Total time: 28 s, completed Jul 8, 2024, 4:47:52 PM

[info] welcome to sbt 1.9.9 (Oracle Corporation Java 21.0.3)
[success] Total time: 0 s, completed Jul 8, 2024, 4:48:05 PM
[success] Total time: 55 s, completed Jul 8, 2024, 4:49:00 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:49:00 PM
[success] Total time: 32 s, completed Jul 8, 2024, 4:49:33 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:49:33 PM
[success] Total time: 29 s, completed Jul 8, 2024, 4:50:02 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:50:02 PM
[success] Total time: 29 s, completed Jul 8, 2024, 4:50:31 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:50:32 PM
[success] Total time: 28 s, completed Jul 8, 2024, 4:51:00 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:51:00 PM
[success] Total time: 29 s, completed Jul 8, 2024, 4:51:29 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:51:29 PM
[success] Total time: 28 s, completed Jul 8, 2024, 4:51:57 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:51:57 PM
[success] Total time: 28 s, completed Jul 8, 2024, 4:52:25 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:52:25 PM
[success] Total time: 28 s, completed Jul 8, 2024, 4:52:54 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:52:54 PM
[success] Total time: 28 s, completed Jul 8, 2024, 4:53:22 PM

17.0.9-graalce:

[info] welcome to sbt 1.9.9 (GraalVM Community Java 17.0.9)
[success] Total time: 0 s, completed Jul 8, 2024, 4:55:06 PM
[success] Total time: 61 s (01:01), completed Jul 8, 2024, 4:56:07 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:56:07 PM
[success] Total time: 35 s, completed Jul 8, 2024, 4:56:42 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:56:42 PM
[success] Total time: 34 s, completed Jul 8, 2024, 4:57:16 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:57:16 PM
[success] Total time: 33 s, completed Jul 8, 2024, 4:57:49 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:57:49 PM
[success] Total time: 33 s, completed Jul 8, 2024, 4:58:22 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:58:22 PM
[success] Total time: 32 s, completed Jul 8, 2024, 4:58:54 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:58:54 PM
[success] Total time: 33 s, completed Jul 8, 2024, 4:59:27 PM
[success] Total time: 0 s, completed Jul 8, 2024, 4:59:27 PM
[success] Total time: 32 s, completed Jul 8, 2024, 4:59:59 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:00:00 PM
[success] Total time: 33 s, completed Jul 8, 2024, 5:00:32 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:00:32 PM
[success] Total time: 32 s, completed Jul 8, 2024, 5:01:04 PM

[info] welcome to sbt 1.9.9 (GraalVM Community Java 17.0.9)
[success] Total time: 0 s, completed Jul 8, 2024, 5:01:59 PM
[success] Total time: 55 s, completed Jul 8, 2024, 5:02:54 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:02:54 PM
[success] Total time: 35 s, completed Jul 8, 2024, 5:03:29 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:03:29 PM
[success] Total time: 33 s, completed Jul 8, 2024, 5:04:02 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:04:02 PM
[success] Total time: 32 s, completed Jul 8, 2024, 5:04:35 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:04:35 PM
[success] Total time: 32 s, completed Jul 8, 2024, 5:05:07 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:05:07 PM
[success] Total time: 32 s, completed Jul 8, 2024, 5:05:39 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:05:39 PM
[success] Total time: 32 s, completed Jul 8, 2024, 5:06:11 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:06:11 PM
[success] Total time: 32 s, completed Jul 8, 2024, 5:06:43 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:06:43 PM
[success] Total time: 32 s, completed Jul 8, 2024, 5:07:15 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:07:15 PM
[success] Total time: 32 s, completed Jul 8, 2024, 5:07:47 PM

21.0.2-graalce:

[info] welcome to sbt 1.9.9 (GraalVM Community Java 21.0.2)
[success] Total time: 0 s, completed Jul 8, 2024, 5:09:22 PM
[success] Total time: 59 s, completed Jul 8, 2024, 5:10:21 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:10:21 PM
[success] Total time: 36 s, completed Jul 8, 2024, 5:10:58 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:10:58 PM
[success] Total time: 34 s, completed Jul 8, 2024, 5:11:32 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:11:32 PM
[success] Total time: 33 s, completed Jul 8, 2024, 5:12:06 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:12:06 PM
[success] Total time: 33 s, completed Jul 8, 2024, 5:12:39 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:12:39 PM
[success] Total time: 33 s, completed Jul 8, 2024, 5:13:12 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:13:12 PM
[success] Total time: 33 s, completed Jul 8, 2024, 5:13:45 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:13:45 PM
[success] Total time: 33 s, completed Jul 8, 2024, 5:14:18 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:14:18 PM
[success] Total time: 33 s, completed Jul 8, 2024, 5:14:51 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:14:51 PM
[success] Total time: 33 s, completed Jul 8, 2024, 5:15:24 PM

[info] welcome to sbt 1.9.9 (GraalVM Community Java 21.0.2)
[success] Total time: 0 s, completed Jul 8, 2024, 5:15:53 PM
[success] Total time: 59 s, completed Jul 8, 2024, 5:16:52 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:16:52 PM
[success] Total time: 35 s, completed Jul 8, 2024, 5:17:27 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:17:27 PM
[success] Total time: 34 s, completed Jul 8, 2024, 5:18:01 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:18:01 PM
[success] Total time: 33 s, completed Jul 8, 2024, 5:18:33 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:18:34 PM
[success] Total time: 32 s, completed Jul 8, 2024, 5:19:05 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:19:06 PM
[success] Total time: 33 s, completed Jul 8, 2024, 5:19:38 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:19:38 PM
[success] Total time: 33 s, completed Jul 8, 2024, 5:20:11 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:20:11 PM
[success] Total time: 33 s, completed Jul 8, 2024, 5:20:44 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:20:44 PM
[success] Total time: 32 s, completed Jul 8, 2024, 5:21:16 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:21:16 PM
[success] Total time: 32 s, completed Jul 8, 2024, 5:21:48 PM

17.0.11-tem:

[info] welcome to sbt 1.9.9 (Eclipse Adoptium Java 17.0.11)
[success] Total time: 0 s, completed Jul 8, 2024, 5:23:38 PM
[success] Total time: 57 s, completed Jul 8, 2024, 5:24:35 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:24:35 PM
[success] Total time: 41 s, completed Jul 8, 2024, 5:25:16 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:25:16 PM
[success] Total time: 39 s, completed Jul 8, 2024, 5:25:56 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:25:56 PM
[success] Total time: 39 s, completed Jul 8, 2024, 5:26:35 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:26:35 PM
[success] Total time: 39 s, completed Jul 8, 2024, 5:27:14 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:27:14 PM
[success] Total time: 38 s, completed Jul 8, 2024, 5:27:52 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:27:53 PM
[success] Total time: 38 s, completed Jul 8, 2024, 5:28:31 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:28:31 PM
[success] Total time: 39 s, completed Jul 8, 2024, 5:29:10 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:29:10 PM
[success] Total time: 38 s, completed Jul 8, 2024, 5:29:48 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:29:48 PM
[success] Total time: 38 s, completed Jul 8, 2024, 5:30:26 PM

[info] welcome to sbt 1.9.9 (Eclipse Adoptium Java 17.0.11)
[success] Total time: 0 s, completed Jul 8, 2024, 5:30:47 PM
[success] Total time: 56 s, completed Jul 8, 2024, 5:31:43 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:31:43 PM
[success] Total time: 40 s, completed Jul 8, 2024, 5:32:24 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:32:24 PM
[success] Total time: 39 s, completed Jul 8, 2024, 5:33:02 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:33:02 PM
[success] Total time: 39 s, completed Jul 8, 2024, 5:33:41 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:33:41 PM
[success] Total time: 39 s, completed Jul 8, 2024, 5:34:20 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:34:20 PM
[success] Total time: 39 s, completed Jul 8, 2024, 5:34:58 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:34:59 PM
[success] Total time: 38 s, completed Jul 8, 2024, 5:35:37 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:35:37 PM
[success] Total time: 38 s, completed Jul 8, 2024, 5:36:15 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:36:15 PM
[success] Total time: 39 s, completed Jul 8, 2024, 5:36:54 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:36:54 PM
[success] Total time: 37 s, completed Jul 8, 2024, 5:37:31 PM

21.0.3-tem:

[info] welcome to sbt 1.9.9 (Eclipse Adoptium Java 21.0.3)
[success] Total time: 0 s, completed Jul 8, 2024, 5:39:18 PM
[success] Total time: 57 s, completed Jul 8, 2024, 5:40:15 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:40:15 PM
[success] Total time: 39 s, completed Jul 8, 2024, 5:40:54 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:40:54 PM
[success] Total time: 37 s, completed Jul 8, 2024, 5:41:31 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:41:31 PM
[success] Total time: 36 s, completed Jul 8, 2024, 5:42:07 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:42:07 PM
[success] Total time: 37 s, completed Jul 8, 2024, 5:42:44 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:42:44 PM
[success] Total time: 36 s, completed Jul 8, 2024, 5:43:20 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:43:20 PM
[success] Total time: 36 s, completed Jul 8, 2024, 5:43:56 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:43:57 PM
[success] Total time: 36 s, completed Jul 8, 2024, 5:44:33 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:44:33 PM
[success] Total time: 36 s, completed Jul 8, 2024, 5:45:09 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:45:09 PM
[success] Total time: 36 s, completed Jul 8, 2024, 5:45:45 PM

[info] welcome to sbt 1.9.9 (Eclipse Adoptium Java 21.0.3)
[success] Total time: 0 s, completed Jul 8, 2024, 5:46:16 PM
[success] Total time: 57 s, completed Jul 8, 2024, 5:47:14 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:47:14 PM
[success] Total time: 40 s, completed Jul 8, 2024, 5:47:54 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:47:54 PM
[success] Total time: 38 s, completed Jul 8, 2024, 5:48:32 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:48:32 PM
[success] Total time: 37 s, completed Jul 8, 2024, 5:49:09 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:49:10 PM
[success] Total time: 36 s, completed Jul 8, 2024, 5:49:46 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:49:46 PM
[success] Total time: 36 s, completed Jul 8, 2024, 5:50:22 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:50:23 PM
[success] Total time: 36 s, completed Jul 8, 2024, 5:50:59 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:50:59 PM
[success] Total time: 36 s, completed Jul 8, 2024, 5:51:35 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:51:35 PM
[success] Total time: 36 s, completed Jul 8, 2024, 5:52:11 PM
[success] Total time: 0 s, completed Jul 8, 2024, 5:52:11 PM
[success] Total time: 36 s, completed Jul 8, 2024, 5:52:47 PM

22.0.1-graal:

[info] welcome to sbt 1.9.9 (Oracle Corporation Java 22.0.1)
[success] Total time: 0 s, completed Jul 8, 2024, 6:40:22 PM
[success] Total time: 55 s, completed Jul 8, 2024, 6:41:17 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:41:17 PM
[success] Total time: 33 s, completed Jul 8, 2024, 6:41:49 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:41:50 PM
[success] Total time: 30 s, completed Jul 8, 2024, 6:42:20 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:42:20 PM
[success] Total time: 29 s, completed Jul 8, 2024, 6:42:49 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:42:49 PM
[success] Total time: 29 s, completed Jul 8, 2024, 6:43:18 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:43:19 PM
[success] Total time: 29 s, completed Jul 8, 2024, 6:43:47 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:43:48 PM
[success] Total time: 29 s, completed Jul 8, 2024, 6:44:16 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:44:17 PM
[success] Total time: 28 s, completed Jul 8, 2024, 6:44:45 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:44:45 PM
[success] Total time: 28 s, completed Jul 8, 2024, 6:45:13 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:45:13 PM
[success] Total time: 28 s, completed Jul 8, 2024, 6:45:41 PM

[success] Total time: 0 s, completed Jul 8, 2024, 6:45:53 PM
[success] Total time: 55 s, completed Jul 8, 2024, 6:46:48 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:46:48 PM
[success] Total time: 33 s, completed Jul 8, 2024, 6:47:21 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:47:21 PM
[success] Total time: 29 s, completed Jul 8, 2024, 6:47:50 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:47:50 PM
[success] Total time: 29 s, completed Jul 8, 2024, 6:48:19 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:48:20 PM
[success] Total time: 29 s, completed Jul 8, 2024, 6:48:48 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:48:48 PM
[success] Total time: 28 s, completed Jul 8, 2024, 6:49:17 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:49:17 PM
[success] Total time: 28 s, completed Jul 8, 2024, 6:49:45 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:49:45 PM
[success] Total time: 28 s, completed Jul 8, 2024, 6:50:13 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:50:13 PM
[success] Total time: 28 s, completed Jul 8, 2024, 6:50:41 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:50:41 PM
[success] Total time: 28 s, completed Jul 8, 2024, 6:51:09 PM

22.0.1-graalce:

[info] welcome to sbt 1.9.9 (GraalVM Community Java 22.0.1)
[success] Total time: 0 s, completed Jul 8, 2024, 6:54:11 PM
[success] Total time: 58 s, completed Jul 8, 2024, 6:55:09 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:55:09 PM
[success] Total time: 36 s, completed Jul 8, 2024, 6:55:46 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:55:46 PM
[success] Total time: 34 s, completed Jul 8, 2024, 6:56:20 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:56:20 PM
[success] Total time: 33 s, completed Jul 8, 2024, 6:56:53 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:56:54 PM
[success] Total time: 33 s, completed Jul 8, 2024, 6:57:26 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:57:26 PM
[success] Total time: 32 s, completed Jul 8, 2024, 6:57:58 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:57:58 PM
[success] Total time: 33 s, completed Jul 8, 2024, 6:58:31 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:58:31 PM
[success] Total time: 32 s, completed Jul 8, 2024, 6:59:03 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:59:04 PM
[success] Total time: 32 s, completed Jul 8, 2024, 6:59:35 PM
[success] Total time: 0 s, completed Jul 8, 2024, 6:59:36 PM
[success] Total time: 32 s, completed Jul 8, 2024, 7:00:08 PM

[info] welcome to sbt 1.9.9 (GraalVM Community Java 22.0.1)
[success] Total time: 0 s, completed Jul 8, 2024, 7:00:39 PM
[success] Total time: 59 s, completed Jul 8, 2024, 7:01:38 PM
[success] Total time: 0 s, completed Jul 8, 2024, 7:01:38 PM
[success] Total time: 37 s, completed Jul 8, 2024, 7:02:15 PM
[success] Total time: 0 s, completed Jul 8, 2024, 7:02:15 PM
[success] Total time: 34 s, completed Jul 8, 2024, 7:02:49 PM
[success] Total time: 0 s, completed Jul 8, 2024, 7:02:49 PM
[success] Total time: 33 s, completed Jul 8, 2024, 7:03:22 PM
[success] Total time: 0 s, completed Jul 8, 2024, 7:03:22 PM
[success] Total time: 33 s, completed Jul 8, 2024, 7:03:55 PM
[success] Total time: 0 s, completed Jul 8, 2024, 7:03:55 PM
[success] Total time: 33 s, completed Jul 8, 2024, 7:04:28 PM
[success] Total time: 0 s, completed Jul 8, 2024, 7:04:28 PM
[success] Total time: 32 s, completed Jul 8, 2024, 7:05:01 PM
[success] Total time: 0 s, completed Jul 8, 2024, 7:05:01 PM
[success] Total time: 32 s, completed Jul 8, 2024, 7:05:33 PM
[success] Total time: 0 s, completed Jul 8, 2024, 7:05:33 PM
[success] Total time: 32 s, completed Jul 8, 2024, 7:06:05 PM
[success] Total time: 0 s, completed Jul 8, 2024, 7:06:05 PM
[success] Total time: 32 s, completed Jul 8, 2024, 7:06:37 PM
selhagani commented 4 months ago

Thank you for sharing that, I'm getting similar results to what you got as well

szeiger commented 4 months ago

And this is the data from our internal benchmark, building part of our monorepo with our custom Bazel-based Scala tooling:

c-refice commented 4 months ago

Hi @szeiger, unfortunately I was not able to reproduce your results on my machine. The run-to-run variance is quite high, here's a representative sample:

17.0.11-graal:

[info] welcome to sbt 1.9.9 (Oracle Corporation Java 17.0.11)
[success] Total time: 0 s, completed Jul 23, 2024, 1:25:43 PM
[success] Total time: 74 s (01:14), completed Jul 23, 2024, 1:26:57 PM
[success] Total time: 0 s, completed Jul 23, 2024, 1:26:57 PM
[success] Total time: 23 s, completed Jul 23, 2024, 1:27:20 PM
[success] Total time: 0 s, completed Jul 23, 2024, 1:27:20 PM
[success] Total time: 40 s, completed Jul 23, 2024, 1:28:00 PM
[success] Total time: 0 s, completed Jul 23, 2024, 1:28:00 PM
[success] Total time: 19 s, completed Jul 23, 2024, 1:28:20 PM
[success] Total time: 0 s, completed Jul 23, 2024, 1:28:20 PM
[success] Total time: 19 s, completed Jul 23, 2024, 1:28:39 PM
[success] Total time: 0 s, completed Jul 23, 2024, 1:28:39 PM
[success] Total time: 22 s, completed Jul 23, 2024, 1:29:01 PM
[success] Total time: 0 s, completed Jul 23, 2024, 1:29:01 PM
[success] Total time: 32 s, completed Jul 23, 2024, 1:29:33 PM
[success] Total time: 0 s, completed Jul 23, 2024, 1:29:33 PM
[success] Total time: 19 s, completed Jul 23, 2024, 1:29:52 PM
[success] Total time: 0 s, completed Jul 23, 2024, 1:29:52 PM
[success] Total time: 20 s, completed Jul 23, 2024, 1:30:12 PM
[success] Total time: 0 s, completed Jul 23, 2024, 1:30:12 PM
[success] Total time: 35 s, completed Jul 23, 2024, 1:30:48 PM

21.0.3-graal:

[info] welcome to sbt 1.9.9 (Oracle Corporation Java 21.0.3)
[success] Total time: 0 s, completed Jul 23, 2024, 1:33:00 PM
[success] Total time: 88 s (01:28), completed Jul 23, 2024, 1:34:28 PM
[success] Total time: 0 s, completed Jul 23, 2024, 1:34:28 PM
[success] Total time: 59 s, completed Jul 23, 2024, 1:35:27 PM
[success] Total time: 0 s, completed Jul 23, 2024, 1:35:27 PM
[success] Total time: 47 s, completed Jul 23, 2024, 1:36:14 PM
[success] Total time: 0 s, completed Jul 23, 2024, 1:36:14 PM
[success] Total time: 21 s, completed Jul 23, 2024, 1:36:36 PM
[success] Total time: 0 s, completed Jul 23, 2024, 1:36:36 PM
[success] Total time: 40 s, completed Jul 23, 2024, 1:37:16 PM
[success] Total time: 0 s, completed Jul 23, 2024, 1:37:16 PM
[success] Total time: 20 s, completed Jul 23, 2024, 1:37:36 PM
[success] Total time: 0 s, completed Jul 23, 2024, 1:37:36 PM
[success] Total time: 20 s, completed Jul 23, 2024, 1:37:57 PM
[success] Total time: 0 s, completed Jul 23, 2024, 1:37:57 PM
[success] Total time: 39 s, completed Jul 23, 2024, 1:38:36 PM
[success] Total time: 0 s, completed Jul 23, 2024, 1:38:36 PM
[success] Total time: 20 s, completed Jul 23, 2024, 1:38:56 PM
[success] Total time: 0 s, completed Jul 23, 2024, 1:38:56 PM
[success] Total time: 20 s, completed Jul 23, 2024, 1:39:16 PM

Would it be possible for you to share a JFR profile of your internal benchmark run with the two different Graal versions? You can use the async profiler with sbt as follows:

sbt -J-agentpath:/path/to/async-profiler-3.0-linux-x64/lib/libasyncProfiler.so=start,event=cpu,file=profile.jfr --no-colors "clean;compiler/compile; ..."

If your compiler does not use sbt, you can add -agentpath:/path/to/async-profiler-3.0-linux-x64/lib/libasyncProfiler.so=start,event=cpu,file=profile.jfr to your JVM flags.

szeiger commented 4 months ago

Your results are unexpected. The first one or two runs being slower is normal due to the warmup, but there shouldn't be a big variance afterwards. I think a 2x difference between runs indicates some sort of problem of your benchmarking setup. Running our internal build with profiling should be possible. Do I add this parameter to the JVM doing the compilation, run the whole build, and then shut the JVM down?

c-refice commented 4 months ago

Do I add this parameter to the JVM doing the compilation, run the whole build, and then shut the JVM down?

Yes. Alternatively, if you have a long-running JVM process, you can attach and detach the profiler as specified in the async-profiler docs using the asprof command, provided you have the PID of the running JVM. In your case it would something look like this:

asprof -e cpu start <PID>

# run the whole build...

asprof -f profile.jfr stop <PID>
szeiger commented 4 months ago

@c-refice How do I make async-profiler not write anything to stdout (which is always a PITA with Java tooling)? We're compiling with a Bazel worker, so any additional output must go to stderr and never use stdin/stdout. I'm already setting -XX:+DisplayVMOutputToStderr and -Xlog:disable and I've also added loglevel=NONE to the asyncprofiler options but it still prints at least "Profiling started" to stdout.

szeiger commented 4 months ago

It looks like I can run asprof manually to avoid any output from the JVM. I'll do some test runs and collect the data, and then try to find a place to upload it. These logs are getting pretty big.

szeiger commented 4 months ago

I did 3 runs each on 17 and 21:

~/tmp/profile_17ee_1.jfr: Elapsed time: 559.912s, Critical Path: 516.60s *
~/tmp/profile_17ee_2.jfr: Elapsed time: 578.837s, Critical Path: 504.14s
~/tmp/profile_17ee_3.jfr: Elapsed time: 568.723s, Critical Path: 474.75s

~/tmp/profile_21ee_1.jfr: Elapsed time: 653.596s, Critical Path: 541.00s
~/tmp/profile_21ee_2.jfr: Elapsed time: 647.507s, Critical Path: 530.65s
~/tmp/profile_21ee_3.jfr: Elapsed time: 640.945s, Critical Path: 535.80s *

These are the profiles from the fastest run of each:

(I'm not sure how long these links will remain valid with our security infrastructure locking everything down and only allowing very short-term exceptions.)

c-refice commented 4 months ago

Thank you very much! I already downloaded them, and I'll take a look at them as soon as possible

c-refice commented 3 months ago

Unfortunately I was not able to make use of the Graal 17 profile data. Opening it in Java Mission Control results in an OOM exception, and converting it to a flamegraph doesn't produce usable results (though it does for the Graal 21 data, strangely).

I'll try to run some more benchmarks myself, but in the meantime here's a couple more things you could try:

szeiger commented 3 months ago

@c-refice I ran another set of benchmarks with a smaller build. The difference in build time is also comparatively smaller. Perhaps it doesn't affect all projects equally.

https://drive.google.com/file/d/1Smc_zclTADQhY0TYURnpFCtBtv45GuAF/view?usp=sharing contains 6 .jfr profiles and 6 .html flamegraphs from different builds. (I wasn't sure how to generate both in a single build)

The .jfr files:

17ee-1: (17:29:08) INFO: Elapsed time: 334.468s, Critical Path: 316.38s
17ee-2: (17:35:54) INFO: Elapsed time: 341.595s, Critical Path: 324.98s
17ee-3: (17:43:01) INFO: Elapsed time: 337.366s, Critical Path: 315.13s

21ee-1: (16:58:42) INFO: Elapsed time: 370.647s, Critical Path: 341.54s
21ee-2: (17:06:06) INFO: Elapsed time: 365.422s, Critical Path: 340.86s
21ee-3: (17:13:11) INFO: Elapsed time: 365.127s, Critical Path: 342.02s

And the flamegraphs:

17ee-1: (18:00:45) INFO: Elapsed time: 338.799s, Critical Path: 315.95s
17ee-2: (18:08:01) INFO: Elapsed time: 338.916s, Critical Path: 319.26s
17ee-3: (18:14:57) INFO: Elapsed time: 340.357s, Critical Path: 326.50s

21ee-1: (18:31:02) INFO: Elapsed time: 364.896s, Critical Path: 345.15s
21ee-2: (18:39:03) INFO: Elapsed time: 380.320s, Critical Path: 360.78s
21ee-3: (18:48:21) INFO: Elapsed time: 358.982s, Critical Path: 339.19s

(The link should be good for 8 hours again, then I'll have to reapprove it)

c-refice commented 3 months ago

Great, thank you for the effort!

(The link should be good for 8 hours again, then I'll have to reapprove it)

I wasn't able to download the link in time, could you re-authorize it?

szeiger commented 3 months ago

done