Why Does This Perform Better?

Question

So I'm trying to implement an Aspect-Oriented Design into my architecture using debug_backtrace and PHP reflection. The design works but I decided to see just how badly it impacts performance so I wrote up the following profiling test. The interesting thing is that when the Advisable and NonAdvisable methods do nothing, the impact is about 5 times that for using an advisable method versus using a non-advisable method, but when I increase the complexity of each method (here by increasing the number of iterations to 30 or more), advisable methods perform begin to perform better and continue to increase as the complexity increases.

Base class:

abstract class Advisable {

    private static $reflections = array();
    protected static $executions = 25;

    protected static function advise()
    {
        $backtrace = debug_backtrace();
        $method_trace = $backtrace[1];
        $object = $method_trace['object'];
        $function = $method_trace['function'];
        $args = $method_trace['args'];

        $class = get_called_class();

        // We'll introduce this later
        $before = array();
        $around = array();
        $after = array();

        $method_info = array(
            'args' => $args,
            'object' => $object,
            'class' => $class,
            'method' => $function,
            'around_queue' => $around
        );

        array_unshift($args, $method_info);
        foreach ($before as $advice)
        {
            call_user_func_array($advice, $args);
        }

        $result = self::get_advice($method_info);

        foreach ($after as $advice)
        {
            call_user_func_array($advice, $args);
        }

        return $result;
    }

    public static function get_advice($calling_info)
    {
        if ($calling_info['around_queue'])
        {
            $around = array_shift($calling_info['around_queue']);
            if ($around)
            {
                // a method exists in the queue
                return call_user_func_array($around, array_merge(array($calling_info), $calling_info['args']));
            }
        }
        $object = $calling_info['object'];
        $method = $calling_info['method'];
        $class = $calling_info['class'];

        if ($object)
        {
            return null; // THIS IS THE OFFENDING LINE
            // this is a class method
            if (isset(self::$reflections[$class][$method]))
            {
                $parent = self::$reflections[$class][$method];
            }
            else
            {
                $parent = new ReflectionMethod('_'.$class, $method);
                if (!isset(self::$reflections[$class]))
                {
                    self::$reflections[$class] = array();
                }
                self::$reflections[$class][$method] = $parent;
            }
            return $parent->invokeArgs($object, $calling_info['args']);
        }
        // this is a static method
        return call_user_func_array(get_parent_class($class).'::'.$method, $calling_info['args']);
    }
}

An implemented class:

abstract class _A extends Advisable
{
    public function Advisable()
    {
        $doing_stuff = '';
        for ($i = 0; $i < self::$executions; $i++)
        {
            $doing_stuff .= '.';
        }
        return $doing_stuff;
    }

    public function NonAdvisable()
    {
        $doing_stuff = '';
        for ($i = 0; $i < self::$executions; $i++)
        {
            $doing_stuff .= '.';
        }
        return $doing_stuff;
    }
}

class A extends _A
{
    public function Advisable()
    {
        return self::advise();
    }
}

And profile the methods:

$a = new A();
$start_time = microtime(true);
$executions = 1000000;
for ($i = 0; $i < $executions; $i++)
{
    $a->Advisable();
}
$advisable_execution_time = microtime(true) - $start_time;
$start_time = microtime(true);
for ($i = 0; $i < $executions; $i++)
{
    $a->NonAdvisable();
}
$non_advisable_execution_time = microtime(true) - $start_time;

echo 'Ratio: '.$advisable_execution_time/$non_advisable_execution_time.'<br />';
echo 'Advisable: '.$advisable_execution_time.'<br />';
echo 'Non-Advisable: '.$non_advisable_execution_time.'<br />';
echo 'Overhead: '.($advisable_execution_time - $non_advisable_execution_time);

If I run this test with the complexity at 100 (A::executions = 100), I get the following:

Ratio: 0.289029437803
Advisable: 7.08797502518
Non-Advisable: 24.5233671665
Overhead: -17.4353921413

Any ideas?

Answer 1

Sorry for the bother, I just found the line return null; in the get_advice method before the parent method gets called. I hate to answer my own question but it's not really worth someone else searching for it.

Answer 2

You're skipping all of the iterations when you call A's Advisable method... you're overwriting it with one single call to the inherited advise() method. So, when you add iterations, you're only adding them to the NonAdvisable() call.

Answer 3

method overhead should apply to PHP as well as to Java i guess - "the actual method that is called is determined at run time" => the overhead for shadowed Advisible method is bigger

but it would be O(1) instead of Non-Advisable's O(n)