Hi folks. ÂI was hoping that someone here could 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 eitherof 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

Larry,

i havent dug into the code or the post much cause im coding away today,
but i did drop you test script on a box of mine and run it. for what its
worth,
heres the results:

nathan@devel ~/working/www $ php testBench.php
Testing __call()
Native Method: 8.62859416008 seconds
Magic Method: 15.2616789341 seconds
Testing __call() with sub-function
Native Method: 8.45631313324 seconds
Magic Method: 31.9451780319 seconds

the native method actually ran faster the second time..

-nathan

Yeah, it does that sometimes. But over 1 million iterations a 0.2 second
difference is negligible, and easily explained by random events in the
environment (other processes on the box, etc.) It's the 25% difference I'm
getting on just one box that is confusing the hell of of me. :-)

On Thursday 18 October 2007, Nathan Nobbe wrote:
> Larry,
>
> i havent dug into the code or the post much cause im coding away today,
> but i did drop you test script on a box of mine and run it. for what its
> worth,
> heres the results:
>
> nathan@devel ~/working/www $ php testBench.php
> Testing __call()
> Native Method: 8.62859416008 seconds
> Magic Method: 15.2616789341 seconds
> Testing __call() with sub-function
> Native Method: 8.45631313324 seconds
> Magic Method: 31.9451780319 seconds
>
> the native method actually ran faster the second time..
>
> -nathan


--
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

On 10/18/07, Larry Garfield <larry@garfieldtech.com> wrote:
>
> Yeah, it does that sometimes. But over 1 million iterations a 0.2 second
> difference is negligible, and easily explained by random events in the
> environment (other processes on the box, etc.) It's the 25% difference
> I'm
> getting on just one box that is confusing the hell of of me. :-)



is the behavior consistent (im assuming it is). do you have error logging
turned on?
have you compared php.ini on the strange system against the configuration
you have
on other systems?
is it only acting strange on the cli? maybe try accessing the script from a
browser and
see if you get different results.

-nathan