Comments (10)
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.
Related Issues (20)
- Why are my Timbre timezones different than the system ones? HOT 3
- [shadow-cljs] Invalid :refer, var taoensso.encore/have does not exist HOT 26
- IllegalAccessException when logging internal JDK exception (SunCertPathBuilderException) via `log/error` HOT 13
- shadow-cljs: Advanced build bloated since 6.0.3 HOT 6
- Exception thrown when log arguments have same name, but different separators HOT 2
- Timbre crashing Cider workflow (?) HOT 9
- Using TAOENSSO_TIMBRE_CONFIG_EDN environment variable leads to an execption HOT 4
- Need some help/advice: No debug or info level logging, and duplicated message content HOT 10
- Add console appender opt to control `:raw-console?` HOT 1
- Link to Portal Timbre guide HOT 1
- Latest release uses older com.taoensso/encore; order-dependent if used with e.g. Tufte HOT 2
- API docs link from README results in 404 HOT 3
- Graal optimizations may break uberjar running HOT 6
- Seeing a lot of deprecation warnings in our log HOT 13
- Lots of Encore warnings HOT 3
- How to add appenders in the edn configuration? HOT 5
- Timbre v7
- Skipping a message for a specific appender HOT 6
- [TIMBRE WARNING]: `error-fn` failed, falling back to `pr-str` HOT 28
- how to use :min-level at the appender level based on namespace? HOT 1
Recommend Projects
-
React
A declarative, efficient, and flexible JavaScript library for building user interfaces.
-
Vue.js
🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.
-
Typescript
TypeScript is a superset of JavaScript that compiles to clean JavaScript output.
-
TensorFlow
An Open Source Machine Learning Framework for Everyone
-
Django
The Web framework for perfectionists with deadlines.
-
Laravel
A PHP framework for web artisans
-
D3
Bring data to life with SVG, Canvas and HTML. 📊📈🎉
-
Recommend Topics
-
javascript
JavaScript (JS) is a lightweight interpreted programming language with first-class functions.
-
web
Some thing interesting about web. New door for the world.
-
server
A server is a program made to process requests and deliver data to clients.
-
Machine learning
Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.
-
Visualization
Some thing interesting about visualization, use data art
-
Game
Some thing interesting about game, make everyone happy.
Recommend Org
-
Facebook
We are working to build community through open source technology. NB: members must have two-factor auth.
-
Microsoft
Open source projects and samples from Microsoft.
-
Google
Google ❤️ Open Source for everyone.
-
Alibaba
Alibaba Open Source for everyone
-
D3
Data-Driven Documents codes.
-
Tencent
China tencent open source team.
from timbre.