How do you diagnose the cause of slow (25min) app startup time?

Question

I run my clojure app on the server directly from a git repo with the clojure CLI. I'm struggling with a problem where it takes ~5-25 mins to startup in a virtual server and ~1 min on my laptop. During this time there's almost no CPU usage and little of the 4GB of RAM is used. I'm wondering if this is some kind of lock condition. It seems like it's probably related to a dep since I don't remember it doing this in the past. What are some ways to diagnose what's wrong?

$ time clojure -A:server -e "(require 'riverdb.server)"
WARNING: requiring-resolve already refers to: #'clojure.core/requiring-resolve in namespace: datomic.common, being replaced by: #'datomic.common/requiring-resolve
    
real	24m49.555s
user	1m58.976s
sys	0m3.672s

I tried the solution at https://clojure.org/guides/dev_startup_time, which I thought helped, but if I run it multiple times the delay varies widely:

$ time clojure -A:dev:server -e "(require 'riverdb.server)"

real	5m19.167s
user	0m29.084s
sys	0m1.724s

$ time clojure -A:dev:server -e "(require 'riverdb.server)"

real	19m53.558s
user	0m31.972s
sys	0m1.988s

Answer 1

Try (require 'riverdb.server :verbose)

Comments

This is a good suggestion if you can interactively watch the console to determine where the "slow" load is happening. Otherwise, it's probably just a list of ns'es, so not very helpful.

---

Oh this is a great option I didn't know about!  It's getting stuck on:
    (clojure.core/load "/buddy/core/keys/jwk/ec")

Downgrading buddy/buddy-core from 1.6 to 1.4 eliminated the problem.

There's an issue ticket here: https://github.com/funcool/buddy-core/issues/70

Buddy is "doing work" generating keys when the namespace is loaded, and that was draining the entropy on the virtual server, so a workaround was to call it like so:

time clojure -A:server -J-Djava.security.egd=file:/dev/urandom -e "(require 'riverdb.server :verbose)"

Answer 2

It's likely that something you are loading on startup has a top-level def that "does work", possibly network work that takes a long time to do in a virtual server environment. Doing top level defs that initialize database connections or things like that are generally an issue - either construct them in code or use delay to defer construction until use.

To debug what is having this issue, you need to get a stack trace. Generally with Java you can use jps and jstack to find and induce the jvm to produce a stack.

If you can't interactively look at it, you could add some top-level code in whatever you load to call (Thread/dumpStack). Or you can spin a background thread that does this in a loop (with Thread/sleep between).

Answer 3

Is there any output from the clojure command that you can examine, e.g. the kinds of output it generates when it is downloading dependencies from other servers, e.g. from Clojars.org or Maven central?

What is the output of clojure -Sdescribe on the systems where things are slow? This is a long shot guess, but there were some older versions of the clojure command that had some performance issues with certain kinds of dependencies.

Comments

That issue was with Java 8 (u202+), Java 11.0.2, and Clojure < 1.10.1, AND you are loading a user.clj. If you are not loading a user.clj file, then it's unlikely this is the issue.

---

$ clojure -Sdescribe
{:version "1.10.1.536"
 :config-files ["/usr/local/lib/clojure/deps.edn" "/home/riverdb/.clojure/deps.edn" "deps.edn" ]
 :config-user "/home/riverdb/.clojure/deps.edn"
 :config-project "deps.edn"
 :install-dir "/usr/local/lib/clojure"
 :config-dir "/home/riverdb/.clojure"
 :cache-dir ".cpcache"
 :force false
 :repro false
 :resolve-aliases ""
 :classpath-aliases ""
 :jvm-aliases ""
 :main-aliases ""
 :all-aliases ""}

$ java -version
openjdk version "11.0.7" 2020-04-14
OpenJDK Runtime Environment GraalVM CE 20.1.0 (build 11.0.7+10-jvmci-20.1-b02)
OpenJDK 64-Bit Server VM GraalVM CE 20.1.0 (build 11.0.7+10-jvmci-20.1-b02, mixed mode, sharing)