View Issue Details

IDProjectCategoryView StatusLast Update
0000077XdebugProfilingpublic2024-04-15 13:37
ReporterRoger Keays Assigned Toderick  
PriorityhighSeveritymajorReproducibilityalways
Status acknowledgedResolutionopen 
Target Version3.4dev 
Summary0000077: Profiler doesn't handle recursive functions
Description

The xdebug profiler seems to be unable to handle recursion properly. given the script:

<?php

function c() {
d();
}
function d() {

static $x;
if (!isset($x)) $x = 0;
$x++;
while ($x < 20) c();
}

c();

?>

We see the results

c() - cumulative: 1014.75% self: 49.36%
d() - cumulative: 965% self: 47.87%
main - cumulative: 100% self: 2.66%

self still sums to approx 100%, but the cumulative time is all wrong.

Having a look at the cachegrind.out file it is pretty clear what is happening - xdebug is counting the first call to d() in the total of the second call to d() - which is okay, but since it prints both to the file you end up with the equivalent of 3 calls to d().

I wouldn't accept filtering the linked list for function names the match the exiting function when summing totals as a valid solution for this defect, since recursion may be hidden at a distance of more than 1 function call away.

Can't think of a quick fix for this one...

TagsNo tags attached.
Operating System
PHP Version5.1.0

Relationships

has duplicate 0001710 closedderick Doubled recursion count in kcachegrind on select recursive function 
child of 0002072 acknowledged Rewrite the profiler 

Activities

eis_os

2010-07-23 09:42

reporter   ~0001536

Last edited: 2010-07-23 15:00

Can the time split by nest level?
So xdebug only sum up the total taken of the current nest level?

Currently my XDebug output here goes crazy, WinCacheGrind telling me percentage values in the 10000% range... (heavily recursion together with Smarty3) (That was actually bug 0000357

eis_os

2010-07-23 11:14

reporter   ~0001537

A slightly modified testcase (less recursive, more time per call):
<?php

function c() {
usleep(1000);
d();
}
function d() {
static $x;
if (!isset($x)) $x = 0;
$x++;
while ($x <30) c();
}

c();

?>

FloSchnell

2010-11-24 16:30

reporter   ~0001617

Can confirm this issue.
This, of course, also applies to object methods.
Really hard to realize that there's something wrong because if the program contains more than just nested functions then you won't realize that the cumulative is actually wrong.
It just seemed way too high, which got me looking into the issue ...

dinu

2012-05-25 03:06

reporter   ~0002189

I desperately need a fix to this, or I will have to go back to ZendDebugger... working on a project where recursion is unavoidable as its goal is to wrap together pieces of self-referencing data.

dinu

2012-06-02 18:08

reporter   ~0002229

So, here's my 2 cents:
http://www.exteon.ro/ro/produse/unelte-php/xt2callgrind
It's tested with a fairly large script of 100K+ function calls, lots of recursion, results are excellent.

It's a very large computational effort though, I now doubt it can be implemented in real time, might thou be translated in a C post-processing feature.

I do have one related question though, if it's in the Docs I missed it: with the profile or trace trigger, I get timings 200% (for large scripts) to 600% (for small scripts) of the real execution time. Do you have some stats linking real execution time, traced execution time and call overhead? Or what is expected of? Should the overhead be roughly linear with the execution time, or roughly linear with the # of function calls?

jboffel

2015-07-09 04:32

reporter   ~0003148

Last edited: 2015-07-13 08:37

Any plan on fixing this bug?

It's still wrongly reporting time spent in recursive function in xdebug 2.3.3 even if we push detect cycles...

I generated from vallgrind for a C program the equivalent example given here and kcachegrind show something relevant if we use detect cycles.

Issue History

Date Modified Username Field Change
2004-07-16 05:16 Roger Keays New Issue
2010-03-20 23:47 derick Target Version => 2.2dev
2010-07-23 09:42 eis_os Note Added: 0001536
2010-07-23 09:45 eis_os Note Edited: 0001536
2010-07-23 09:45 eis_os Note Edited: 0001536
2010-07-23 09:46 eis_os Note Edited: 0001536
2010-07-23 11:14 eis_os Note Added: 0001537
2010-07-23 15:00 eis_os Note Edited: 0001536
2010-11-24 16:30 FloSchnell Note Added: 0001617
2012-05-25 03:06 dinu Note Added: 0002189
2012-06-02 18:08 dinu Note Added: 0002229
2015-07-09 04:32 jboffel Note Added: 0003148
2015-07-13 08:37 jboffel Note Edited: 0003148
2016-07-31 12:36 derick Category Usage problems => Usage problems (Crashes)
2016-07-31 12:38 derick Category Usage problems (Crashes) => Usage problems (Wrong Results)
2016-12-03 13:20 derick PHP Version 4.3.0 => 5.1.0
2016-12-03 13:20 derick Assigned To => derick
2016-12-03 13:20 derick Status new => acknowledged
2020-03-12 16:35 derick Category Usage problems (Wrong Results) => Variable Display
2020-03-12 16:36 derick Category Variable Display => Profiling
2021-03-17 09:27 derick Priority normal => high
2021-03-17 09:27 derick Target Version 2.2dev => 3.1dev
2021-05-12 19:11 derick Relationship added has duplicate 0001710
2021-08-26 23:34 derick Target Version 3.1dev => 3.2dev
2022-06-06 15:27 derick Target Version 3.2dev => 3.3dev
2023-08-02 16:45 derick Target Version 3.3dev => 3.4dev
2024-04-15 13:37 derick Relationship added child of 0002072