Skip to content
Snippets Groups Projects
user avatar
dpsutton authored
* Try multi-release true again in our manifest

Problem statement:
Luiz packs our partner jars (exasol, starburst, etc.) into our jar so
they can be "first class" and in cloud. But with the 44 cycle we've run
into some issues:

```shell
/tmp/j via :coffee: v17.30 on :cloud:  metabase-query
❯ jar uf 0.44.0-RC1.jar modules/*.jar

❯ java --version
openjdk 11.0.14.1 2022-02-08
OpenJDK Runtime Environment Temurin-11.0.14.1+1 (build 11.0.14.1+1)
OpenJDK 64-Bit Server VM Temurin-11.0.14.1+1 (build 11.0.14.1+1, mixed mode)

/tmp/j via :coffee: v11.0.14.1 on :cloud:  metabase-query
❯ jar uf 0.44.0-RC1.jar modules/*.jar
java.lang.module.InvalidModuleDescriptorException: Unsupported major.minor version 61.0
	at java.base/jdk.internal.module.ModuleInfo.invalidModuleDescriptor(ModuleInfo.java:1091)
	at java.base/jdk.internal.module.ModuleInfo.doRead(ModuleInfo.java:195)
	at java.base/jdk.internal.module.ModuleInfo.read(ModuleInfo.java:147)
	at java.base/java.lang.module.ModuleDescriptor.read(ModuleDescriptor.java:2553)
	at jdk.jartool/sun.tools.jar.Main.addExtendedModuleAttributes(Main.java:2083)
	at jdk.jartool/sun.tools.jar.Main.update(Main.java:1017)
	at jdk.jartool/sun.tools.jar.Main.run(Main.java:366)
	at jdk.jartool/sun.tools.jar.Main.main(Main.java:1680)

```

Diogo tracked this down with some great sleuthing to an upgrade in our
graal/js engine from “22.0.0.2” -> “22.1.0". This brought along the
transitive truffle jar (which is the actual engine powering the js
engine). The 22.0.0.2 was technically a multi-release jar but it only
included java 11 sources. The 22.1.0 added java 17 sources in addition
to the java 11.

And this proves fatal to using the `jar` command. When `"Multi-Release"`
is set to true, it knows to only look at versions it will need. Lacking
this, it looks at all of the classes and the class version for 17 is
61.0 is higher than it knows how to understand and it breaks.

Obvious Solution:
Set Multi-Release to true. We have done this in the past. On startup we
have a message logged:

> WARNING: sun.reflect.Reflection.getCallerClass is not supported. This
> will impact performance.

And setting multi-release can remove this. But when we did that we ended
up with:
- https://github.com/metabase/metabase/issues/16380
- https://github.com/metabase/metabase/pull/17027

That issue describes slowdowns of queries on the order of 0.6 seconds ->
1.3 seconds. Almost doubling. People reported dashboards timing
out. Jeff tracked this down to

> Profiling revealed that the calls to Log4jLoggerFactory.getLogger
> became much slower between the two versions. See attached screenshots.

And this is a pernicious problem that we cannot easily test for.

Lets try again:
I've set multi-release to true and built a jar with `bin/build`. I
immediately ran into problems:

```shell
❯ MB_DB_CONNECTION_URI="postgres://user:pass@localhost:5432/compare

" MB_JETTY_PORT=3007 java "$(socket-repl 6007)" -jar multi-release-local.jar
Warning: protocol #'java-time.core/Amount is overwriting function abs
WARNING: abs already refers to: #'clojure.core/abs in namespace: java-time.core, being replaced by: #'java-time.core/abs
WARNING: abs already refers to: #'clojure.core/abs in namespace: java-time, being replaced by: #'java-time/abs
Warning: environ value /Users/dan/.sdkman/candidates/java/current for key :java-home has been overwritten with /Users/dan/.sdkman/candidates/java/17.0.1-zulu/zulu-17.jdk/Contents/Home
Exception in thread "main" java.lang.Error: Circular loading of installed providers detected
	at java.base/java.nio.file.spi.FileSystemProvider.installedProviders(FileSystemProvider.java:198)
	at java.base/java.nio.file.Path.of(Path.java:206)
	at java.base/java.nio.file.Paths.get(Paths.java:98)
	at org.apache.logging.log4j.core.util.Source.toFile(Source.java:55)
	at org.apache.logging.log4j.core.util.Source.<init>(Source.java:142)
	at
        org.apache.logging.log4j.core.config.ConfigurationSource.<init>(ConfigurationSource.java:139)
```

So hazarded a guess that a bump in the log4j would solve this. And it
does solve it.

Then profiling some queries against bigquery (just viewing the table) in
the RC2 and the locally built version with the multi-release:

```shell
-- multi-release
2022-07-27 12:28:00,659 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: completed] 1.1 s
2022-07-27 12:28:02,609 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: completed] 897.9 ms
2022-07-27 12:28:03,950 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: completed] 778.1 ms

-- RC non-multi-release
2022-07-27 12:28:57,633 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: completed] 1.0 s
2022-07-27 12:28:59,343 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: completed] 912.9 ms
2022-07-27 12:29:02,328 DEBUG middleware.log :: POST /api/dataset 202 [ASYNC: completed] 808.6 ms
```
So times seem very similar.

