Benjamin Benjamin 25.06.2015

Profiling CakePHP 3 using Tideways Extension API

Tideways Timeline Profiler provides a powerful extension API to add custom timespans.

In this tutorial we will add support for CakePHP 3 applications. It is the first of many more tutorials, showing how to integrate with libraries and frameworks that are not supported by Tideways out of the box.

The result will be custom timespans for CakePHP like this following screenshot shows:

CakePHP TimespansCakePHP Timespans

Bootstrapping a Tideways Extension

We start by creating a reusable Composer package for this extension with a composer.json containing:

{
    "name": "tideways/profiler-cakephp3",
    "type": "tideways-extension",
    "autoload": {"files": ["Tideways.php"]}
}

The Composer autoloading refers to a Tideways.php, which contains a simple extension skeleton that prevents errors when Tideways is not installed:

<?php

namespace Tideways\Extensions;

class CakePHP3
{
    public static function load()
    {
        if (!class_exists('Tideways\Profiler')) {
            return;
        }
    }
}

CakePHP3::load();

Instrument CakePHP

The next step is finding out more about CakePHP 3, especially answers to the following questions:

  • How does the framework call controllers and actions?
  • What view or template engine does the framework use? How is it called?
  • What methods are called to boostrap the framework?
  • Does the framework use an event system?
  • Where in the FrontController are exceptions catched and processed?
  • How can we name individual controllers and actions?

We start by adding a timeline span for the controller call. We find that Cake\Controller\Controller::invokeAction calls the actions of your application, so we add custom instrumentation:

<?php

// previous code from Tideways.php

\Tideways\Profiler::watchCallback(
    'Cake\Controller\Controller::invokeAction',
    function ($context) {
        $controller = $context['object'];

        if (!$controller->request ||
            !$controller->isAction($controller->request->params['action'])) {
            return;
        }

        $title = get_class($controller) . '::' . $controller->request->params['action'];

        $span = \Tideways\Profiler::createSpan('php.ctrl');
        $span->annotate(['title' => $title]);

        return $span->getId();
    }
);

The watchCallback method has two arguments. First is a function that the Tideways extension is listening to and second a callback that gets invoked before the listened method is called. The current context is passed to the callback including the listened functions name, reference to an object and arguments. In this example we are accessing $context['object'] for the current instance where invokeAction is called on.

You have to return the id of a span from a callback to start collecting the time, otherwise Tideways will just skip profiling this function call.

Next, we also want to add timespans for the views rendered during a request:

<?php

// previous code from Tideways.php

\Tideways\Profiler::watchCallback(
    'Cake\View\View::render',
    function ($context) {
        $view = ($context['args'][0]) ?: get_class($context['object']);
        $span = \Tideways\Profiler::createSpan('view');
        $span->annotate(['title' => $view]);

        return $span->getId();
    }
);

The short ternary operator to populate the $view variable handles different cases where we render a template or return for example a JSON response.

CakePHP uses an event system, so lets hook into the Event Manager object to catch the different events and display their duration during the request and listeners that get called:

<?php

// previous code from Tideways.php

\Tideways\Profiler::watchCallback(
    'Cake\Event\EventManager::dispatch',
    function ($context) {
        $event = is_object($context['args'][0])
            ? $context['args'][0]->name()
            : $context['args'][0];
        $span = \Tideways\Profiler::createSpan('event');
        $span->annotate(['title' => $event]);

        return $span->getId();
    }
);

\Tideways\Profiler::watchCallback(
    'Cake\Event\EventManager::_callListener',
    function ($context) {
        $listener = $context['args'][0];
        if (is_array($listener)) {
            $title = get_class($listener[0]) . '::' . $listener[1];
        } else {
            return; // only support object listeners
        }

        $span = \Tideways\Profiler::createSpan('php');
        $span->annotate(['title' => $title]);

        return $span->getId();
    }
);

Again we are handling some CakePHP internals here to set the $event name and create a span of type event, setting a title and returning the ID from the callback. Listeners are registered with the timespan type php.

One method that pops up in the first tests for needing monitoring is Cake\ORM\Table::schema() which performs automatic model metadata discovery. We can add a watch for this method to the Profiler and it will automatically be profiled in all your CakePHP requests:

<?php

// previous code from Tideways.php

\Tideways\Profiler::watch('Cake\ORM\Table::schema');

This concludes the custom instrumentation that we can build to profile CakePHP code from the outside. You can see the whole code on Github or install it with Composer: $ composer require tideways/profiler-cakephp3.

More insights with changes to the CakePHP app

The following changes are a bit unconvenient, because we didn't want to modify our CakePHP application to start profiling. However some PHP code is not easily instrumented automatically.

CakePHP does not have a dedicated boostrap method, instead it runs much of the in the bootstrap/start.php script. If we want to get feedback about CakePHP bootstraping, we need to wrap this in a custom span by modifying the file. This way we can monitor bootstrapping and other expensive startup code.

<?php

    // find this line in bootstrap/start.php
    require 'vendor/autoload.php';

    // Add afterwards
    $span = \Tideways\Profiler::createSpan('php');
    $span->annotate(['title' => 'Cake::boot']);
    $span->startTimer();

    // rest of bootstrap/start.php

    $span->stopTimer();

The last important step is implementing the transaction naming, so that requests are segemented and can be analyzed individually. Again, the way CakePHP is desigend we cannot hook into this with Tideways Extension API from the outside yet.

Open up webroot/index.php to configure transaction naming and change the file to contain the last if-block as shown in this snippet:

<?php

require dirname(__DIR__) . DIRECTORY_SEPARATOR . 'bootstrap' . DIRECTORY_SEPARATOR . 'start.php';

use Cake\Network\Request;
use Cake\Network\Response;
use Cake\Routing\DispatcherFactory;

$dispatcher = DispatcherFactory::create();
$dispatcher->dispatch(
    $request = Request::createFromGlobals(),
    new Response()
);

if (class_exists("Tideways\Profiler") &&
    isset($request->params['controller']) &&
    isset($request->params['action'])) {

    $name = $request->params['controller'] . '/' . $request->params['action'];
    Tideways\Profiler::setTransactionName($name);
}

After we added all this to our extension we can start profiling CakePHP, using the opensource application Still Maintained? I see the following result in the Profiler when searching for the maintenance status of a package:

CakePHP TimespansCakePHP Timespans