Profile across namespaces about timbre HOT 10 CLOSED

Hi Martin,

Should work! I'd double check your log level and that the top form you're calling is wrapped with profile (profiling only kicks in when the relevant thread-local binding is in place).

Does that help?

from timbre.

Hm, I'm not setting a log level and it seems that this means there is no minimum.

(profile :info :read-file (dorun (map read-file (take 4 files))))

I'm starting a profiling like this. read-file is defined with defnp and calls a function parse (defined in a different namespace) further down the call stack that is also defined with defnp.

It shows only the profiling for the read-file fn and omits the other fn defined using defnp.
I assumed both would show up:

2014-May-14 13:20:49 +0200 superdings.local INFO [patalyze.core] - Profiling: :patalyze.core/read-file
                      Id      nCalls       Min        Max       MAD      Mean   Time% Time
:patalyze.core/read-file           4   405.0ms    856.0ms   145.0ms   565.0ms     100 2.3s
              Clock Time                                                          100 2.3s
          Accounted Time                                                          100 2.3s

from timbre.

(profile :info :read-file (dorun (map read-file (take 4 files))))

So (just to confirm): this instructs Timbre to only profile when you're running at a logging level >= :info. The p calls don't get a level, only the outer profile call.

It shows only the profiling for the read-file fn and omits the other fn defined using defnp.
I assumed both would show up

Hmm, both should show up. Things I'd check:

• Confirm that the new defnp definition is actually in place. If you're working at the REPL, it's sometimes for the var state to get confused.
• Confirm that your Timbre config's :ns-whitelist and :ns-blacklist settings are disabled ([]).
• Confirm that your Timbre config's :middleware is disabled ([]) or otherwise not interfering.

What happens when you call (profile :trace :parse <a parse call>) from the same ns?

from timbre.

So (just to confirm): this instructs Timbre to only profile when you're running at a logging level >= :info.

Yes, thats how I understood it as well. The Profiling call turns up in the logs as well so I actually think the log level is probably ok.

I restarted the repl to make sure the defnp is in place.
All the keys you mentioned are set to [].

(profile :trace :parse (dorun (map parser/parse list-of-xml-snippets)))

doesn't print anything to the logs. If I set the call to (profile :info ... ) it properly logs the profiling of my parse function.

Interestingly running the parse takes significantly longer than running read-file (which does more than parse). So I'm now thinking that I might be using dorun incorrectly or that things are not executed until the end and some lazy sequences might not be fully computed. Digging into that...

from timbre.

doesn't print anything to the logs. If I set the call to (profile :info ... ) it properly logs the profiling of my parse function.

Sorry, that's my fault! Shouldn't be multi-tasking. The lower the profile form's level, the less likely it'll be to log. I should have suggested you try :report, not :trace.

If your config's logging level is :debug (the default):

• (profile <x> ...) will profile+log for x = :debug :info, :warn, :error, :fatal, :report but not for :trace.

So just to back up for a sec. What happens when you run:

• (profile :report :parse (dorun (map parser/parse list-of-xml-snippets)))` from the parser's ns?
• (profile :report :parse (dorun (map parser/parse list-of-xml-snippets)))` from another ns?

Note that dorun will realise the lazy seq here. You'll want doall instead if you actually want the seq elements, but that shouldn't affect the profiling.

from timbre.

Ah ok. :report logs stuff indeed.

When running the parse fn I get the following nearly identical:

2014-May-14 14:31:34 +0200 superdings.local REPORT [patalyze.core] - Profiling: :patalyze.core/parse
                  Id      nCalls       Min        Max       MAD      Mean   Time% Time
:patalyze.core/parse       6,862   914.0μs    537.0ms   699.0μs     2.0ms      89 13.3s
          Clock Time                                                          100 15.0s
      Accounted Time                                                           89 13.3s

2014-May-14 14:34:30 +0200 superdings.local REPORT [patalyze.parser] - Profiling: :patalyze.parser/parse
                    Id      nCalls       Min        Max       MAD      Mean   Time% Time
:patalyze.parser/parse       6,862     1.0ms    117.0ms   514.0μs     2.0ms      87 13.1s
            Clock Time                                                          100 15.0s
        Accounted Time                                                           87 13.1s

Are you sure that you wanted me to profile the parse fn and not the read-file one?

I also ran a profiling for the read-file fn: (profile :info :read-file (doall (map read-file (take 2 files)))) — This doesn't list the parse fn in the profiling and appends the log entry very shortly after executing the fn — long before the result is returned to the repl.

from timbre.

Are you sure that you wanted me to profile the parse fn and not the read-file one?

Yeah, since that's the fn that didn't seem to be showing up in the log - just wanted to confirm that it logs correctly when we profile it directly.

I also ran a profiling for the read-file fn: (profile :info :read-file (doall (map read-file (take 2 files)))) — This doesn't list the parse fn in the profiling and appends the log entry very shortly after executing the fn — long before the result is returned to the repl.

So maybe a silly question: but you're absolutely sure your read-file fn is actually calling the parse fn? There's no potential laziness in how read-file is calling parse? Is there anyway you could give me a small reproducible example to look at?

from timbre.

It looks somewhat like this. I'd not be surprised if there is an error in how I'm expecting this to work, esp with regards to laziness.

;; in patalyze.core
(defnp read-file [xml-archive]
  "Reads one weeks patent archive and returns a seq of maps w/ results"
  (map parser/patentxml->map
       (split-xml large-string))) ;; this returns a lazy seq

;; in patalyze.parser
(defn patentxml->map [xml-str]
    (let [version      (detect-version xml-str)
          xml-resource (parse xml-str)
          parsed  (do-more-stuff)]
        parsed))

I expected dorun to go down the whole way and it does that for the repl but somehow not during the profiling. Sorry if this turns out to be a dull mistake & and thanks a ton for your super fast responses! 👍

from timbre.

(profile :info :read-file (dorun (map (comp dorun read-file) (take 2 files))))
(profile :info :read-file (doseq [f (take 2 files) _ (read-file f)] nil)

These calls profile all the functions defined with defnp. I guess laziness bite my a**. Thanks!

from timbre.

Okay, no problem - thanks for letting me know!

I guess laziness bite my a**.

In case it's relevant, just remember that dorun will realize only the lazy seq it's wrapping:

(defn my-lazy-fn [x] (map #(do (println "running") (+ x %)) (range 10))) ; Returns a lazy seq
(map my-lazy-fn (range 10)) ; A lazy seq _of_ lazy seqs

(dorun (map my-lazy-fn (range 10))) ; A _realized_ seq of lazy seqs => still no print

;; To get the `println`s to execute, you'll need something like:
(defn my-lazy-fn [x] (dorun (map #(do (println "running") (+ x %)) (range 10))))
(dorun (map my-lazy-fn (range 10)))

;; or
(defn my-lazy-fn [x] (map #(do (println "running") (+ x %)) (range 10)))
(dorun (map #(dorun (my-lazy-fn %)) (range 10)))

doall may also be more appropriate if you actually want the seq contents and not just a side effect. But if you don't need laziness, mapv is faster + less likely to cause these kinds of confusing errors.

Good luck, cheers! :-)

from timbre.