Showing time instead of cumulative in the icicle boxes

[unhyperbolic]

I find it very confusing that the size of the boxes and the number of the boxes do not correlate. In particular, if a function has multiple callees, you can have a situation where a child box has a larger value than the parent box.
This fixes it.

[unhyperbolic]

Python 2.7 failures are unrelated to this commit.

[jiffyclub]

Thanks for making a PR to snakeviz! I agree it can be confusing how times don't always match box size when functions are called from multiple places, but it is my intent that box size reflects and displays cumulative time, because the graphic shows functions and the functions they call, which is what cumulative time is a measure of.

[unhyperbolic]

Where actually is code that is computing the width of a box?

In drawsvg.js, I see vis.data([json])...attr("width",function(d){return x(d.dx);}) but I can't figure out where that dx is computed. The metric used to compute d.dx should also be the one that is written in the box - everything else is confusing.

You seem to suggest that that time is cumulative time but I think that is wrong: A box represents a function invocation, not a function, that is if you walk up the parenting boxes, you get the call stack and the width of the box should only be the time spent in the function when called through this particular chain. The good news is: you are actually computing that time correctly (I don't know how see above question). The bad news is: that time is not the cumulative time written into the box.

[jiffyclub]

Snakeviz does attempt to display the block width as time spent in that particular part of the call tree, but that is unfortunately not something cprofile actually records. When a function is called from multiple places in the call tree cprofile combines the metrics for those calls, leaving snakeviz without the info to know how much time was spent in the different places. That might be part of what you're seeing.

It'd be really helpful if you could share a profile or code snippet that illustrates the problem you're seeing so I can help diagnose it.

The code that builds the call tree is buried here:

snakeviz/snakeviz/templates/viz.html

Lines 172 to 246 in b8e9f9a

	function sv_build_hierarchy(
	node_name, depth, max_depth, cutoff, node_time, parent_name, call_stack) {
	// track visited functions so we can avoid infinitely displaying
	// instances of recursion
	if (_.isUndefined(call_stack)) {
	var call_stack = Immutable.Set([node_name])
	} else {
	var call_stack = call_stack.add(node_name);
	};
	var data = {
	name: node_name,
	display_name: stats[node_name]['display_name'],
	time: node_time,
	cumulative: stats[node_name]['stats'][3],
	parent_name: parent_name
	};
	if (depth < max_depth && !_.isEmpty(stats[node_name]['children'])) {
	child_names = {};
	for (var child_name in stats[node_name]['children']) {
	// Cut off children that have already been visited (recursion)
	if (!call_stack.contains(child_name)) {
	child_names[child_name] = stats[node_name]['children'][child_name];
	}
	}
	// Normalize the child times.
	// Unfortunately, stats[child_name]['callers'][node_name][3] doesn't
	// give us the time that child spend under node in this instance, but
	// in all instances across the call tree. Yikes!
	// This may lead to unexpected behavior, e.g., the child times add up
	// to more than the node time. A normalization is necessary.
	var child_times = {};
	var total_children_time = 0.0;
	for (var child_name in child_names) {
	child_times[child_name] = stats[child_name]['callers'][node_name][3];
	total_children_time += child_times[child_name];
	}
	if (total_children_time > node_time) {
	for (var child_name in child_names) {
	child_times[child_name] *= (node_time / total_children_time);
	}
	}
	data['children'] = [];
	// recurse
	for (var child_name in child_names) {
	if (child_times[child_name]/node_time > cutoff) {
	data['children'].push(
	sv_build_hierarchy(
	child_name, depth+1, max_depth, cutoff,
	child_times[child_name], node_name, call_stack
	));
	}
	}
	// D3, the plotting framework, only accounts for times in the leaf
	// nodes. Hence, if the node_time exceeds the total time in its
	// children, we need to add another child node to account for the the
	// time spent in node itself.
	if (total_children_time < node_time) {
	data['children'].push({
	name: node_name,
	display_name: data['display_name'],
	parent_name: data['parent_name'],
	cumulative: stats[node_name]['stats'][3],
	time: node_time - total_children_time
	});
	}
	}
	return data;
	}

[unhyperbolic]

I came up with an example to illustrate my point:

def sumOfSquares(r):
    return sum(x ** 2 for x in range(r))
def indirectSumOfSquares(r):
    return sumOfSquares(r)
 def sillyComputation(r):
    return sumOfSquares(r) - indirectSumOfSquares(r)
%snakeviz sillyComputation(10000000)

Here is the image when the text in the box "cumulative" (as it is now): https:/unhyperbolic/snakeviz/blob/bugImages/labeledByCumulative.png
And here with my above commit changing it to "time":
https:/unhyperbolic/snakeviz/blob/bugImages/labeledByTime.png

From looking at the images, I am confused by your comments: unlike you claim, cProfile does seem to give the necessary information to draw the boxes correctly. But writing cumulative as text into the boxes yields inconsistent results (e.g. one of the two invocation sof sumOfSquares is grouped under indirectSumOfSquares but its time is larger than its parent).

Thanks for sending the code snippet. There is still a disconnect in my mind: drawIcicle is using "d.dx" for the width. But the code snipped you sent is not setting dx anywhere. Where is assignment of a value to dx happening?

[unhyperbolic]

Just found the code that is computing the widths of the boxes:

snakeviz/snakeviz/static/drawsvg.js

Lines 39 to 41 in b8e9f9a

	var partition = d3.layout.partition()
	.size([width - leftMargin, height - topMargin])
	.value(function(d) { return d.time; });

And here is the code that is putting the text in the boxes:

snakeviz/snakeviz/static/drawsvg.js

Lines 296 to 297 in b8e9f9a

	labels.append("tspan")
	.text(function(d) { return d.cumulative.toPrecision(3) + " s"; })

I hope that makes the inconsistency crystal clear and why my commit is the right fix.

[jiffyclub]

I spent some time re-familiarizing myself with this code and now have a good grasp of what's on. As described in other issues, especially #112, the data made available by cProfile has some serious limitations when it comes to reconstructing a call tree with accurate timings in every part of the tree. The d.time value you linked isn't a direct product of cProfile output, rather a value derived from it in the sv_build_hierarchy function I linked.

The d.time value would be better named estimated_actual_cumulative_time and is calculated in sv_build_hierarchy from the caller/callee information provided by cProfile and a truth about program execution: the cumulative time spent in functions called within a parent function cannot exceed the cumulative time spent in the parent function. Sometimes, because of a program's structure, the data from cProfile will look like more time is spent in child calls than in the parent and when that happens the sv_build_hierarchy scales the child times so that they fit inside the parents' time. However, there is no info available that says how much time was truly spent in that part of the call tree, it's only a best guess (or for programs with no redundant parent/child calls it will be exactly correct).

Sometimes that guess is spot on and the size of the box is correct and the d.time value is mostly correct. Here's an example where it works:

import time

def sleep8():
    time.sleep(0.5)
    sleep3()

def sleep3():
    time.sleep(0.3)

def sleep1():
    time.sleep(0.1)

def sleepn(n):
    for _ in range(n):
        sleep1()

def root():
    sleep8()
    sleep3()
    sleepn(1)

root()

Current snakeviz shows this profile:

And your change shows this:

That shows how the parent time is propagated down to children when the child's cumulative time would exceed the parents', which in this case does result in the information displayed being more intuitive.

However, the guess can also be totally wrong, especially in cases where the same parent/child call results in very different execution times in different parts of the call tree. This is well illustrated by the example code from #112:

"""https:/jiffyclub/snakeviz/issues/112"""
import time

def a(t0, t1):
    c(t0)
    d(t1)

def b():
    a(1, 4)

def c(t):
    time.sleep(t)

def d(t):
    time.sleep(t)

if __name__ == "__main__":
    a(4, 1)  # 5 seconds total, 4 in c, 1 in d
    b()  # 5 seconds total, 1 in c, 4 in d

For that the current snakeviz shows this:

And your change results in this:

Those are both wrong, thanks to the limited information provided by cProfile.

Given the impossibility of showing completely correct info I decided to show the cumulative time spent in a function as reported by cProfile. That way at least the value shown matches what one sees in the table below or when using the pstats module directly. I also like that the value shown can be clearly impossible, that way people don't take it at face value. However, given this confusion, I could also see a case for not showing times in the icicle plot at all.

[unhyperbolic]

Thanks for your explanation. I see... That's unfortunate on cProfile's part :(

[unhyperbolic]

There is another project pyprof2calltree, also see http://thomas-cokelaer.info/blog/2013/10/profiling-python-with-valgrind/.
Does it suffer from the same problem?

[jiffyclub]

I don't know for sure, but it's working from the same limited cProfile source so I would expect so.