Using Blackfire.io to profile Drupal loading time

Alex Dergachev
alex@evolvingweb.ca
@dergachev on twitter, github, drupal.org
Dave Vasilevsky
vasi@evolvingweb.ca
twitter.com/djvasi
@vasi on github, drupal.org

About the speakers

Outline

* Intro + motivation * Profiling methodology + philosophy * Demo 1: Blackfire UI Tour * Blackfire basics: Terminology, advantages, installation * Blackfire features (basic + intermediate) * Demo 2: Copy as cURL * Blackfire + Drupal tricks * Demo 3: Block visibility * Drupal performance considerations * Q & A

Motivation

Why page loading time is SUPER IMPORTANT

What profiling doesn't measure

What profiling measures

Why it matters for Drupal

Profiling gets results, fast

ProjectImprovementTime spent
McGill academic calendar13%1 hour
Client X52%6 hours
Evolving Web D821%2 days
AllJoyn Certification57%3 hours

How to profile: M.A.F.I.A.

How to profile: Measure

How to profile: Analyze

How to profile: Fix

How to profile: Iterate

How to profile: Applause

Measurement tools

Blackfire.io

Case study: McGill U

McGill University listing of courses and programs.

Case study: McGill U

Let's profile a page with Blackfire!

* Visit page * Make a profile * Tour the profile: read numbers? * Metrics (overall, I/O, cpu, memory...) * Call graph * Hot path -> resources * Function list * Number of calls * Expand: callees (time restricted to call) * Let's find a problem function * Hot path: theme() * moriarty_preprocess_page is long for a preprocess hook! * Follow down graph until the time changes significantly * We get to loadAcademicFacultyNodes * Calling node_load 36 times! Could be multiple

The slow code

public function loadAcademicFacultyNodes($language, $key){
  foreach($this->faculties as $f){
    if ($f->nid && $f->code){
      if (!$language || $f->language === $language){
        $node = node_load($f->nid);
        if ($key && $f->$key){
          $return[$f->$key] = $node;
        } else {
          $return[] = $node;
        }
      }
    }
  }
  // ...
}

Iterate over faculties, load nodes one at a time.

* Loading nodes one at a time is slow! Should load them all together, to minimize the number of DB queries.

A fix

public function loadAcademicFacultyNodes($language, $key){
  foreach($this->faculties as $f){
    if ($f->nid && $f->code){
      if (!$language || $f->language === $language){
        if ($key && $f->$key){
          $nids[$f->$key] = $f->nid;
        } else {
          $nids[] = $f->nid;
        }
      }
    }
  }

  $nodes = node_load_multiple($nids);
  // ...
}

Collect the nids, load all nodes at once.

Case study: McGill U

Saved about 25ms!

A real improvement in under an hour of total work, from profiling to committing a fix.

Installing Blackfire

Sign in with GitHub, then view the super-easy Blackfire Install Docs.

This installs: * `Probe`, a minimalistic PHP extension * `Agent`, a daemon that connects probe to blackfire servers * `Companion`, a Chrome extension * `Client`, command-line client It has has your API keys, and also instructions for Red Hat, OS X, Windows, docker, chef, and more. Install steps on Ubuntu: wget -O - https://packagecloud.io/gpg.key | sudo apt-key add - echo "deb http://packages.blackfire.io/debian any main" | sudo tee /etc/apt/sources.list.d/blackfire.list sudo apt-get update sudo apt-get install blackfire-agent blackfire-php # fill in server-id and server-token sudo blackfire-agent --register sudo /etc/init.d/blackfire-agent start # for command-line use, fill in client-id and client-token blackfire config # disable xhprof and xdebug php extensions # restart apache or php-fpm

Blackfire features

Case study: Client X

The problem

Homepage is slow

Let's check it out in Chrome inspector's Network tab:

That's a pretty slow redirect! Our browser is at the path `/en`, so that's what Blackfire would profile But we want to profile the redirect itself!

Profiling

Use Chrome's Copy as cURL:

Profiling

Give the results of Copy as cURL to Blackfire:

Profiling

Blackfire does its magic:

Analysis

function tq_home_preprocess_page(&$variables) {
  // ...
  $lang = locale_language_from_browser($languages);
  drupal_goto('<front>', $lang);
}

Moved it to a hook_init!

Case study: Client X

Took just an hour or two.

Blackfire tips

Blackfire tips

Blackfire tips

Can't use blackfire to compare different PHP versions

Case study: evolvingweb.ca

Case study: evolvingweb.ca

We already upgraded our site to Drupal 8!

D8 is great, we love features like Views in core, CKEditor, Twig…

But it's slower than D7

We learned a lot about D8, told people all about it.

Blog view

Really fast when cached!

No so fast after any node is edited, and D8 invalidates cache tags

Uncached requests

Aggregation makes it hard to profile uncached behavior.

So at the start of each request, pretend a node was edited:

class EwsiteSubscriber implements EventSubscriberInterface {
  public static function getSubscribedEvents() {
    $events[KernelEvents::REQUEST][] = ['killBlogCache'];
    return $events;
  }

  public function killBlogCache(GetResponseEvent $event) {
    $tags = ['node_list', 'node:239'];
    \Drupal::service("cache_tags.invalidator")->invalidateTags($tags);
  }
}
If we edit a node and then profile, Blackfire will have one uncached requests, then nine cached ones. We still want reliable numbers.

Profiling

Now let's see why it's so slow:

That's part of D8 core, and it's taking 117 ms!

* We do have a lot of blocks * But that's normal for a D8 site, so many things are blocks now

Analysis

public function getVisibleBlocksPerRegion(array &$cacheable_metadata = []) {
  // ...
  foreach ($this->blockStorage->loadByProperties(array('theme' => $active_theme->getName())) as $block_id => $block) {
    $access = $block->access('view', NULL, TRUE);
    // ....
  }
}

To get a list of blocks, Drupal 8:

* Iterates through lazy collections many times * Merges metadata many times over

Does this sound familiar?

node_access!

Instead of loading and checking each node, uses a single DB query.

A fix

Built a module that determines block visibility in one DB query: github.com/vasi/block_access_records

We saved over 80 ms on every uncached request!

* Similar to how `node_access` works, read more about it on our blog. * Supports Drupal's built-in block visibility conditions Caveats: * Sites with custom block conditions may need to implement them * Not super well tested

Blackfire Premium

Calls to Action!

Calls to Action!

Drupal training program

Visit us in Canada!

Just one more thing…

/

#