Debugging Magento Performance with New Relic

Earlier this year, New Relic posted a piece by Dyan de Rochemont, lead Magento developer at Bold Commerce, on Facing Magento with New Relic. That post offered an introduction to the benefits of integrating New Relic into Magento servers. This post will expand on that idea with a bit more of a technical approach.

We won’t explain how to install New Relic in a server because that’s thoroughly covered in the documentation. Just make sure you are using the most recent version of the New Relic PHP Agent. We’ll also assume you already have a fully working server where your Magento site is already up and running. To keep things simple we’ll use a vanilla installation of Magento plus the publicly available Sample Data. Look to this Magento post if you need help to install and configure the sample data. Of course, you’ll also need a New Relic account—you can get a free-forever New Relic Standard account by signing up here.

I created a (fake) Magento module to accompany this article. If you’d like to follow this article step by step while looking at the code, you can find it at Github. The module creates a Magento Widget that can be inserted into any CMS page or Static Block. It shows a list with links to all products that are marked with the custom attribute "featured." The custom attribute must be created and assigned to some products before testing the module.

A sample scenario

Good, so you have New Relic installed and your site is running! But you’ve asked a developer to create a widget that shows products marked with a custom attribute “featured.” One place where you want that widget is at the footer of the site. The developer implemented that feature, but for some reason the entire site is now taking much longer to load than before.

If you’ve worked with Magento for a while, especially if you have taken over projects originally made by developers who were not Magento Certified, you may have already run into similar situations.

New Relic to the rescue

The first thing you’ll want to do is install the Yireo New Relic module. This module takes care of integrating some of the more advanced features of New Relic and makes it easier for you to get a proper breakdown of what’s happening on your website.

Once the module is installed, go to System > Configuration > Advanced > New Relic and enter your Application Name (e.g. Demo Store), New Relic License Key, and decide whether or not you want New Relic Browser (formerly known as Real User Monitoring or RUM). We won’t go into what New Relic Browser is or how to use it in this article so you can leave it disabled for now. Save the changes.

Now go to your site’s frontend. Start browsing around. After a couple of minutes you should see the “Demo Store” application show up in your New Relic account, under the “Applications” tab. Click through to it to view more details. See below for an example of how the Application Overview page might look after hitting the site with traffic for 30 minutes:

Configuring New Relic application settings

At this point you may want to review the application settings by clicking on the “Settings” tab inside your New Relic application.

More specifically, look at the “Apdex T” value, which defines three thresholds (“satisfaction” tiers) for your app server’s response time. (Hover your mouse over the question mark for a brief explanation, or refer to this link for the documentation.) Changing the field’s value will also update the tooltip, which is useful to visualize what your different satisfaction tiers will be.

Since we want New Relic to log transactions that take more than two seconds (the “frustrating” threshold), make sure the Apdex T value is set to 0.5. You can also configure the threshold at which New Relic will log traces, but we’ll leave that at the default value.

Debugging performance issues

Back to our sample scenario. Here’s how the “Demo Store” Application Overview page would look like after installing the module in your server:

Notice how the curves suddenly spike? There’s a 3,000 ms total increase for both curves together, and it looks like much of that time is spent in Magento rather than the database.

Note on full-page caching: It’s worth mentioning that both the full-page cache and the block cache must be disabled to truly appreciate the impact in this limited scenario—otherwise the impact would be effective only on each first page load. Disabling caching also helps you see relevant performance information in New Relic for this particular case faster than you normally would.

Debugging transactions

Because the new module brings the server response time above the two-second “frustrating” threshold defined by your application’s Apdex T value, New Relic will automatically start to log those transactions. You will see them in a number of places:

• Monitoring > Overview: You’ll find the last few slow transactions and their traces listed under the “Transactions” heading, right below the graph.
• Monitoring > Transactions: This is a more detailed view of more transactions. You can sort them by different parameters and open them to view more details.

In this case we’ll go to the Monitoring > Transactions tab, which looks as follows:

Here we can also appreciate the performance decrease starting slightly before the 14:50 time mark. That’s about the time the module was activated in the server. We can see that the “/cms/page/view” route suddenly takes more than twice wall clock time. That’s because to create this screenshot I generated traffic against a single CMS page (using Siege or BlazeMeter). But if you generated traffic against all pages you would see an increase in all curves at the same time.

