Interpreting profiler results on a slow page

Question

I'm still having major problems with configurable products and page load speeds. I have a configurable product with 530 associated products, each with around 4 custom options.

I'm also using SCP, but I don't think this either responsible or helping my load times, so am currently kinda ignoring it.

I have run the page profiler and this particular product takes 9.9 seconds to load, and the biggest (if I'm interpreting it correctly?) culprits are below:

__EAV_COLLECTION_LOAD_ATTR__ - 3.9239   
CONFIGURABLE:Mage_Catalog_Model_Product_Type_Configurable::getConfigurableAttributes - 4.8121
TTT2:Mage_Catalog_Model_Resource_Product_Type_Configurable_Attribute_Collection::_afterLoad - 4.5175
CONFIGURABLE:OrganicInternet_SimpleConfigurableProducts_Catalog_Model_Product_Type_Configurable::getUsedProducts - 4.5157

It seems the problem is "Magento" rather than the additional module as most of the time taken is on core Magento methods, if I'm right. As such is this just a limitation of configurable products? i.e. for a highly variable product, it's wise to keep to only a few associated products (which kinda defeats the object and is actually extremely limiting). All of my products are highly configurable, hence the choice, however I didn't realise it was so slow.

Is this a configuration issue, or a hardware issue, or will I just have to rethink the whole situation. Even if I upgraded hardware presumably it may speed up slightly but wouldn't be scalable and should that product ever increase in it's configurability the same "bottleneck" would be reached.

Is it the custom options attached to the product causing the issue and as such the actual configurable part is fine, it's just once you start loading up options?

And to finish, if you were tasked with creating a store where, for example, a "Candle" could have 1000 different permutations, i.e. colour, size, shape etc, and still maintain a scalable fast solution?

Any thoughts and ideas are appreciated on this as I initially posted a while back and was a bit vague, but have since done a bit of profiling and believe I've located (some) of the problem, just how to fix going forward.

Answer 1

The built-in Magento Profiler is crap. If you really want to see what is slowing down your page loading speeds I'd suggest using the PhpStorm IDE with Xdebug. If you are developing for Magento or are doing frequent code changes use PhpStorm else you can probably get away with using the Eclipse IDE. Using Xdebug you can run a profile on your pages and then view the output with WinCacheGrind or the built in profiler in PhpStorm and see the EVERYTHING, the WHOLE trace of function calls starting from when Magento gets the first request. Doing so, you can step deeper and deeper into each function and see the time it takes for each function to execute.

Speaking for personal experience one website I worked on had configurable product pages taking up to a minute or more to load, in some extreme cases even more than an hour! They too had hundreds of child products and hundreds of options in one configurable product. After a lot of tracing 90% of speed issues came from the custom built theme from the previous company that used to manage that particular Magento store.

The problem areas were nested loops and large product collections being re-instantiated each time inside the nested loops which will definitely cripple page speeds.

Now product pages load within 2-3 seconds, WITHOUT Magento caching enabled. With caching it's nearly instant, and this is a store with 380K products.

Besides the guide suggested by benmarks do check out that same TurnKeyes Magento Performance blog: http://turnkeye.com/blog/category/magento-performance/ they also released a Part 2 for improving Magento performance which is really good.

You can also use the caching technique mentioned here: http://turnkeye.com/blog/magento-performance-optimization-configurable-products-2/ on static sections of your website bypassing extra Magento function calls. One section that saved a good chunk of time was the navigation bar/menu. After applying the caching technique it saved a good second of loading time from each page load, but in exchange for having Magento remember which menu link you clicked on when selecting something from the dropdown.

Other suggestions, do review your website theme and comment out function calls that your website does not utilize. Since you are using APC, make sure you have 2-layered caching enabled.

PhpStorm: http://www.jetbrains.com/phpstorm/

Xdebug: http://xdebug.org/

WinCacheGrind: http://sourceforge.net/projects/wincachegrind/

Installing Xdebug with PhpStorm: http://confluence.jetbrains.com/display/PhpStorm/Xdebug+Installation+Guide

http://confluence.jetbrains.com/display/PhpStorm/Zero-configuration+Web+Application+Debugging+with+Xdebug+and+PhpStorm

Answer 2

Following a post on here from someone else regarding Collection Caching, it's apparently considered prudent to cache the block HTML output over the collection?

Whether this is true or not I'd like to know, however one thing I can report is that I added the below lines to the catalog_product_view node of my local.xml file for that specific page and my load times have increased by 80%, from 10.92 seconds to 2.21 seconds.

<action method="setCacheLifetime">
    <lifetime>3600</lifetime> <!-- Cache Lifetime of 1 hour -->
</action>

Hopefully this helps someone out as it appears my configurable products are now far more usable and indeed scalable. Thanks to benmarks for the head up on this.

Answer 3

If Magento code/function looks like this:

Varien_Profiler::start('TTT1:'.__METHOD__);
$this->_addProductAttributes();
Varien_Profiler::stop('TTT1:'.__METHOD__);
Varien_Profiler::start('TTT2:'.__METHOD__);
$this->_addAssociatedProductFilters();
Varien_Profiler::stop('TTT2:'.__METHOD__);
Varien_Profiler::start('TTT3:'.__METHOD__);
$this->_loadLabels();
Varien_Profiler::stop('TTT3:'.__METHOD__);
Varien_Profiler::start('TTT4:'.__METHOD__);
$this->_loadPrices();
Varien_Profiler::stop('TTT4:'.__METHOD__);

You know your dealing with a bottle neck. You don't need XDebug to figure that out, just common sence. Why else should there be 4 different profile statements in there ?

If you install a debugger and step through the code, you will see it loades ALL the attributes and then loop's trough them and takes a couple of them Magento actually needs and throws the rest away. And there also a couple of other bad programming practices going on. Like functions that only take single items and not list of items. So, if something is called inside this function, it will be inside a loop.

But Magento is very flexible, so you can write your own/better implementation of the logic (to bad they don't use interfaces). Just google for: 'Magento Configurable Product Performance Boost', copy past and hope it works. Or learn to program and fix it your selfs.

Here is a beter implementation that uses caching, but i'm not responible for it. Maybe e-mail the author: http://www.jg-dev.de/kontakt/

public function getUsedProducts($requiredAttributeIds = null, $product = null)
{
    Varien_Profiler::start('CONFIGURABLE:'.__METHOD__);
    if (!$this->getProduct($product)->hasData($this->_usedProducts)) {
        if (is_null($requiredAttributeIds)
            and is_null($this->getProduct($product)->getData($this->_configurableAttributes))) {
            // If used products load before attributes, we will load attributes.
            $this->getConfigurableAttributes($product);
            // After attributes loading products loaded too.
            Varien_Profiler::stop('CONFIGURABLE:'.__METHOD__);
            return $this->getProduct($product)->getData($this->_usedProducts);
        }

        $usedProducts = array();
        if (!Mage::app()->getStore()->isAdmin() && $product) {
            $locale = Mage::app()->getLocale();
            $cacheId = self::LOCALE_CACHE_KEY . $locale->getLocaleCode() . $product->getId();
            $usedProducts = Mage::app()->loadCache($cacheId);
        }

        if (empty($usedProducts)) {
            $collection = $this->getUsedProductCollection($product)
                ->addAttributeToSelect('*')
                ->addFilterByRequiredOptions()
            ;

            if (is_array($requiredAttributeIds)) {
                foreach ($requiredAttributeIds as $attributeId) {
                    $attribute = $this->getAttributeById($attributeId, $product);
                    if (!is_null($attribute))
                        $collection->addAttributeToFilter($attribute->getAttributeCode(), array('notnull'=>1));
                }
            }
            foreach ($collection as $item) {
                $item->unsetData('stock_item');
                $usedProducts[] = $item;
            }
            if (!Mage::app()->getStore()->isAdmin() && $product) {
                Mage::app()->saveCache(serialize($usedProducts), $cacheId, array(self::LOCALE_CACHE_TAG), self::LOCALE_CACHE_LIFETIME);
            }
        } else {
            $usedProducts = unserialize($usedProducts);
        }

        $this->getProduct($product)->setData($this->_usedProducts, $usedProducts);
    }
    Varien_Profiler::stop('CONFIGURABLE:'.__METHOD__);
    return $this->getProduct($product)->getData($this->_usedProducts);
}