Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

Can XDebug track separately the time spent for profiler calls?

I am using XDebug as a profiler for a PHP application. I have run into a situation where XDebug changes severely the results in such a degree that they are useless.

Here a simplified example to demonstrate the problem:

function foo(){ $x = 1; }
function bar(){ foo(); }

Test A:

$t0 = microtime(true);
for ($i = 0; $i < 1000000; $i++) foo();
echo microtime(true) - $t0;

Test B:

$t0 = microtime(true);
for ($i = 0; $i < 1000000; $i++) bar();
echo microtime(true) - $t0;

So, these are the results I am getting (in seconds):

          profiler  | profiler  > profiler
          disabled  | enabled   > results
          --------------------------------------------------------------------
          output    | output    > total time   time in foo()   time in bar()
Test A    0.159     | 12.199    > 12.245       0.110           - (not called)
Test B    0.233     | 25.399    > 25.578       0.104           11.068

The increased execution time is expected because of the extra calls to the profiler. The slight variation between the microtime-based output and the profiler results is also expected. I have repeated the tests several times, and the results are always similar.

From the results taken from Test B with the profiler disabled, we can say that the script spends about 0.159 seconds in foo() and 0.074 seconds in bar(). It is evident that time spent in bar() is less than the time spent in foo().

However, when I analyze the results of the profiler (with qcachegrind), the time shown as spent in bar() (= 11.068 seconds) is ridiculously higher than the time in foo() (=0.104 seconds). There is a possible explanation for this: each time a function call is made, the profiler runs some extra code to keep track of the time spent in the call. I believed that it excluded this extra time from the results, but apparently it does not.

[EDIT] As a result, the profiler says that bar() takes more time than foo() in this program, which is not the case as we have measured with the profiler disabled. It's not even close! The relative results (the percentage of time taken by each function) are totally wrong. This should not be expected, because, if this is the case, the profiler can not indicate which function takes most of the time. Although the absolute times are expected to have (big) differences, the relative times should not have. [/EDIT]

This renders the results unusable. Any code that is more modular (with more function calls, wrappers, objects etc.) is severely penalized, although it is not that slower!

So the question is: Is there any way to tell XDebug to ignore or track separately the extra time spent for the profiler calls?

like image 842
linepogl Avatar asked Sep 29 '11 12:09

linepogl


1 Answers

It is known that xdebug behaves like that and actually no news. Sorry, obviously this is news to you, and I don't want to say everybody needs to know that.

As an explanation: xdebug does the whole job, from beginning to end, dumping/metricating everyhing as announced. This comes with a price (how couldn't it?).

If you need to pick metrics in an isolated context within your script, you should not run xdebug. Or as your question shows: You're trying to profile xdebug with xdebug switched on (with PHP code!). That won't really work, you can't profile a PHP compiled C extension with PHP user-code, or at least I won't trust that much. Imagine the lib is changing the behaviour of the interpreter, that same interpreter your profiling code is running on.

If you really need to profile a specific part of your code isolated, xdebug is just not the tool of choice. Look for xhprof or maybe in a real life environment Pinba.

like image 98
hakre Avatar answered Sep 19 '22 03:09

hakre