Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

How to interpret Kcachegrind graphs?

Tags:

kcachegrind

I have started using Kcachegrind for performance analysis. But I don't understand the GUI and the output graphs.

For example for this call graph

enter image description hereSignatureIterator::iterate_parameters() I don't understand what is the 9.25% referring to ? the 5 198x means how many times SignatureIterator::iterate_parameters() called SignatureIterator::parse_type() ? What is the meaning of 100% in Symbol::byte_at(int) const ? What is an ELF Object ?

Note: In the official documentation http://kcachegrind.sourceforge.net/html/CallGraph.html, but still don't understand what is the caller distance to the function ?

like image 715
Bionix1441 Avatar asked Jun 08 '15 15:06

Bionix1441


1 Answers

All visualizations in KCachegrind center around a currently selected function, which is Symbol::byte_at() here. Usually, the percentage number of the selected function is shown in relation to total cost (runtime/cycles what ever). However, if you enable the mode/tool button "Relative to parent", the percentage numbers in the call graph get "zoomed up" to show 100% for the selected function, to make it easier to see ratios of cost spent in other functions, relative to the selected one.

Let's assume the cost (ie. event type selected in KCachegrind) is time (in CPU cycles or millisecs - doesn't matter to percentages). This makes it perhaps easier to understand.

The percentages in call graphs always show the time spent in some given function while the selected function (Symbol::byte_at) was active, ie. the time both functions could be found on the call stack during runtime of the program. This works both in callee direction (downwards Symbol::byte_at()) and caller direction (upwards Symbol::byte_at()).

Downwards, that is easier to understand: while Symbol::byte_at() was active, 24.14% of that time the processor actually was executing code from Symbol::base(). The other time (100% - 24.14%), code from Symbol::byte_at() itself was running.

Upwards of the selected function, it maybe is a bit more tricky. For example, the 9.25% for SignatureIterator::iterate_parameters() means that during the time Symbol::byte_at() was active, 9.25% of that time it was indirectly called from SignatureIterator::iterate_parameters(). Similarly, Symbol::byte_at() was called 11.27% of the time it was running directly from SignatureIterator::parse_type(). That is, upwards of the selected function, percentages in direct parents of a function always add up to the exact percentage of that function, unless a function was left off from the visualization due to being below the visibility threshold (see context menu).

like image 52
kohlbraten42 Avatar answered Oct 08 '22 00:10

kohlbraten42