This page is not created by, affiliated with, or supported by Slack Technologies, Inc.
2022-03-12
Channels
- # babashka (37)
- # beginners (27)
- # biff (1)
- # calva (18)
- # cider (45)
- # clj-on-windows (5)
- # cljsrn (1)
- # clojure (90)
- # clojure-art (3)
- # clojure-uk (1)
- # clojurescript (7)
- # core-logic (4)
- # datomic (4)
- # events (2)
- # fulcro (3)
- # hyperfiddle (23)
- # leiningen (66)
- # malli (1)
- # meander (7)
- # nrepl (1)
- # off-topic (9)
- # pathom (1)
- # re-frame (15)
- # reitit (19)
- # remote-jobs (1)
- # shadow-cljs (103)
Hopefully this is the right place to ask: I have an issue with leiningen where it times out when I run lein repl
. It just waits the timeout period (set to 120000 in my project.clj), then says
Ctrl+\
while it's hanging, you'll get a thread dump so maybe you'll see a stacktrace of whatever your program is doing
@U45T93RA6 thanks, that did give me a stack trace (among other things) and it looks like maybe there's something going on with the ring handler, although I'm not sure. I will continue to investigate.
It could also be failing to fetch dependencies if you needed a vpn or something for a private repo
@U0LK1552A when I run DEBUG=true lein repl
, I get:
> Leiningen's classpath: :/usr/local/Cellar/leiningen/2.9.8/libexec/leiningen-2.9.8-standalone.jar
> Applying task repl to []
> Applying task javac to nil
> Running javac with [@/var/folders/xb/0v6prcw13331hhfyw8qskhqc0000gn/T/.leiningen-cmdline13237562225446695570.tmp]
> Applying task compile to nil
> All namespaces already AOT compiled.
> REPL server launch timed out.
I'm not totally sure what that means but I guess that's normal?
You could try getting stack as was mentioned. Or hook a cpu sampling profiler to the lein process while it is hanging to see where it is hanging/spending the time at for diagnosis
Thank you for your help, that is definitely new for me, but I will try it out
Ok. Yeah I don't have any simpler way unless there is just something common like this you can find via search. I've used the profiling method before to diagnose though
Async Profiler is good and relatively easy to use for cpu profiling. strace might give you dome details too
It's useful to check whether it's a problem for other lein-based projects on your machine and whether it works with this project somewhere else
@U06BE1L6T thank you I will check those out. Lein seems to be working normally outside of this project, so I suspect it's something wrong with my config or deps, but I'm not sure which yet
So I profiled lein repl
using async profiler as suggested, and I got this result:
Profiling for 60 seconds
Done
--- Execution profile ---
Total samples : 9
--- 30000000 ns (33.33%), 3 samples
[ 0] __psynch_cvwait
[ 1] os::PlatformMonitor::wait(long)
[ 2] Monitor::wait_without_safepoint_check(long long)
[ 3] G1ServiceThread::sleep_before_next_cycle()
[ 4] G1ServiceThread::run_service()
[ 5] ConcurrentGCThread::run()
[ 6] Thread::call_run()
[ 7] thread_native_entry(Thread*)
[ 8] _pthread_start
[ 9] thread_start
--- 20000000 ns (22.22%), 2 samples
[ 0] __psynch_cvwait
[ 1] os::PlatformMonitor::wait(long)
[ 2] Monitor::wait_without_safepoint_check(long long)
[ 3] WatcherThread::sleep() const
[ 4] WatcherThread::run()
[ 5] Thread::call_run()
[ 6] thread_native_entry(Thread*)
[ 7] _pthread_start
[ 8] thread_start
--- 20000000 ns (22.22%), 2 samples
[ 0] __psynch_cvwait
[ 1] os::PlatformMonitor::wait(long)
[ 2] Monitor::wait_without_safepoint_check(long long)
[ 3] VMThread::wait_for_operation()
[ 4] VMThread::loop()
[ 5] VMThread::run()
[ 6] Thread::call_run()
[ 7] thread_native_entry(Thread*)
[ 8] _pthread_start
[ 9] thread_start
--- 10000000 ns (11.11%), 1 sample
[ 0] __gettimeofday
[ 1] os::PlatformMonitor::wait(long)
[ 2] Monitor::wait_without_safepoint_check(long long)
[ 3] WatcherThread::sleep() const
[ 4] WatcherThread::run()
[ 5] Thread::call_run()
[ 6] thread_native_entry(Thread*)
[ 7] _pthread_start
[ 8] thread_start
--- 10000000 ns (11.11%), 1 sample
[ 0] __psynch_cvwait
[ 1] os::PlatformMonitor::wait(long)
[ 2] Monitor::wait_without_safepoint_check(long long)
[ 3] MonitorDeflationThread::monitor_deflation_thread_entry(JavaThread*, JavaThread*)
[ 4] JavaThread::thread_main_inner()
[ 5] JavaThread::run()
[ 6] Thread::call_run()
[ 7] thread_native_entry(Thread*)
[ 8] _pthread_start
[ 9] thread_start
ns percent samples top
---------- ------- ------- ---
80000000 88.89% 8 __psynch_cvwait
10000000 11.11% 1 __gettimeofday
It looks like it's spending most of its time waiting and about 11% on "gettimeofday"
Not sure what that means as far as my project is concerned
Those don't mean much without a mapping from namespaces (or Java packages) to class/method calls. I don't know much about async profiler but maybe it can give it to you. YourKit definitely can (although it might take some effort to properly run it for this specific task) In all honesty I think Ctrl+\ woud give you all info you need
Your kit is good. Visualvm is fine too. I think it comes built in with modern jdks even
For Async Profiler you want to create a flamegraph and look for the main thread (not sure what that means in terms of the lein repl
process(es)).
But yeah, if you capture stacktraces via kill -3, jcmd Thread.print
or some other means that's probably the most useful thing you can do.
I will try yourkit next
I've been overanalyzing the stack traces I get with ctrl+\ and I'm struggling to find an issue
I see my code but it looks like it's just loading it (all the lines numbers are 1)
And there doesn't seem to be an exception thrown
Here's what the top of the yourkit flamegraph shows
It looks like the highest function that's not completely generic is compiler.eval
It looks like it just hangs on compiler.eval
Not sure why that is
@U06BE1L6T of course, here they are: https://pastebin.com/dMjAB9u9
Does anything stand out that I might have missed?
I would say the most interesting one is the main
thread.
That one seems to be simply waiting the repl to start
Now, I don't know much details about leiningen internals,
but lein repl
typically launches two jvm processes.
So it might be helpful to gather stacktraces for the other process too.
I looked at the stack traces from the other process and it didn't have any of my code in it
clojure-agent-send-off-pool-0 Waiting CPU usage on sample: 0ms
jdk.internal.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:211)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:715)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1047)
java.util.concurrent.CountDownLatch.await(CountDownLatch.java:230)
clojure.core$promise$reify__8524.deref(core.clj:7111)
clojure.core$deref.invokeStatic(core.clj:2324)
clojure.core$deref.invoke(core.clj:2310)
nrepl.ack$wait_for_ack$fn__10144.invoke(ack.clj:28)
clojure.core$binding_conveyor_fn$fn__5772.invoke(core.clj:2034)
clojure.lang.AFn.call(AFn.java:18)
java.util.concurrent.FutureTask.run(FutureTask.java:264)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
java.lang.Thread.run(Thread.java:833)
clojure-agent-send-off-pool-1 Runnable CPU usage on sample: 0ms
sun.nio.ch.Net.accept(Native Method)
sun.nio.ch.NioSocketImpl.accept(NioSocketImpl.java:755)
java.net.ServerSocket.implAccept(ServerSocket.java:675)
java.net.ServerSocket.platformImplAccept(ServerSocket.java:641)
java.net.ServerSocket.implAccept(ServerSocket.java:617)
java.net.ServerSocket.implAccept(ServerSocket.java:574)
java.net.ServerSocket.accept(ServerSocket.java:532)
nrepl.server$accept_connection.invokeStatic(server.clj:53)
nrepl.server$accept_connection.invoke(server.clj:49)
nrepl.server$start_server$fn__11039.invoke(server.clj:176)
clojure.core$binding_conveyor_fn$fn__5772.invoke(core.clj:2034)
clojure.lang.AFn.call(AFn.java:18)
java.util.concurrent.FutureTask.run(FutureTask.java:264)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
java.lang.Thread.run(Thread.java:833)
clojure-agent-send-off-pool-2 Waiting CPU usage on sample: 0ms
jdk.internal.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:252)
java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:401)
java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:903)
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1061)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1122)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
java.lang.Thread.run(Thread.java:833)
ClosingPipeCloser 1449847400 Waiting CPU usage on sample: 0ms
java.lang.Object.wait(Native Method)
java.lang.Thread.join(Thread.java:1304)
java.lang.Thread.join(Thread.java:1372)
com.hypirion.io.Pipe.join(Pipe.java:120)
com.hypirion.io.ClosingPipe$OutCloser.run(ClosingPipe.java:111)
java.lang.Thread.run(Thread.java:833)
Common-Cleaner Waiting CPU usage on sample: 0ms
java.lang.Object.wait(Native Method)
java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:155)
jdk.internal.ref.CleanerImpl.run(CleanerImpl.java:140)
java.lang.Thread.run(Thread.java:833)
jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:162)
main Waiting CPU usage on sample: 0ms
jdk.internal.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:252)
java.util.concurrent.FutureTask.awaitDone(FutureTask.java:444)
java.util.concurrent.FutureTask.get(FutureTask.java:203)
clojure.core$deref_future.invokeStatic(core.clj:2306)
clojure.core$future_call$reify__8477.deref(core.clj:6976)
clojure.core$deref.invokeStatic(core.clj:2328)
clojure.core$deref.invoke(core.clj:2310)
nrepl.ack$wait_for_ack.invokeStatic(ack.clj:29)
nrepl.ack$wait_for_ack.invoke(ack.clj:15)
leiningen.repl$server.invokeStatic(repl.clj:309)
leiningen.repl$server.invoke(repl.clj:287)
leiningen.repl$repl.invokeStatic(repl.clj:410)
leiningen.repl$repl.doInvoke(repl.clj:337)
clojure.lang.RestFn.invoke(RestFn.java:425)
leiningen.repl$repl.invokeStatic(repl.clj:395)
leiningen.repl$repl.invoke(repl.clj:337)
clojure.lang.AFn.applyToHelper(AFn.java:154)
clojure.lang.RestFn.applyTo(RestFn.java:132)
clojure.lang.Var.applyTo(Var.java:705)
clojure.core$apply.invokeStatic(core.clj:669)
clojure.core$apply.invoke(core.clj:662)
leiningen.core.main$partial_task$fn__7340.doInvoke(main.clj:284)
clojure.lang.RestFn.invoke(RestFn.java:410)
clojure.lang.AFn.applyToHelper(AFn.java:154)
clojure.lang.RestFn.applyTo(RestFn.java:132)
clojure.lang.AFunction$1.doInvoke(AFunction.java:31)
clojure.lang.RestFn.applyTo(RestFn.java:137)
clojure.core$apply.invokeStatic(core.clj:669)
clojure.core$apply.invoke(core.clj:662)
leiningen.core.main$apply_task.invokeStatic(main.clj:334)
leiningen.core.main$apply_task.invoke(main.clj:320)
leiningen.core.main$resolve_and_apply.invokeStatic(main.clj:343)
leiningen.core.main$resolve_and_apply.invoke(main.clj:336)
leiningen.core.main$_main$fn__7429.invoke(main.clj:453)
leiningen.core.main$_main.invokeStatic(main.clj:442)
leiningen.core.main$_main.doInvoke(main.clj:439)
clojure.lang.RestFn.applyTo(RestFn.java:137)
clojure.lang.Var.applyTo(Var.java:705)
clojure.core$apply.invokeStatic(core.clj:667)
clojure.main$main_opt.invokeStatic(main.clj:514)
clojure.main$main_opt.invoke(main.clj:510)
clojure.main$main.invokeStatic(main.clj:664)
clojure.main$main.doInvoke(main.clj:616)
clojure.lang.RestFn.applyTo(RestFn.java:137)
clojure.lang.Var.applyTo(Var.java:705)
clojure.main.main(main.java:40)
Notification Thread Runnable CPU usage on sample: 0ms
Stack trace is not available
PipeThread 1449847400 Waiting CPU usage on sample: 0ms
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:338)
com.hypirion.io.Pipe$PipeOutputStream.run(Pipe.java:235)
java.lang.Thread.run(Thread.java:833)
PipeThread 1498588749 Runnable CPU usage on sample: 0ms
java.io.FileInputStream.readBytes(Native Method)
java.io.FileInputStream.read(FileInputStream.java:276)
java.io.BufferedInputStream.fill(BufferedInputStream.java:244)
java.io.BufferedInputStream.read1(BufferedInputStream.java:284)
java.io.BufferedInputStream.read(BufferedInputStream.java:343)
java.io.FilterInputStream.read(FilterInputStream.java:106)
com.hypirion.io.Pipe$PipeOutputStream.run(Pipe.java:239)
java.lang.Thread.run(Thread.java:833)
PipeThread 618181595 Runnable CPU usage on sample: 0ms
java.io.FileInputStream.readBytes(Native Method)
java.io.FileInputStream.read(FileInputStream.java:276)
java.io.BufferedInputStream.fill(BufferedInputStream.java:244)
java.io.BufferedInputStream.read1(BufferedInputStream.java:284)
java.io.BufferedInputStream.read(BufferedInputStream.java:343)
java.io.FilterInputStream.read(FilterInputStream.java:106)
com.hypirion.io.Pipe$PipeOutputStream.run(Pipe.java:239)
java.lang.Thread.run(Thread.java:833)
Thread-2 Waiting CPU usage on sample: 0ms
java.lang.Object.wait(Native Method)
java.lang.Thread.join(Thread.java:1304)
java.lang.Thread.join(Thread.java:1372)
com.hypirion.io.Pipe.join(Pipe.java:120)
leiningen.core.eval$sh.invokeStatic(eval.clj:191)
leiningen.core.eval$sh.doInvoke(eval.clj:173)
clojure.lang.RestFn.applyTo(RestFn.java:137)
clojure.core$apply.invokeStatic(core.clj:667)
clojure.core$apply.invoke(core.clj:662)
leiningen.core.eval$fn__7103.invokeStatic(eval.clj:263)
leiningen.core.eval$fn__7103.invoke(eval.clj:261)
clojure.lang.MultiFn.invoke(MultiFn.java:234)
leiningen.core.eval$eval_in_project.invokeStatic(eval.clj:368)
leiningen.core.eval$eval_in_project.invoke(eval.clj:358)
leiningen.repl$server$fn__11198.invoke(repl.clj:300)
clojure.lang.AFn.applyToHelper(AFn.java:152)
clojure.lang.AFn.applyTo(AFn.java:144)
clojure.core$apply.invokeStatic(core.clj:667)
clojure.core$with_bindings_STAR_.invokeStatic(core.clj:1977)
clojure.core$with_bindings_STAR_.doInvoke(core.clj:1977)
clojure.lang.RestFn.invoke(RestFn.java:425)
clojure.lang.AFn.applyToHelper(AFn.java:156)
clojure.lang.RestFn.applyTo(RestFn.java:132)
clojure.core$apply.invokeStatic(core.clj:671)
clojure.core$bound_fn_STAR_$fn__5767.doInvoke(core.clj:2007)
clojure.lang.RestFn.invoke(RestFn.java:397)
clojure.lang.AFn.run(AFn.java:22)
java.lang.Thread.run(Thread.java:833)
It looks fairly generic
At this point, I'm considering moving my project to something non-leiningen like kit
And just moving source files over one by one
I think that actually might take less time than diagnosing this issue
Leiningen generally works very nicely. Fixing this might be pretty enlightening
I'd try to bisect the issue by removing stuff:
• :repl-options
• any Lein plugins
• dev/
dir if any
btw 120000 is 2 minutes which is not a lot for work projects! Clojure projects scale linearly in terms of compilation size. I've had many work projects that load in the 5-8 minute range. So you can increase it to 10m for good measure
Yeah. Good point to see if something is just taking a long time. Then try to figure out why it's so slow once you know it does start
I also agree lein usually works well and I'd say it's rare to see this sort of issue.
Also one thing I've often done when stuck enough is to actually clone leiningen repo and launch an repl against the lein version tag you are using.
You can then do repl driven debugging within lein which lets you add things like println or whatever.
Lastly I id still prefer hot spots from a profiler shared. I can't parse these thread dumbs that well.
Visualvm > cpu sampler > take snapshot. Then you can view and export the snapshot as an nps file. I like the hot spot filter that typically falls out key function names
@U036TENRD3L
vemv and mikerod had a good point: sometimes, 2 minutes isn't enough - especially if that's the first time you are running lein repl
.
Maybe try lein deps
first too.
About the CPU proflie: it could be interesting but also misleading. It depends on where the process is stuck (or if it's just really taking too much time to load the code).
About the stacktrace: it seems to me that you just reposted the stacktrace for pastebin.
That's I believe the very first process the lein starts, not the process loading your code in the repl.
I've tried to start the repl and the stacktrace was changing quite a bit but looked something like this:
Thanks so much for your help guys
I tried commenting out things in my project.clj and interestingly, there was one thing that got lein to boot when it was gone: the dev dependency ring/ring-devel
Of course when lein booted, it just shows a stack trace because I think the project needs that to work
I'm not sure if this is the culprit, or if ring-devel loads so early that it causes a crash before the hang has a chance to happen
> Visualvm > cpu sampler > take snapshot. Then you can view and export the snapshot as an nps file. I like the hot spot filter that typically falls out key function names
I tried this but the jvisualvm
command isn't working on my jvm, I will investigate further
@U06BE1L6T I think that's what mine looks like too, it didn't have any project code so I figure it wasn't relevant. I did paste it above though
So I don't think the ring-devel dep was really it. When I removed all references to it in the project so it would build, lein ended up hanging again anyway
So I think that just caused something earlier in the process to fail, but it didn't fix the issue
That's strange. It might be some weird code loading issue. What if you keep the dependency there but don't require it anywhere in your code? You can also try to enable verbose ns loading to narrow it.
;; alternatively, you can add :verbose to require statements.
(alter-var-root #'clojure.core/*loading-verbosely* (constantly true))
@U06BE1L6T Just tried that, it does the same thing unfortunately
I think that loading seems to happen before whatever causes the hang
@U036TENRD3L did you find what was the problem?
"REPL server launch timed out."
This does not happen anywhere besides in my project
A few questions: • Is there a way to figure out what the issue is? Maybe a verbose option or something? • Are there common issues I should look at when this sort of thing happens?