[xdebug-general] Xdebug profiling question

Hi

I have a question on how the profiler accounts for time taken to call
functions. My code calls a function which does a few very minor
operations, the profiler shows that 86.48 % of the time is spent in the
function and its descendants, but that 73% time is spent in the function
itself. The 73% is marked (in this case) against the { after the
function declaration (indicated in the source listing below), but if
there are comments at the start of the file the time spent is
occasionally allocated to a comment line or to the last line of the file.

I've appended a few lines of the cachegrind.out file at the end of the
note.

I'm wondering if it's just that actually calling the function is much
more compute intensive than any thing it does, and if the profiler
allocates the time taken by the function call to the function itself?
Can anyone tell me how the profiler works out times associated with
function calls? I have tried to verify this by experiment but I'm not
getting completely consistent results.

I'm also unable to explain why the %age time is sometimes allocated to a
comment line or the end }.

The source code for the main routine is here:
=============================

<?php
    require_once "Token.php";
    require_once "LowerCase.php";
    $token = new Token("go", 105, 107);
    $filter = new LowerCase();
    for ($i=0; $i < 100000; $i++) {
        $norm_token = $filter->normalize($token);
    }
    var_dump($token);
?>

The function that I'm interested in is LowerCase->normalize, the source
is here:
====================================================

<?php
class Lowercase
{
    public function normalize(Token $srcToken)
    {
<-------------------------------------------------------------------------------------
73% here
        $newToken = new Token(strtolower( $srcToken->getTermText() ),
                                $srcToken->getStartOffset(),
                                $srcToken->getEndOffset());
      $newToken->setPositionIncrement($srcToken->getPositionIncrement());

     return $newToken;
    }
}

and for completeness (although I don't think it's relevant) here is the
source for Token.php
===========================================================

<?php

class Token
{
 
    private $_termText;

 
    private $_startOffset;

 
    private $_endOffset;

 
    private $_positionIncrement;

    public function __construct($text, $start, $end)
    {
        $this->_termText = $text;
        $this->_startOffset = $start;
        $this->_endOffset = $end;

        $this->_positionIncrement = 1;
    }

    public function setPositionIncrement($positionIncrement)
    {
        $this->_positionIncrement = $positionIncrement;
    }

 
    public function getPositionIncrement()
    {
        return $this->_positionIncrement;
    }

 
    public function getTermText()
    {
        return $this->_termText;
    }

 
    public function getStartOffset()
    {
        return $this->_startOffset;
    }

    public function getEndOffset()
    {
        return $this->_endOffset;
    }
}

?>

Lines from cachegrind.out.XXX
=====================

fl=/pperfscripts/LowerCase.php
fn=Lowercase->normalize
7 107
cfn=Token->getTermText
calls=1 0 0
8 6
cfn=php::strtolower
calls=1 0 0
8 6
cfn=Token->getStartOffset
calls=1 0 0
9 3
cfn=Token->getEndOffset
calls=1 0 0
10 2
cfn=Token->__construct
calls=1 0 0
10 4
cfn=Token->getPositionIncrement
calls=1 0 0
11 2
cfn=Token->setPositionIncrement
calls=1 0 0
11 3

?>
Received on Thu Jul 03 2008 - 12:34:02 BST