Fork me on GitHub
#clojure
<
2023-11-25
>
roklenarcic17:11:49

I have an app where the core namespace (that require s all the other stuff) takes 10-15secs to load. Is there some way to easily see where that time is going, which namespaces/dependencies take how long to load?

p-himik17:11:44

It's been discussed before, e.g. https://clojurians.slack.com/archives/C03S1KBA2/p1696923668147539 Tl;dr: a regular profiler should be enough.

jumar19:11:30

(_require …. :verbose)_ is a good first step

jpmonettas19:11:44

clj-async profiler 1.1.0 includes a startup profiler https://clojure-goes-fast.com/blog/clj-async-profiler-110/ that I think spawned after the conversation p-himik is linking

☝️ 2
oyakushev20:11:50

Yes, exactly what @U0739PUFQ has said! @U66G3SGP5 feel free to ask if you have any troubles with it.

ghadi20:11:05

It’s unclear if OP was loading fresh or has AOT compiled

p-himik20:11:19

Why does it matter? Wouldn't it be visible when profiling?

1
ghadi20:11:09

It matters because one approach is just loading precompiled bytecode, the other is compiling and also loading

ghadi20:11:24

The first is vastly faster

p-himik20:11:26

Yeah, but profiling will show what the issue is either way.

ghadi20:11:49

Logic is faster than experimentation

🧡 3
ghadi20:11:07

(^ a favorite Rich quote)

p-himik20:11:53

“The true method of knowledge is experiment.” :D

oyakushev20:11:38

Here's another one: "Read -> eval -> print -v ^---------loop----------|"

pesterhazy12:11:57

I didn't find profiling useful for this. Patching the compiler to output timing was more helpful

pesterhazy12:11:08

Agree with @U050ECB92 that AOT'ing is one of the first things to look at as it's pretty easy

pesterhazy12:11:18

Other than that I didn't find any magic bullet other than reducing the number of dependencies, which of course can be expensive to implement

pesterhazy12:11:17

Mostly in my experience reducing startup time means doing less (unnecessary) work

pesterhazy12:11:48

Oh and getting an arm mac :-)

Ben Sless12:11:16

How would you know which experiment to run and what to measure without application of a priori logic?

p-himik12:11:05

> I didn't find profiling useful for this. Have you tried following the article linked above? To make things certain, I just tried it on one of my projects. I find it rather clear, e.g. in the case of that specific project the worst third-party offender is aleph.http. I didn't have to modify the compiler to be able to see that. > How would you know which experiment to run and what to measure without application of a priori logic? We're interested in namespace loading time, so need to measure that. The experiment must be something that measures that time. Profiling suits just fine.

p-himik12:11:52

@U06PNK4HG The article makes a bit of a jump at the end from the call to (prof/generate-flamegraph ...) to viewing the HTML. I think it would help to make this step a bit more explicit, maybe even with opening the HTML file automatically in the default browser.

oyakushev13:11:12

Good point. It assumes that the user has already read the pages before this one. I'll update the doc.

roklenarcic09:11:39

Yeah I did read that page about startup profiling, but the flamegraph at the end contains no information about namespaces and which take what amount of time, so I didn’t bother with it

oyakushev09:11:52

It does contain the information about namespaces. You have to look for frames that look like my,namespace__init.<clinit> (e.g., clojure.core__init.<clinit> ). That marks the entrypoint to the loading of the namespace. And the width (or percentage) gives the time distribution. If you know the total load time, then it's trivial to calculate the load time of a particular namespace, if you need that.

Ben Sless09:11:03

Another option is to use JFR (Java Flight Recorder) to just record what happens during start up, then you get a synchronous view of what threads are doing

p-himik09:11:19

No clue how hard implementing something like this would be, but maybe useful to have an extra viewing mode that's focused specifically on loading times and hierarchies. Probably quite a task on its own, given that in my mind it also helps the user understand that if A depends on B then removing that B won't improve the total loading time because B is also a dependency of C, and so on.

Ingy döt Net18:11:16

Does anyone have a reliable way of checking if there is data available on stdin?

Ingy döt Net19:11:55

This kinda works:

(defn stdin-ready? []
  (let [chan (chan)]
    (go (>! chan (. ^LineNumberingPushbackReader *in* read)))
    (when-let [char (alt!!
                      (timeout 500) nil
                      chan ([char] (when-not (< char 0) char)))]
      (. *in* (unread char))
      true)))

Ingy döt Net19:11:31

But I get this warning

Reflection warning, yamlscript/cli.clj:65:7 - call to method unread can't be resolved (target class is unknown).
which is on the line
(. *in* (unread char))

