View Issue Details

IDProjectCategoryView StatusLast Update
0000385Xdebugpublic2010-03-20 23:43
Reportergauthierm Assigned Toderick  
PrioritynormalSeverityminorReproducibilityalways
Status resolvedResolutionunable to reproduce 
Summary0000385: profiling time of md5() and serialize() not reported correctly
Description

If I run a script that calls md5() or serialize() many times in a loop, the calling function reports a large execution time but it's really md5() and/or serialize() that is taking all the time.

Example:

function my_func() {
for ($i = 0; $i < 1000; $i++) { md5($foo); }
}

In this example, the profiled running time of my_func() is high and the running time of md5() is low.

TagsNo tags attached.
Operating Systemlinux
PHP Version5.2.6

Activities

mehdir

2009-02-02 12:30

reporter   ~0000910

Last edited: 2009-02-02 15:06

I have the same problem with every profiled functions.
Profiling time of a function seems to be add to the caller function time :

<?php
function OneThousandMd5() {
for($i=0; $i<1000;$i++) {
$test = md5('dummy');
}
}
OneThousandMd5();
?>

Results :
onThousandMd5 (self) : 36 527 (69,72%)
md5 : 16, 191 (30,28%)

Another example more signifiant :
<?php

/
Only one profiled function within.
/
function oneDoThousandArray() {
doThousandArray();
}

function doThousandArray() {
for($i=0; $i<1000;$i++) {
$test = array();
}
}
/
1000 profiled functions within.
/
function oneThoushandDoArray() {
for($i=0; $i<1000;$i++) {
doArray();
}
}

function doArray() {
$test = array();
}

$s = microtime(true);
oneDoThousandArray();
$e = microtime(true);
echo "oneDoThousandArray : ".(($e - $s) 1000000)."\n";
$s = microtime(true);
oneThoushandDoArray();
$e = microtime(true);
echo "oneThoushandDoArray : ".(($e - $s)
1000000)."\n";

?>

Results :
Without xdebug profiling :
oneDoThousandArray : 965.118408203
oneThoushandDoArray : 14851.0932922

With xdebug profiling
oneDoThousandArray : 1019.9546814 (1.05x)
oneThoushandDoArray : 46550.0354767 (3.13x)

Cachegrind data :
oneDoThousandArray : 100% (0.867 ms)
oneDoThousandArray (self) : 6.81% (1 call)
doThousandArray : 93.19 %
oneThousandDoArray : 100% (47, 374 ms)
oneThousandDoArray (self) : 77.74% (1 call)
doArray : 22.26% (1000 calls)

The best would be to remove profiling time from xdebug cachegrind file, or, if not possible, to add the profiling time of the function to the function executing time not to the caller executing time.

Issue History

Date Modified Username Field Change
2008-07-10 20:02 gauthierm New Issue
2009-02-02 12:30 mehdir Note Added: 0000910
2009-02-02 15:06 mehdir Note Edited: 0000910
2010-03-20 23:43 derick Status new => resolved
2010-03-20 23:43 derick Resolution open => unable to reproduce
2010-03-20 23:43 derick Assigned To => derick
2016-07-31 12:35 derick Category Debug client (console) => debugclient (debugging tool)
2016-07-31 12:35 derick Category debugclient (debugging tool) => (No Category)