Recognize nesting

[jasonab]

If I profile nested function calls, the time for the outer is the time for the inner + outer call. It would be nice to be able to tell p to subtract out the inner time.

[ptaoussanis]

Hi Jason, thanks for getting in touch!

It'd help if you could give me a concrete example to look at?

[jasonab]

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.

[ptaoussanis]

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):

1. See that we're spending an awful lot of time on fna.
2. Profile fna's constituents to discover where specifically fna is spending all this time.
3. 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?

[ptaoussanis]

Sorry, am a bit swamped with work atm - will try get this done tomorrow.

[ptaoussanis]

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!

[jasonab]

Sure, thanks for the improvement.