Newsgroups: php.internals
Path: news.php.net
Xref: news.php.net php.internals:32800
Mailing-List: contact internals-help@lists.php.net; run by ezmlm
Received-SPF: error (pb1.pair.com: domain garfieldtech.com from 204.127.200.82 cause and error)
To: internals@lists.php.net
Date: Mon, 15 Oct 2007 20:54:11 -0500
User-Agent: KMail/1.9.6
MIME-Version: 1.0
Content-Type: text/plain;
  charset="utf-8"
Content-Transfer-Encoding: 7bit
Content-Disposition: inline
Message-ID: <200710152054.11288.larry@garfieldtech.com>
Subject: Strange benchmark behavior
From: larry@garfieldtech.com (Larry Garfield)

Hi folks.  I was hoping that someone here could help me understand a bit of 
weirdness I've come across.  I'm trying to run some micro-benchmarks on PHP 
5's object handling.  My test code is as follows:

<?php
define('ITERATIONS', 1000000);
///////////////////////////////////////////////////////////////////
echo "Testing __call()". PHP_EOL;

class TestCall {
  function normal() { return; }
  function __call($method, $args) { return; }
}

$t = new TestCall();

$start = microtime(true);
for ($i=0; $i < ITERATIONS; ++$i) {
  $t->normal();
}
$stop = microtime(true);
echo "Native Method: " . ($stop - $start) . " seconds". PHP_EOL;

$start = microtime(true);
for ($i=0; $i < ITERATIONS; ++$i) {
  $t->doesntExist();
}
$stop = microtime(true);
echo "Magic Method: " . ($stop - $start) . " seconds". PHP_EOL;

///////////////////////////////////////////////////////////////////
echo "Testing __call() with sub-function". PHP_EOL;

class TestCallSub {
  function normal() { return; }
  function bar() { return; }
  function __call($method, $args) {
    if ($method == 'foo') {
      return call_user_func_array(array($this, 'bar'), $args);
    }
    return;
  }
}

$t = new TestCallSub();

$start = microtime(true);
for ($i=0; $i < ITERATIONS; ++$i) {
  $t->normal();
}
$stop = microtime(true);
echo "Native Method: " . ($stop - $start) . " seconds". PHP_EOL;

$start = microtime(true);
for ($i=0; $i < ITERATIONS; ++$i) {
  $t->foo();
}
$stop = microtime(true);
echo "Magic Method: " . ($stop - $start) . " seconds". PHP_EOL;

///////////////////////////////////////////////////////////////////
?>

Basically I'm just trying to figure out the cost of __call() and other fancy 
OO features.  

The problem I'm running into is that the results I get back on a PHP 5.2.4 box 
are along the lines of the following:

Native Method: 0.76211094856262 seconds
Magic Method: 1.851991891861 seconds
Testing __call() with sub-function
Native Method: 1.0601480007172 seconds
Magic Method: 5.7655189037323 seconds

Ignoring the exact numbers for a moment, I am puzzled as to why the second 
Native Method is 25% slower than the first.  The function call should be 
exactly the same.  Using a separate variable for the second test had no 
effect.  My first thought was that the existence of a non-trivial __call() 
was slowing down the whole object.  However, when I comment out the first 
test block entirely, I got the following results:

Testing __call() with sub-function
Native Method: 0.75452494621277 seconds
Magic Method: 6.1330490112305 seconds

So when the first test doesn't get run, the second test gets faster.  Huh?  
I've run the test numerous times now, and it's very consistent.

Confused, I ran the same test script on a different computer running 5.2.1 
(which I have been led to believe is a notably slow and buggy version):

Testing __call()
Native Method: 2.9479010105133 seconds
Magic Method: 5.5952389240265 seconds
Testing __call() with sub-function
Native Method: 2.525377035141 seconds
Magic Method: 11.09939289093 seconds

It doesn't happen there.  (Yes, it's a much older box. <g>)  I get almost 
exactly the same results for the "sub-function" version regardless of whether 
the first test runs or not, which is what I would expect to happen.

Curiouser and curiouser, I had a friend run the same script on a 5.2.3 
computer:

Native Method: 0.976696014404 seconds
Magic Method: 2.29192996025 seconds
Testing __call() with sub-function
Native Method: 0.953128814697 seconds
Magic Method: 4.98710489273 seconds

Again, no statistically significant difference between the first and second 
tests.

So I tried it again on another 5.2.4 box, which should be identically 
configured to the first.  (Two different servers with the same shared hosting 
company.)

Testing __call()
Native Method: 0.83786416053772 seconds
Magic Method: 2.7027611732483 seconds
Testing __call() with sub-function
Native Method: 0.94142198562622 seconds
Magic Method: 7.6225128173828 seconds

So, thoroughly confused, I throw the question out.  G'What?  Is this a bug in 
PHP 5.2.4?  Is this a flaw in my testing methodology?  Is this a flaw in that 
one particular server's configuration or compilation?  If so to either of the 
second two, what?

I'm reluctant to trust any benchmarks from this script until I figure out why 
it's behaving like that, so any advise would be appreciated.

-- 
Larry Garfield			AIM: LOLG42
larry@garfieldtech.com		ICQ: 6817012

"If nature has made any one thing less susceptible than all others of 
exclusive property, it is the action of the thinking power called an idea, 
which an individual may exclusively possess as long as he keeps it to 
himself; but the moment it is divulged, it forces itself into the possession 
of every one, and the receiver cannot dispossess himself of it."  -- Thomas 
Jefferson