search

taoensso / timbre

Pure Clojure/Script logging library
https://www.taoensso.com/timbre
Eclipse Public License 1.0
1.45k stars 172 forks source link

GraalVM native image file size. #326

Closed ribelo closed 3 years ago

ribelo commented 4 years ago

Adding timbre to the dependency, causes the native image file to grow by approximately ~50mb.

ptaoussanis commented 3 years ago

Hi Rafał,

Could you please link to a minimal test project that demonstrates the issue? Will make it easier for me or someone else to confirm the problem and debug.

Thanks!

ericdallo commented 3 years ago

I had the same issue, I removed a lot of timbre unnecessary dependencies for my project with:

com.taoensso/timbre {:mvn/version "5.1.0" 
                     :exclusions [org.julienxx/clj-slack
                                  com.mchange/c3p0
                                  org.graylog2/gelfclient
                                  ymilky/franzy
                                  com.newrelic.agent.java/newrelic-agent
                                  cljs-node-io
                                  congomongo
                                  raven-clj]}

I didn't confirm image size was reduced yet

ericdallo commented 3 years ago

BTW this is my project: https://github.com/clojure-lsp/clojure-lsp/pull/267

@ribelo you can also use Graalvm Dashboard to monitor image size: https://www.graalvm.org/docs/tools/dashboard/?ojr=help%3Btopic%3Dgetting-started.md

ptaoussanis commented 3 years ago

@ericdallo Hi Eric,

Are you certain that any of the deps excluded there are otherwise actually included by default? They certainly shouldn't be. If they are, do you have any idea why that might be? I'm not too familiar with Graal.

Thanks,

ericdallo commented 3 years ago

I just checked that with lein deps :tree, then it showed me something like this:

[com.taoensso/timbre "5.1.0"]
   [cheshire "5.10.0"]
     [com.fasterxml.jackson.core/jackson-core "2.10.2"]
     [com.fasterxml.jackson.dataformat/jackson-dataformat-cbor "2.10.2"]
     [com.fasterxml.jackson.dataformat/jackson-dataformat-smile "2.10.2"]
     [tigris "0.1.2"]
   [cljs-node-io "1.1.2"]
     [org.clojure/clojurescript "1.10.339"]
       [com.google.javascript/closure-compiler-unshaded "v20180610"]
         [args4j "2.33"]
         [com.google.javascript/closure-compiler-externs "v20180610"]
         [com.google.jsinterop/jsinterop-annotations "1.0.0"]
         [com.google.protobuf/protobuf-java "3.0.2"]
       [org.clojure/google-closure-library "0.0-20170809-b9c14c6b"]
         [org.clojure/google-closure-library-third-party "0.0-20170809-b9c14c6b"]
       [org.mozilla/rhino "1.7R5"]
   [com.mchange/c3p0 "0.9.5.5"]
     [com.mchange/mchange-commons-java "0.2.19"]
   [com.newrelic.agent.java/newrelic-agent "3.30.0"]
   [com.taoensso/encore "3.9.2"]
     [com.taoensso/truss "1.6.0"]
   [congomongo "2.2.1"]
     [org.mongodb/mongo-java-driver "3.10.2"]
   [io.aviso/pretty "0.1.37"]
   [irclj "0.5.0-alpha4"]
   [net.java.dev.jna/jna "5.6.0"]
   [org.clojure/java.jdbc "0.7.11"]
   [org.graylog2/gelfclient "1.5.0" :exclusions [[com.fasterxml.jackson.core/jackson-core]]]
     [io.netty/netty-handler "4.1.42.Final"]
       [io.netty/netty-buffer "4.1.42.Final"]
       [io.netty/netty-codec "4.1.42.Final"]
       [io.netty/netty-common "4.1.42.Final"]
       [io.netty/netty-transport "4.1.42.Final"]
         [io.netty/netty-resolver "4.1.42.Final"]
     [org.slf4j/slf4j-api "1.7.25"]
   [org.julienxx/clj-slack "0.6.3"]
     [clj-http "2.0.0"]
       [commons-io "2.4" :exclusions [[org.clojure/clojure]]]
       [org.apache.httpcomponents/httpclient "4.5" :exclusions [[org.clojure/clojure]]]
         [commons-logging "1.2"]
       [org.apache.httpcomponents/httpcore "4.4.1" :exclusions [[org.clojure/clojure]]]
       [org.apache.httpcomponents/httpmime "4.5" :exclusions [[org.clojure/clojure]]]
   [org.zeromq/cljzmq "0.1.4"]
     [org.zeromq/jzmq "3.0.1"]
   [raven-clj "1.6.0"]
     [org.martinklepsch/clj-http-lite "0.4.1"]
     [prone "1.0.1"]
   [server-socket "1.0.0"]
   [ymilky/franzy "0.0.1"]
     [org.apache.kafka/kafka-clients "0.9.0.1"]
       [net.jpountz.lz4/lz4 "1.2.0"]
       [org.xerial.snappy/snappy-java "1.1.1.7"]
     [ymilky/franzy-common "0.0.1"]

