Getting a comprehensive view of the causes of poor performance and latency in your Drupal instance can be tricky. AllPlayers.com, a Tracelytics user, has developed a module to integrate Drupal with Tracelytics and make this process much more straightforward. This module is an excellent example of how one can integrate custom code with the Tracelytics API to provide greater insight into application performance. Let’s explore the functionality of this module, and the source to see how that was implemented to report on full stack application tracing data.

Installation

Installing the Drupal module is as straightforward as downloading it and extracting the .tar.gz or zip. The files should then be installed in your Drupal installation, under sites/all/modules. You can also install the module through the Drupal Admin UI.  You should have also already installed the instrumentation, including instrumentation for your web server and PHP.

Features

Additional Layers

The module provides information on various Drupal-specific layers, each corresponding to a specific Drupal hook. Hooks are PHP functions called by the Drupal framework code at various times during request processing, and are used to generate Tracelytics layer entry and exit events. These events allow Tracelytics to determine how much time each request spent processing in an individual layer. The layers supported today are:

• drupal_hook_boot : Tasks run at the beginning of each page request.
• drupal_hook_init : Setup tasks for non-cached page requests.
• drupal_hook_form_alter : Modifications of a form before it is rendered.
• drupal_views (corresponds to time spent between drupal_hook_views_pre_view and drupal_hook_views_post_render)
• drupal_hook_node_load : Act on nodes loaded from a database.
• drupal_hook_watchdog : Message / event logging.
• drupal_hook_exit :  Tasks run at the end of each page request.

Controller / Action

A controller and action pair is reported for each request by examining currently active Drupal “menu item”, which provides information on the code handling each request. This is particularly important with Drupal since almost all non-static requests are handled by the root index.php file, meaning the URL itself is not useful for categorizing a request.

• Controller: The ‘page_callback’ function associated with the active Drupal menu item (from the menu_get_item() call).
• Action: The first argument in the ‘page_arguments’ array associated with the active menu item.

Request Partitioning

Requests are associated with a specific partition, depending on the type of request. This is crucial for determining where your heaviest requests come from, and when. The support partitions today are:

• Admin : Drupal admin user
• Anonymous : Anonymous user (not logged-in)
• Authenticated : Logged in user
• Cron : Periodic / cron execution
• Drush : Command line shell / script (see www.drush.org)

Complete Error Logging

Drupal provides a “watchdog” function for logging error/warning/debug messages. More severe messages can be forwarded to Tracelytics and will be tracked as errors.

Configuration

The above features can be turned on and off through the Drupal admin interface:

Note that it also integrates with Drush, a command line / shell scripting package.

How’s it work?

How does this module integrate with Tracelytics?  If we examine the module code, we’ll see that it makes extensive use of the oboe_log function.  This is a function added to PHP by the Tracelytics PHP instrumentation (“oboe”) module. It allows a code to log events, and is described in more detail in our knowledge base.  The particular snippet logs an “info” event to report the partition based on the currently logged in user:

switch ($user->uid) {
  case 1:
    oboe_log('info', array('Partition' => 'Admin'));
    break;

  case 0:
    oboe_log('info', array('Partition' => 'Anonymous'));
    break;

  default:
    oboe_log('info', array('Partition' => 'Authenticated'));
    break;
}

If we browse through the rest of the code (specially the tracelytics_early and tracelytics_late sub-modules), we’ll see that each module registers the same hook. The “early” module executes first and sends the “entry” event, while the “late” module executes last and sends the “exit” event. The order of Drupal module execution is controlled by assigning each module a weight.

Depending on the site configuration, various other modules would also register the same hooks and perform processing. Using the timestamps on the events allows Tracelytics to determine the processing time spent in each layer.  Snippets for the “init” hooks (which are called for all non-cached page requests) are shown below:

tracelytics_early.module:

function tracelytics_early_init() {
  if (variable_get('tracelytics_layers', FALSE)) {
    oboe_log('drupal_hook_init', 'entry', array());
  }
}

tracelytics_late.module:

function tracelytics_late_init() {
  if (variable_get('tracelytics_layers', FALSE)) {
    oboe_log('drupal_hook_init', 'exit', array());
  }
}

The pattern used for other hooks is the same.

As you can see, integrating Tracelytics as part of your application is very straightforward! In future blog articles, we’ll explore integrations with other languages and platforms, including Python, Ruby, and Java.