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

class CakePHP3 
{
     public static function load()     {
         if (!class_exists('TidewaysProfiler')) {
             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 bootstrap the framework?
• Does the framework use an event system?
• Where in the FrontController are exceptions cached and processed?
• How can we name individual controllers and actions?

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

<?php

// previous code from Tideways.php

TidewaysProfiler::watchCallback(
     'CakeControllerController::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 = TidewaysProfiler::createSpan('php.ctrl');
         $span->annotate(['title' => $title]);

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

The watchCallback method has two arguments. The first one is a function that the Tideways extension is listening to and the second one is 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

TidewaysProfiler::watchCallback(
     'CakeViewView::render',
     function ($context) {
         $view = ($context['args'][0]) ?: get_class($context['object']);
         $span = TidewaysProfiler::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

TidewaysProfiler::watchCallback(
     'CakeEventEventManager::dispatch',
     function ($context) {
         $event = is_object($context['args'][0])
             ? $context['args'][0]->name()
             : $context['args'][0];
         $span = TidewaysProfiler::createSpan('event');
         $span->annotate(['title' => $event]);

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

TidewaysProfiler::watchCallback(
     'CakeEventEventManager::_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 = TidewaysProfiler::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 that need monitoring is CakeORMTable::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

TidewaysProfiler::watch('CakeORMTable::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 inconvenient, 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 bootstrap method, instead it runs much of the in the bootstrap/start.php script. If we want to get feedback about CakePHP bootstrapping, 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 = TidewaysProfiler::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 segmented 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 CakeNetworkRequest;
use CakeNetworkResponse; 
use CakeRoutingDispatcherFactory;

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

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

    $name = $request->params['controller'] . '/' . $request->params['action'];
     TidewaysProfiler::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 Timespans