So is not related to graal, not sure why it's adding that jars thought

ericdallo commented 3 years ago

Is there any chance that it's including these libs from here?

ericdallo commented 3 years ago

I'm just adding this to my deps.edn: com.taoensso/timbre {:mvn/version "5.1.0"}

ptaoussanis commented 3 years ago

@ericdallo

Where are you running lein deps :tree?

lein deps :tree will by default run under the :default profile, which includes :dev dependencies. If you run this from the Timbre dir, you'll see all this other stuff pulled in.

In other words: it's normal for lein deps :tree in Timbre's dir to show all that stuff, but none of it should be transitively pulled in to a project which depends on Timbre.

:dev dependencies are only intended for development, your exclusions there shouldn't be necessary (and I suspect actually have no effect). You should be able to confirm by calling lein deps :tree from your own project's dir.

Does that make sense?

ericdallo commented 3 years ago

It makes sense, but I'm already running from my project root 🤔 Should I run something like lein with-profile :prod deps :tree?

ptaoussanis commented 3 years ago

It makes sense, but I'm already running from my project root 🤔

So just to triple check: you're running lein deps :tree in your project root (not Timbre's project root), and you're seeing the output you attached above?

If so, I'm not sure offhand what could cause that- that's unexpected for me but I might be missing something obvious. Could you please add [lein-pprint "1.3.2"] to your :plugins then run lein pprint > pprinted and copy the contents here or email me / share a secret gist?

Important: please check pprinted for any sensitive info first - it could contain Clojars passwords, etc.

ericdallo commented 3 years ago

So just to triple check: you're running lein deps :tree in your project root (not Timbre's project root), and you're seeing the output you attached above?

Yep