Ingy döt Net19:11:23

and when I change it to

(. ^LineNumberingPushbackReader *in* (unread char))
I get this warning:
Reflection warning, yamlscript/cli.clj:65:7 - call to method unread on clojure.lang.LineNumberingPushbackReader can't be resolved (argument types: java.lang.Object).

Ingy döt Net19:11:36

but both seem to work

Ingy döt Net19:11:09

However when I compile to native with graalvm I get

Exception in thread "main" java.lang.IllegalArgumentException: No matching method unread found taking 1 args for class clojure.lang.LineNumberingPushbackReader
        at clojure.lang.Reflector.invokeMatchingMethod(Reflector.java:127)
        at clojure.lang.Reflector.invokeInstanceMethod(Reflector.java:102)
        at yamlscript.cli$stdin_ready_QMARK_.invokeStatic(cli.clj:65)
        at yamlscript.cli$get_code.invokeStatic(cli.clj:187)
        at yamlscript.cli$do_compile.invokeStatic(cli.clj:252)
        at yamlscript.cli$_main.invokeStatic(cli.clj:386)
        at yamlscript.cli$_main.doInvoke(cli.clj:358)
        at clojure.lang.RestFn.applyTo(RestFn.java:137)
        at yamlscript.cli.main(Unknown Source)
        at [email protected]/java.lang.invoke.LambdaForm$DMH/sa346b79c.invokeStaticInit(LambdaForm$DMH)

Ingy döt Net19:11:47

@U04V15CAJ do you have any insight here?

Ingy döt Net19:11:52