To continue our debugging process we’ll look into the most time-consuming transaction, which is the first one on the list. Because we added the code to the footer of the page, it doesn’t really matter which transaction you open (as long as it’s not from the admin area): All frontend pages have been slowed to a crawl! In a scenario where only a specific page is affected, open the transaction that corresponds to that page’s location.

Clicking on a transaction to view more details opens up an overlay:

In the transaction details overlay we can see the hit on performance more clearly. We also get a breakdown of the slowest performing “segments.” And finally (not visible in this screenshot) there’s a list of transaction “traces” that are extremely helpful in cases like this.

Drilling down: transaction traces

Traces are arguably one of the most important features of New Relic. (For more information on what they are and how to use them you can refer to the Transaction Trace documentation.)

At this point you should see a few slow traces. If there are any that have an incredibly high duration (e.g. 49 seconds) you can ignore them for now, they’re the odd ones out (you’ve probably been hitting the server with more traffic than it can handle). Open a trace on the 2-8 seconds range to drill down on the trace’s Overview tab:

The screenshot reveals some useful information on the Slowest components table:

• Several functions that belong to Mage_Eav and Mage_Core classes are being called 120 times. Eav classes called so many times probably means there’s going to be a lot of database calls.
• We can also see at least two database queries that are being called 120 times. This confirms our theory from the previous item.
• This is not a coincidence: In my database there are exactly 120 products that are marked as “featured” and are being displayed by the new module.

You can probably see what’s going on at this point, but before jumping to conclusions let’s drill deeper by going to the SQL statements tab within this Trace.

The SQL statements tab clearly shows there are not two but seven queries being executed around 120 times (you could see different results based on the number of products marked as “featured”).

What’s happening is clear: The defective module is loading products within an n+1 query loop. In other words: it’s making seven database calls for each product marked as “featured”—and there are 120 products!

Finding the bug

Finding the piece of code that’s causing this problem may not be as easy as the rest of this process, but a good developer should discover it within 15 minutes using the appropriate tools. In our case, here’s the piece of code that’s causing the trouble:

/**

* Produces the list of links

* @return string

*/

protected function _toHtml() {

  $collection = $this->_getCollection(); 

      /* see the next code-block to see the code 

         for _getCollection() */

  $count = $collection->count();

  /* (etc...) */



  foreach($collection as $product) {

     /** @var Mage_Catalog_Model_Product $product */

        /* NOTE: Doing this is a big mistake! The developer had to load each product *individually* because Magento won't pull the product name from the database and provide URL rewrite capabilities through the Product model *unless* the collection was configured correctly before loading */

        $product = Mage::getModel('catalog/product')

                     ->load($product->getId());

      // (etc ...)

  }

  // (etc ...)

}

Inside $this->_getCollection() we can see that the collection is set up to return only products that have the “featured” attribute marked as “true”:

$collection = Mage::getResourceSingleton( 

    'catalog/product_collection'

);

$collection->addAttributeToFilter( 

    'featured', 

    array('eq' => 1) 

);

Fixing the problem

This common performance antipattern can be solved by eager-loading the product information before entering the loop. Since our module shows a list of product names and their URLs then we need only eager-load those two attributes. And in Magento that’s very easy:

// optimized version

$collection->clear() // don’t load default data

  ->addAttributeToFilter('featured', array('eq' => 1))

  ->addAttributeToSelect('name') // eager-load names

  ->addUrlRewrite(); // eager-load product URLs

Once this is in place, we can safely delete the line that was loading product information within the loop:

foreach($collection as $product) {

  /** @var Mage_Catalog_Model_Product $product */

  // the evil line has been deleted!



  // (etc ...)

}

Finally, now that we made some changes let’s see if performance has been restored by checking the New Relic Application Overview page:

Thanks to New Relic we have quickly identified and efficiently fixed a huge performance bug that would have slowed the entire site by three seconds on every page. Delays like that could potentially cause an e-commerce operation to lose significant sales and customers as they abandon the site in frustration.

Guest author Gabriel Somoza is director of operations at Strategery, which specializes in building high-quality e-commerce stores and Web applications. He is also a Magento Certified Developer (Plus) and a Zend PHP 5 Certified Engineer .