Result of pprinted 
{:description "Clojure sample",
 :compile-path "/home/greg/dev/clojure-sample/target/default/classes",
 :deploy-repositories
 [["clojars"
   {:url "https://repo.clojars.org/",
    :password :gpg,
    :username :gpg}]],
 :group "clojure-sample",
 :license
 {:name "EPL-2.0 OR GPL-2.0-or-later WITH Classpath-exception-2.0",
  :url "https://www.eclipse.org/legal/epl-2.0/"},
 :resource-paths
 ("/home/greg/dev/clojure-sample/dev-resources"
  "/home/greg/dev/clojure-sample/resources"),
 :uberjar-merge-with
 {"META-INF/plexus/components.xml" leiningen.uberjar/components-merger,
  "data_readers.clj" leiningen.uberjar/clj-map-merger,
  #"META-INF/services/.*"
  [clojure.core/slurp
   (fn*
    [p1__7686__7688__auto__ p2__7687__7689__auto__]
    (clojure.core/str
     p1__7686__7688__auto__
     "\n"
     p2__7687__7689__auto__))
   clojure.core/spit]},
 :name "clojure-sample",
 :checkout-deps-shares
 [:source-paths
  :test-paths
  :resource-paths
  :compile-path
  #'leiningen.core.classpath/checkout-deps-paths],
 :source-paths ("/home/greg/dev/clojure-sample/src"),
 :eval-in :subprocess,
 :repositories
 [["central"
   {:url "https://repo1.maven.org/maven2/", :snapshots false}]
  ["clojars" {:url "https://repo.clojars.org/"}]],
 :test-paths ("/home/greg/dev/clojure-sample/test"),
 :target-path "/home/greg/dev/clojure-sample/target/default",
 :prep-tasks ["javac" "compile"],
 :java-source-paths ("/home/greg/dev/clojure-sample/src-java"),
 :native-path "/home/greg/dev/clojure-sample/target/default/native",
 :offline? false,
 :root "/home/greg/dev/clojure-sample",
 :javac-options ["-implicit:none"],
 :pedantic? ranges,
 :clean-targets [:target-path],
 :plugins ([lein-pprint/lein-pprint "1.3.2"]),
 :url "http://github/com/ericdallo/clojure-sample",
 :profiles
 {:uberjar
  {:aot [:all],
   :jvm-opts
   ["-server"
    "-Dclojure.compiler.direct-linking=true"
    "-Dclojure.spec.skip-macros=true"]},
  :native-image
  {:dependencies
   ([ericdallo/sqlite-jni-graal-fix "0.0.1-graalvm-20.2.0"]
    [org.graalvm.nativeimage/svm "20.2.0"])}},
 :plugin-repositories
 [["central"
   {:url "https://repo1.maven.org/maven2/", :snapshots false}]
  ["clojars" {:url "https://repo.clojars.org/"}]],
 :aliases
 {"downgrade" "upgrade", "jet" ["run" "-m" "jet.main" "--to-json"]},
 :version "0.1.0-SNAPSHOT",
 :jar-exclusions [#"^\." #"\Q/.\E"],
 :main clojure-sample.core,
 :global-vars {},
 :uberjar-exclusions [#"(?i)^META-INF/[^/]*\.(SF|RSA|DSA)$"],
 :jvm-opts
 ["-XX:-OmitStackTraceInFastThrow"
  "-XX:+TieredCompilation"
  "-XX:TieredStopAtLevel=1"],
 :dependencies
 ([org.clojure/data.json "1.0.0"]
  [org.clojure/clojure "1.10.2"]
  [nubank/matcher-combinators "3.1.2"]
  [org.eclipse.lsp4j/org.eclipse.lsp4j
   "0.10.0"
   :exclusions
   ([org.eclipse.xtend/org.eclipse.xtend.lib])]
  [digest/digest "1.4.10"]
  [cljfmt/cljfmt
   "0.7.0"
   :exclusions
   ([rewrite-cljs/rewrite-cljs] [rewrite-clj/rewrite-clj])]
  [rewrite-clj/rewrite-clj "0.6.1"]
  [org.eclipse.xtend/org.eclipse.xtend.lib
   "2.25.0.M1"
   :exclusions
   ([com.google.guava/guava])]
  [seancorfield/next.jdbc "1.1.613"]
  [com.google.guava/guava "30.1-jre"]
  [com.taoensso/timbre "5.1.0"]
  [prismatic/schema "1.1.12"]
  [org.clojure/tools.reader "1.3.4"]
  [nrepl/nrepl "0.8.3"]
  [org.xerial/sqlite-jdbc "3.34.0"]
  [org.clojure/core.async "1.3.610"]
  [clojure-complete/clojure-complete
   "0.2.5"
   :exclusions
   ([org.clojure/clojure])]
  [borkdude/jet "0.0.6"]),
 :release-tasks
 [["vcs" "assert-committed"]
  ["change" "version" "leiningen.release/bump-version" "release"]
  ["vcs" "commit"]
  ["vcs" "tag"]
  ["deploy"]
  ["change" "version" "leiningen.release/bump-version"]
  ["vcs" "commit"]
  ["vcs" "push"]],
 :test-selectors {:default (constantly true)}}

I can't see the extra deps there though

ptaoussanis commented 3 years ago

https://github.com/clojure-lsp/clojure-lsp/pull/267

@ericdallo This is your project, right?

You seem to be using a local version of Timbre (5.1.1-SNAPSHOT) there, but when I replace with 5.1.0 and remove your :exclusions and run lein deps :tree on my end, I see the following:

<...>
 [com.taoensso/timbre "5.1.0"]
   [com.taoensso/encore "3.4.0"]
     [com.taoensso/truss "1.6.0"]
   [io.aviso/pretty "0.1.37"]
<...>

Which is correct / as expected.

This with:

lein version
%> Leiningen 2.9.5 on Java 1.8.0_275 OpenJDK 64-Bit Server VM

I'd check your ~/.lein/profiles.clj or other implicit config to rule out the possibility that something is somehow interfering.

Only other thing I can think to add is that your project.clj config is quite unusual- though even if there'd be a problem there, it's not obvious why it wouldn't affect me when I try your project.

ericdallo commented 3 years ago

Actually, I was testing on https://github.com/ericdallo/clojure-sample, but thanks for the debugging :)

ptaoussanis commented 3 years ago

Actually, I was testing on https://github.com/ericdallo/clojure-sample, but thanks for the debugging :)

Just confirming that if I add com.taoensso/timbre {:mvn/version "5.1.0"} to the deps.edn there and run lein deps :tree, I get the same (correct, expected) response:

 [com.taoensso/timbre "5.1.0"]
   [com.taoensso/encore "3.4.0"]
     [com.taoensso/truss "1.6.0"]
   [io.aviso/pretty "0.1.37"]

Besides some sort of implicit config in your environment, or something wrong with your version of leiningen- I'm out of ideas on what could cause you to be pulling in transitive :dev dependencies.

I'll note that I'm not familiar with this leiningen + deps.edn approach, so could be I'm missing something obvious.

ericdallo commented 3 years ago

Hum, odd indeed, I use lein 2.9.5 and did exactly what you did, also I don't have any config on my ~/.lein/profiles.clj, anyway, thanks for the deubgging, I can say If I found anything :)

ptaoussanis commented 3 years ago

👍 BTW will check the spit-appender PR from you tomorrow.

ericdallo commented 3 years ago

Thank you! It's the only missing external dependency of https://github.com/clojure-lsp/clojure-lsp/pull/267

gsnewmark commented 3 years ago

All of the 3pa dependencies are included for me and my colleagues too. They only appear when we try to include Timbre 5.1.1 in our project, but none of these dependencies are included with the Timbre 5.0.1 or earlier. I'm using Leiningen 2.9.1 along with a regular project.clj.

ptaoussanis commented 3 years ago

@gsnewmark Hi Ivan!

All of the 3pa dependencies are included for me and my colleagues too. They only appear when we try to include Timbre 5.1.1 in our project,

Just to absolutely confirm: with Timbre v5.1.1 (so current version) - you're seeing all the 3pa dependencies pulled into your project when you run lein deps :tree in your own project?

Something quite unexpected is happening then, since the 3pa dependencies are literally commented out of :dev dependencies in v5.1.1.

I wonder if there could be an obscure issue with the keyword technically being invalid (starting with a "3"). Not obvious how that'd manifest in the observed problem, but will try check next I have a chance. Unfortunately still haven't been able to reproduce this problem myself.

gsnewmark commented 3 years ago

@ptaoussanis yep. Unfortunately the project is closed-source, so I can't share the exact project.clj file, but basically when we have [com.taoensso/timbre "5.0.1"] lein deps :tree run inside of our project returns the following snippet for the timbre:

 [com.taoensso/timbre "5.0.1"]
   [com.taoensso/encore "3.1.0"]
     [com.taoensso/truss "1.6.0"]
   [io.aviso/pretty "0.1.37"]

But when we update it to [com.taoensso/timbre "5.1.1"], lein deps :tree returns:

[com.taoensso/timbre "5.1.1"]
   [cljs-node-io "1.1.2"]
     [org.clojure/clojurescript "1.10.339"]
       [com.cognitect/transit-clj "0.8.309" :exclusions [[org.clojure/clojure]]]
         [com.cognitect/transit-java "0.8.332"]
           [org.msgpack/msgpack "0.6.12"]
             [com.googlecode.json-simple/json-simple "1.1.1" :exclusions [[junit]]]
             [org.javassist/javassist "3.18.1-GA"]
       [com.google.javascript/closure-compiler-unshaded "v20180610"]
         [args4j "2.33"]
         [com.google.code.gson/gson "2.7"]
         [com.google.javascript/closure-compiler-externs "v20180610"]
         [com.google.jsinterop/jsinterop-annotations "1.0.0"]
       [org.clojure/google-closure-library "0.0-20170809-b9c14c6b"]
         [org.clojure/google-closure-library-third-party "0.0-20170809-b9c14c6b"]
       [org.mozilla/rhino "1.7R5"]
   [com.mchange/c3p0 "0.9.5.5"]
     [com.mchange/mchange-commons-java "0.2.19"]
   [com.newrelic.agent.java/newrelic-agent "3.30.0"]
   [com.taoensso/encore "3.10.1"]
     [com.taoensso/truss "1.6.0"]
   [congomongo "2.2.1"]
     [org.mongodb/mongo-java-driver "3.10.2"]
   [io.aviso/pretty "0.1.37"]
   [irclj "0.5.0-alpha4"]
   [net.java.dev.jna/jna "5.6.0"]
   [org.clojure/java.jdbc "0.7.11"]
   [org.graylog2/gelfclient "1.5.0" :exclusions [[com.fasterxml.jackson.core/jackson-core]]]
   [org.julienxx/clj-slack "0.6.3"]
     [clj-http "2.0.0"]
       [org.apache.httpcomponents/httpmime "4.5" :exclusions [[org.clojure/clojure]]]
       [slingshot "0.12.2" :exclusions [[org.clojure/clojure]]]
     [org.clojure/data.json "0.2.5"]
   [org.zeromq/cljzmq "0.1.4"]
     [org.zeromq/jzmq "3.0.1"]
   [raven-clj "1.6.0"]
     [org.martinklepsch/clj-http-lite "0.4.1"]
     [prone "1.0.1"]
   [server-socket "1.0.0"]
   [ymilky/franzy "0.0.1"]
     [ymilky/franzy-common "0.0.1"]

This is reproduced for me (NixOS + Leiningen) and for at least two of my colleagues (one with NixOS, one with OS X).

Adding explicit exclusions helps:

[com.taoensso/timbre "5.1.1"
 :exclusions [irclj
              org.graylog2/gelfclient
              org.julienxx/clj-slack
              org.clojure/java.jdbc
              com.mchange/c3p0
              cheshire
              ymilky/franzy
              com.newrelic.agent.java/newrelic-agent
              net.java.dev.jna/jna
              raven-clj
              congomongo
              server-socket
              org.zeromq/cljzmq
              cljs-node-io]]

> lein deps :tree

[com.taoensso/timbre "5.1.1" :exclusions [[irclj] [org.graylog2/gelfclient] [org.julienxx/clj-slack] [org.clojure/java.jdbc] [com.mchange/c3p0] [cheshire] [ymilky/franzy] [com.newrelic.agent.java/newrelic-agent] [net.java.dev.jna/jna] [raven-clj] [congomongo] [server-socket] [org.zeromq/cljzmq] [cljs-node-io]]]
   [com.taoensso/encore "3.10.1"]
     [com.taoensso/truss "1.6.0"]
   [io.aviso/pretty "0.1.37"]

but frankly speaking I also don't understand what's causing such a drastic change in the transitive dependencies as at first glance none of the commits since the 5.0.1 could have caused this.

gsnewmark commented 3 years ago

:slightly_smiling_face: It looks like the dependencies are only included in the 5.1.1:

screenshot-2021-02-03T13-53-43

https://clojars.org/com.taoensso/timbre/versions/5.1.1

But none of them are present in the 5.1.0 (we skipped this one, so I wasn't sure about it before):

screenshot-2021-02-03T13-55-12

https://clojars.org/com.taoensso/timbre/versions/5.1.0

ptaoussanis commented 3 years ago

@gsnewmark Thanks for the detailed info Ivan!! The Clojars info is particularly helpful.

For some reason haven't been able to reproduce this locally, but if the problem shows up on Clojars - then I have a way to test changes.

Should have some time tomorrow or Fri to solve + cut a new release.

ericdallo commented 3 years ago

Oh, I knew it I was not that crazy :p Thanks for the help @gsnewmark

ptaoussanis commented 3 years ago

Investigating now. First results are very interesting: it looks like it's either something on my system causing the problem, or a problem with Lein or Clojars itself.

So clearly something outside of the code + project itself is causing :dev dependencies to be included in Clojars where they should not.

Will continue looking.

Update- things I've already ruled out:

ptaoussanis commented 3 years ago

Managed to create a minimum reproducible project.

With the following project.clj:

(defproject com.taoensso.tests/clojars-test "0.1.0-SNAPSHOT"
  :description "FIXME: write description"
  :url "http://example.com/FIXME"
  :license {:name "EPL-2.0 OR GPL-2.0-or-later WITH Classpath-exception-2.0"
            :url "https://www.eclipse.org/legal/epl-2.0/"}
  :dependencies [[org.clojure/clojure "1.10.1"]]
  :profiles
  {:ring {:dependencies [[ring "1.8.2"]]}
   :dev  [:ring]}

  :repl-options {:init-ns clojars-test.core})

lein deploy clojars pulls in Ring as a dependency: https://clojars.org/com.taoensso.tests/clojars-test with Leiningen 2.9.5 on Java 1.8.0_275 OpenJDK 64-Bit Server VM

ptaoussanis commented 3 years ago

Looks like a possible regression in leiningen: https://github.com/technomancy/leiningen/issues/2721

ptaoussanis commented 3 years ago

Okay, so good news: I've confirmed that if I downgrade to lein 2.9.1 then my deployments stop showing this problem. Will push an updated release of Timbre shortly.

There should be no need for any library users to downgrade their lein version. More info on #lein/2721.

Thanks again to everyone for the reports, assistance, and patience on this!

ericdallo commented 3 years ago

Thanks @ptaoussanis I could confirm that is an issue on lein, I have another lib that I deployed with lein deploy clojars that has the same issue