Comments (6)
Hi Jason, thanks for getting in touch!
It'd help if you could give me a concrete example to look at?
from timbre.
Sure, I'm thinking about this:
(a (b) (c))
If I profile it:
(p :a (a (p :b (b)) (p :c (c))))
Timbre will give me three times: running time for :c, running time for :b, and running time for :a (which is the total running time of the entire call).
What I cannot get right now is the time to run :a without the time for :b and :c. Obviously I can do the math, but that gets harder when :b has its own nested calls, and I'm trying to figure out exactly where the slow point is.
from timbre.
Hmm, I'm not sure what you're asking for makes sense (though I may be missing something!).
As a concrete example:
(defn fna [& args] (Thread/sleep 1000) "a")
(defn fnb [& args] (Thread/sleep 500) "b")
(defn fnc [& args] (Thread/sleep 900) "c")
(profile :info :nesting (p :a (fna (p :b (fnb (p :c (fnc)))))))
%>
2012-Dec-15 17:08:54 Schrebermann.local INFO [taoensso.rig.views.experiments] - Profiling taoensso.timbre.profiling/nesting
Name Calls Min Max MAD Mean Total% Total
taoensso.timbre.profiling/a 1 2s 2s 0ns 2s 100 2s
taoensso.timbre.profiling/b 1 1s 1s 0ns 1s 58 1s
taoensso.timbre.profiling/c 1 901ms 901ms 0ns 901ms 37 901ms
Unaccounted 0 0ns
Total 100 2s
When we wrap fna
with (p :a ...)
, we're asking how much time is being spent executing fna
. And that is what we're getting back: in this case fna
consists of waiting for the execution of fnb
and fnc
. It couldn't really be anything else.
If you wanted the time for the sleep within fna
(for example), you'd need to wrap that specially. But that'd be asking for something different. Saying that fna
"took 1s" isn't really accurate. Does that make sense?
Obviously I can do the math, but that gets harder when :b has its own nested calls, and I'm trying to figure out exactly where the slow point is.
It gets harder because there isn't any general/automatic strategy to do what you're looking for.
The way I'd approach this is (for example):
- See that we're spending an awful lot of time on
fna
. - Profile
fna
's constituents to discover where specificallyfna
is spending all this time. - Drill-down in this fashion as necessary until you have the data you want.
What we could do in the general case is perhaps make the "Unaccounted" measurement a little smarter. For example, if (> total-time accounted-time), then we get the usual "Unaccounted" measurement > 0.
But if (> accounted-time total-time), we could instead print an "Over-accounted" figure. In this specific example, that'd come to 58% (or 1.4s). The total should also show 158%.
This'd help make it immediately obvious that there's nesting occurring, and it'll quantify how much. It won't solve the general problem of teasing apart the nesting though.
What do you think?
from timbre.
Sorry, am a bit swamped with work atm - will try get this done tomorrow.
from timbre.
Alright, just pushed 1.1.0
which distinguishes between wall-clock time and accounted-for time.
This gives you some more info to work with in case of nesting, but it's still no substitute for inspection and understanding the flow of your particular code.
Hope this helps a little at least. Just shout if there's anything else I can do!
from timbre.
Sure, thanks for the improvement.
from timbre.
Related Issues (20)
- cljs: JS objects are printed uselessly HOT 2
- Update io.aviso/pretty to 1.2 HOT 1
- Support for `nbb` HOT 3
- Community appenders no longer included in 6.0.0 HOT 2
- 6.0.1. breaks in GraalVM native-image HOT 11
- Add test/s re: GraalVM compatibility HOT 1
- 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
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.