KCachegrind interpretation confusion

Question

I am trying to understand the values shown in Kcachegrind in the left panel

I have Incl. (which I read in the manual is inclusive), Self, Called an Function

Now I am analyzing this cachegrind file and I have

Incl. ---- Self ---- Called ---- Function

100.05 ---- 0.04 ---- (0) ---- {main}

83.38 ---- 0.07 ---- 250 --- item->close

78.85 ---- 78.85 ---- 10 067 ---- php::mysql_query

and the list continues..

But here is my problem.

I think that the item->close is my bottleneck but what I don't understand is how it has 83.38 of Inclusive and then 0.07 of Self and the mysql_query command has the same in both.

What does the 'self' signify here?

Also how do these percentages relate to one another? I don't get it how the item->close takes 83% and the mysql_query takes 78%

Thanks

Doud

Answer 1

"self" means the time taken by that function, but not from any functions that it calls. If "self" is low and "incl." is high, then the best place to optimise is probably in one of the children (eg. called functions). In this case, it looks like the mysql-query takes most of the time, so you'd probably want to optimise the query (If possible). The reason why mysql_qeury has "self" == "incl." is that the profiler can't see into the function, since it is doing its work outside of the php-runtime (eg. in the mysql client library)

I might add that 10067 calls to mysql_query does look mighty suspicious. A database query is a very expensive operation. Are you sure you can't reduce the number of queries somehow?

Edit:

I can try. But what about the Incl.? How is it 80 in the close and then 70 in the mysql query how does that relate to the total percentage which should be 100%

The numbers don't need to add up. What you're looking at, is a sorted list of the time of the whole, that these functions take. It's not a call graph (Although it will often happen to mimic that somehow).

Assume the following code:

function fn1() {
  sleep(1);
  fn2();
}
function fn2() {
  sleep(98);
}
function fn3() {
  sleep(1);
}
fn1();
fn3();

Which might generate the following output:

name | incl. | self
main | 100%  | 0%
fn1  | 99%   | 1%
fn2  | 98%   | 98%
fn3  | 1%    | 1%

When you sort the list by "incl.", you are looking at the functions that are slow in aggregate. In other words, those that score high here, are not necessarily slow, but they call other functions which are. If a function scores high on "incl." and has many calls, you should be looking into trying to reduce the number of calls to this function, or let the function cache its result (Only works if it's a query, rather than an action).

When you sort by "self", you will see the actual calls that take up most time. These are the functions that you'd want to fine-tune on. In most PHP scripts, you'll find that mysql_query dominates this field. If you have many calls, again try to reduce them or cache. If you have few calls, then you probably need to optimise the sql-query. The PHP-debugger can't help you with this. Instead, find the actual query and run an explain on it in the mysql-console. That's a whole chapter in itself.

Duplication

I can try. But what about the Incl.? How is it 80 in the close and then 70 in the mysql query how does that relate to the total percentage which should be 100% – Doud

Did you mean to call fn1() inside fn1()? This will cause an infinite loop – Doud

@Antonio: You're right - that was a typo. I've corrected it now. – Duplication

Thanks for this it was indeed helpful – Doud

does this mean that the list is sorted chronologically, most recent first? – Timberhead

Answer 2

Self means the time spent in the function excluding any functions it calls.

For example:

function foo()
{
    bar();
}

function bar
{
    sleep(1);
}

foo();

This would give you:

Incl    Self   Func
1       0      foo
1       0      bar
1       1      sleep <- Here's the bottleneck!

Adynamia