fwiw I do have this in my reflection.json (used in call to native-image:

{
    "name":"clojure.lang.LineNumberingPushbackReader",
    "allPublicMethods":true,
    "allPublicFields": true,
    "allPublicConstructors": true
  },

Bob B19:11:38

I'm no expert, but it might need a type hint of int since it's a primitive (if the reflective lookup is happening for Object, that presumably won't be found)

Bob B19:11:38

alternatively, java Readers have a ready method that might serve for the original question

Ingy döt Net19:11:38

I'll try it, thanks

Ingy döt Net19:11:43

That also where I stole my (since modified) code from...

Ingy döt Net19:11:41

@U013JFLRFS8 the ^Long annotation got rid of the warnings!

Ingy döt Net19:11:54

graaling it now...

Ingy döt Net19:11:20

I'd cross my fingers but graal takes so damn long I'd get hand cramps

Ingy döt Net19:11:32

@U013JFLRFS8 It worked! You are my hero!!

Ingy döt Net19:11:00

I wasted almost 2 hours 😞

Ingy döt Net19:11:21

(defn stdin-ready? []
  (let [chan (chan)]
    (go (>! chan (. ^LineNumberingPushbackReader *in* read)))
    (when-let [char (alt!!
                      (timeout 500) nil
                      chan ([char] (when-not (< char 0) char)))]
      (. ^LineNumberingPushbackReader *in* (unread ^Long char))
      true)))

Ingy döt Net19:11:10

@U013JFLRFS8 I owe you a crypto-beer! Thanks again...

👍 1
Ingy döt Net19:11:20

@U04V15CAJ my memory isn't as good as yours. sorry

Ingy döt Net19:11:58

@U04V15CAJ glad you mentioned it

(defn stdin-ready? []
  (.ready ^clojure.lang.LineNumberingPushbackReader *in*))
seems to work the same and mush simpler. Strangely there was no .ready in my code base. Not sure what happened to it from before.

👍 1
Ingy döt Net21:11:24

After more testing it turns out the simpler way falls prey to race conditions. This is probably why I abandoned that code in October...

borkdude21:11:16

Do you have an example of how that would go wrong?

Ingy döt Net21:11:10

yeah just a minute

borkdude21:11:23

I'll be back in 30 minutes or so

Ingy döt Net21:11:00

good. I have another issue that is in your wheelhouse 🙂

borkdude21:11:07

FWIW I've never used .ready in any of my projects, I think it's generally better to let users explicitly specify if your tool should read from stdin (since .ready and .available might also not be 100% accurate and give timing issues)

borkdude21:11:17

e.g. clj-kondo --lint -

Ingy döt Net21:11:59

So ys -Y reads ys from stdin and outputs yaml (which in a normal case is same as input):

$ echo 'a: b' | ys -Y | ys -Y | ys -Y
a: b
and with no input:
$ ys -Y
Warning: No input found.
with the .ready code
$ echo 'a: b' | ys -Y
a: b
but
$ echo 'a: b' | ys -Y | ys -Y | ys -Y
Warning: No input found.
Warning: No input found.

borkdude21:11:44

What happens if you straight up use (.ready System/in) without all the reader bs wrapped around it?

borkdude21:11:28

or rather (.available System/in)

borkdude21:11:48

yeah same issue:

$ echo 'a: b' | clj -M -e '(when-not (zero? (.available System/in)) (prn :hello))' | clj -M -e '(.available System/in)'
0

borkdude21:11:13

explicit flag may be better then?

Ingy döt Net21:11:36

there is an explicit flag and you get a warning if it can't find input. checking for stdin is common and nice to have in a lot of utils

Ingy döt Net21:11:44

$ echo 'a: b' | ys -Y - | ys -Y - | ys -Y -
a: b

borkdude21:11:08

hmm ok, I've never supported that use case (checking for missing stdin) and never got any complaints about it, I would consider this a low priority issue not worth spending hours on :)

Ingy döt Net21:11:51

(defn stdin-ready? []
  (let [chan (chan)]
    (go (>! chan (. ^LineNumberingPushbackReader *in* read)))
    (when-let [char (alt!!
                      (timeout 500) nil
                      chan ([char] (when-not (< char 0) char)))]
      (. ^LineNumberingPushbackReader *in* (unread ^Long char))
      true)))
works well so far but it also bloats the native-image by 7MB.

Ingy döt Net21:11:06

Can you happen to see why at a glance?

borkdude21:11:15

it bloats because you don't use core.async anywhere else maybe?

Ingy döt Net21:11:49

that's correct. does bb have a way to minimize that?

borkdude21:11:30

bb doesn't expose the go stuff. the go macro uses heavy machinery which might bloat your image

borkdude21:11:46

well, bb does expose go but not in the normal way

borkdude21:11:56

it has its own implementation of it based on virtual threads

Ingy döt Net21:11:12

would that work for this?

borkdude21:11:49

I think you can write the same stuff using normal java.util.concurrent stuff

borkdude21:11:55

without core.async

borkdude21:11:09

or perhaps promises even

Ingy döt Net21:11:57

I just pulled that code off stackoverflow. I'll have to understand it and change it, but good to know. Thanks

borkdude21:11:59

(let [ready (promise)]
  (future ;; check stream here, deliver to promise when ready)
  (Thread/sleep 500) (deliver nil))

borkdude21:11:01

something like this

🙌 1
Ingy döt Net02:11:15

@U04V15CAJ this is the best I could come up with so far

(defn stdin-ready? []
  (let [ready (promise)]
    (future
      (let [char (. ^LineNumberingPushbackReader *in* read)]
        (when (> char -1)
          (. ^LineNumberingPushbackReader *in* (unread char))
          (deliver ready true))))
    (future
      (Thread/sleep 1000)
      (deliver ready false))
    (let [result @ready]
      (shutdown-agents)
      result)))
and I get
$ time (echo 'a: b' | ys -Y)
a: b
real    0m1.035s
$ time (echo 'a: b' | ys -Y | ys -Y)
a: b
real    0m1.059s
$ time (echo 'a: b' | ys -Y | ys -Y | ys -Y)
Warning: No input found.
real    0m1.040s
Note they all take ~ 1.050s. Usually ys takes about 0.050s. So it's waiting the whole sleep 1000. Also worth noting the first one prints a: b immediately, the second after 1s and the third fails. Not sure how to stop the sleep. Your wisdom would be appreciated 🙂

borkdude08:11:40

@U05H8N9V0HZ :

(let [stdin (promise)]
  (future
    (deliver stdin (slurp *in*)))
  (future
    (Thread/sleep 1000)
    (deliver stdin false))
  (let [stdin @stdin]
    (shutdown-agents)
    (println "stdin:" stdin)))
$ time bb /tmp/stdin.clj <<< '1'
stdin: 1

bb /tmp/stdin.clj <<< '1'   0.02s  user 0.01s system 77% cpu 0.035 total

borkdude08:11:55

$ time bb /tmp/stdin.clj
stdin: false
bb /tmp/stdin.clj   0.02s  user 0.01s system 2% cpu 1.031 total

Ingy döt Net14:11:57

@U04V15CAJ

$ cat x.clj 
(defn get-stdin []
  (let [stdin (promise)]
    (future
      (deliver stdin (slurp *in*)))
    (future
      (Thread/sleep 1000)
      (deliver stdin false))
    (let [stdin @stdin]
      (shutdown-agents)
      stdin)))

(let [text (get-stdin)]
  (if text
    (print text)
    (binding [*out* *err*]
      (println "NO STDIN"))))
->
$ time (echo 123 | bb x.clj | bb x.clj | bb x.clj)
123

real    0m0.065s
$ time bb x.clj 
NO STDIN

real    0m1.116s
all good with bb but....

borkdude14:11:06

You need to use flush after print

Ingy döt Net14:11:53

$ time (echo 'a: b' | ys -Y)
a: b

real    0m1.076s
works but waits 1s
$ time (echo 'a: b' | ys -Y | ys -Y | ys -Y)
Warning: No input found.
Warning: No input found.

real    0m1.095s
doesn't work
$ time (ys -Y)
Warning: No input found.
^C
hangs indefinitely

Ingy döt Net14:11:15

I don't think shutdown-agent kills the Thread/sleep

Ingy döt Net14:11:20

Maybe bb is doing something extra to let that work?

borkdude14:11:00

You need both flush and shutdown-agents

Ingy döt Net14:11:54

I'm using that same function in the bb script above in my code. I added a (flush) after printing but no changes.

Ingy döt Net14:11:46

It works as expected running in bb (there's not even a flush there). I don't understand what kills the sleep when running under bb.

borkdude14:11:22

Bb already flushes for you at the end

Ingy döt Net14:11:18

ok, but what kills the sleep?

borkdude14:11:45

shutdown-agents I think?

Ingy döt Net14:11:21

Initiates a shutdown of the thread pools that back the agent
system. Running actions will complete, but no new actions will be
accepted

borkdude14:11:04

Try this in a single file JVM Clojure program and see what happens. I am afk right now but if you have such a repro I’ll try when I’m back

1
Ingy döt Net14:11:14

Try this:

$ cat x.clj 
(defn get-stdin []
  (let [stdin (promise)]
    (future
      (Thread/sleep 5000)
      (deliver stdin false))
    (future
      (deliver stdin (slurp *in*)))
    (let [stdin @stdin]
      (shutdown-agents)
      stdin)))

(let [text (get-stdin)]
  (if text
    (print text)
    (binding [*out* *err*]
      (println "NO STDIN"))))

(flush)
then (note the alias of bb to clj here)
$ alias bb='clj -M'
$ time (echo 123 | bb x.clj)
123

real    0m6.215s
$ time (echo 123 | bb x.clj | bb x.clj | bb x.clj)
NO STDIN
NO STDIN

real    0m7.933s

Ingy döt Net14:11:32

and

$ time (bb x.clj)
NO STDIN
...hangs...

borkdude15:11:01

@U05H8N9V0HZ It seems that with clj -X it does work, since -X, similar to bb, does some extra stuff:

(ns x)

(defn get-stdin []
  (let [stdin (promise)
        f1 (future
             (Thread/sleep 2000)
             (deliver stdin false))
        _f2 (future
             (deliver stdin (slurp *in*))
             (future-cancel f1))
        stdin @stdin]
    stdin))

(defn doit [_]
  (let [text (get-stdin)]
    (if text
      (do (print text)
          (flush))
      (binding [*out* *err*]
        (println "NO STDIN"))))
  (shutdown-agents))
clj -Sdeps '{:paths ["."]}' -X x/doit Don't remember exactly what it was, but I re-implemented it in bb.cli as well, let's have a look

borkdude15:11:16

I suspect this is because (promise) might also be spawning more futures or so

borkdude15:11:09

hmm probably the issue is that _f2 doesn't get cancelled so even when calling shutdown-agents the future is waited for (since it's not a daemon thread)

borkdude15:11:10

Yeah, here is a repro of that:

(def p (promise))
(def f1 (future (Thread/sleep 1000) (prn :ready) (deliver p true)))
(def f2 (future (prn :stdin (slurp *in*)) (deliver p true)))
(prn (future-cancel f1))
(prn (future-cancel f2))
(shutdown-agents)

borkdude15:11:46

@U05H8N9V0HZ This works in all cases:

(set! *warn-on-reflection* true)

(defn daemon-thread [^Runnable f]
  (.start (doto (new Thread f)
            (.setDaemon true))))

(defn get-stdin []
  (let [stdin (promise)]
    (daemon-thread #(do (Thread/sleep 1000)
                        (deliver stdin false)))
    (daemon-thread #(do (deliver stdin (slurp *in*))))
    @stdin))

(prn :stdin (get-stdin))

Ingy döt Net15:11:21

Thanks! I'll try it soon.

Ingy döt Net21:11:22

@U04V15CAJ works like a charm. good job!

👍 1