Skip to content
Snippets Groups Projects
  • dpsutton's avatar
    1f4bf25f
    Multi release jar again (#24366) · 1f4bf25f
    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>
    Multi release jar again (#24366)
    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>
Code owners
Assign users and groups as approvers for specific file changes. Learn more.