============

Proper benching:

using criterium

```shell
MB_JETTY_PORT=3008 java "$(socket-repl 6008)" -cp "/Users/dan/.m2/repository/criterium/criterium/0.4.6/criterium-0.4.6.jar":0.39.2.jar metabase.core
```

`(bench (log/warn "benching"))`

Summary:
39.2:          21.109470 µs
RC2:           4.975204 µs
multi-release: 7.673965 µs

These flood the consoles with logs

```
Older release: 39.2

user=> (bench (log/warn "benching"))
Evaluation count : 2886240 in 60 samples of 48104 calls.
             Execution time mean : 21.109470 µs
    Execution time std-deviation : 567.271917 ns
   Execution time lower quantile : 20.171870 µs ( 2.5%)
   Execution time upper quantile : 22.429557 µs (97.5%)
                   Overhead used : 6.835913 ns

Found 5 outliers in 60 samples (8.3333 %)
	low-severe	 4 (6.6667 %)
	low-mild	 1 (1.6667 %)
 Variance from outliers : 14.1886 % Variance is moderately inflated by outliers

=============================================

RC2:

user=> (bench (log/warn "benching"))Evaluation count : 12396420 in 60 samples of 206607 calls.
             Execution time mean : 4.975204 µs
    Execution time std-deviation : 521.769687 ns
   Execution time lower quantile : 4.711607 µs ( 2.5%)
   Execution time upper quantile : 6.404317 µs (97.5%)
                   Overhead used : 6.837290 ns

Found 5 outliers in 60 samples (8.3333 %)
	low-severe	 2 (3.3333 %)
	low-mild	 3 (5.0000 %)
 Variance from outliers : 72.0600 % Variance is severely inflated by outliers

=============================================

Proposed Multi-Release

user=> (bench (log/warn "benching"))
Evaluation count : 7551000 in 60 samples of 125850 calls.
             Execution time mean : 7.673965 µs
    Execution time std-deviation : 201.155749 ns
   Execution time lower quantile : 7.414837 µs ( 2.5%)
   Execution time upper quantile : 8.138010 µs (97.5%)
                   Overhead used : 6.843981 ns

Found 1 outliers in 60 samples (1.6667 %)
	low-severe	 1 (1.6667 %)
 Variance from outliers : 14.1472 % Variance is moderately inflated by outliers

```

`(bench (log/info "benching info"))`

This does not hit a console so is a no-op.

Summary:
39.2:          11.534614 µs
RC2:           98.408357 ns
multi-release: 2.236756 µs

```
=============================================
39.2:

user=> (bench (log/info "benching info"))
Evaluation count : 5223480 in 60 samples of 87058 calls.
             Execution time mean : 11.534614 µs
    Execution time std-deviation : 57.756163 ns
   Execution time lower quantile : 11.461502 µs ( 2.5%)
   Execution time upper quantile : 11.657644 µs (97.5%)
                   Overhead used : 6.835913 ns

Found 3 outliers in 60 samples (5.0000 %)
	low-severe	 2 (3.3333 %)
	low-mild	 1 (1.6667 %)
 Variance from outliers : 1.6389 % Variance is slightly inflated by outliers

=============================================

RC2:

user=> (bench (log/info "benching info"))Evaluation count : 574427220 in 60 samples of 9573787 calls.
             Execution time mean : 98.408357 ns
    pExecution time std-deviation : 1.792214 ns
   Execution time lower quantile : 96.891477 ns ( 2.5%)
   Execution time upper quantile : 103.394664 ns (97.5%)
                   Overhead used : 6.837290 ns

Found 8 outliers in 60 samples (13.3333 %)
	low-severe	 3 (5.0000 %)
	low-mild	 5 (8.3333 %)
 Variance from outliers : 7.7881 % Variance is slightly inflated by outliers

=============================================

Multi-release:

user=> (bench (log/info "benching info"))Evaluation count : 26477700 in 60 samples of 441295 calls.
             Execution time mean : 2.236756 µs
    Execution time std-deviation : 15.412356 ns
   Execution time lower quantile : 2.212301 µs ( 2.5%)
   Execution time upper quantile : 2.275434 µs (97.5%)
                   Overhead used : 6.843981 ns

Found 3 outliers in 60 samples (5.0000 %)
	low-severe	 3 (5.0000 %)
 Variance from outliers : 1.6389 % Variance is slightly inflated by outliers
 ```

* bump graal/js

* Custom MB log factory (#24369)

* Custom MB log factory

* Write stupid code to appease stupid Eastwood

* `ns-name` already calls `the-ns` on its argument.

* More code cleanup

* Improved code

* Remove NOCOMMIT

* empty commit to trigger CI

Co-authored-by: default avatarCam Saul <1455846+camsaul@users.noreply.github.com>
1f4bf25f
History
Code owners
Assign users and groups as approvers for specific file changes. Learn more.
Name Last commit Last update
..
metabase