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