Case Study : How a simple code change had a major impact on website performance
During black Friday sale, one of our customers’ websites was too slow and unusable for long periods. We were embarrassed, but all our analysis pointed to code. As part of our active support, we help with identifying code bottlenecks. We use many techniques including profiling, but a simple technique for a really slow website is analyzing the php slow log.
Observations
We track slowest URLs and chart them on our dashboard. A typical days chart looked like the one below. Most of the slow URLs were category listing page urls.
What is the php slow log?
The PHP slow request log is where PHP records information about any request that takes more than “x” seconds to execute. The number of seconds is configurable in the php-fpm.d/www.conf file.
The PHP slow request log records stack traces (also known as tracebacks) of each slowly executing script at the moment the request passed “x” seconds in execution. For example the following trace was generated for the website we were optimizing. The first line gives the date and time, the php-fpm pool name and the pid of the fpm process. The second line names the script – for Magento it will be the index.php always. The following lines have the memory address, the function name, the file name and the line number. A stack trace always lists the last call first.
[03-Dec-2020 22:54:57] [pool www] pid 19267
script_filename = /www/usa/index.php
[0x00007ffa5ec21d30] execute() /home2/customer/77faf58/vendor/magento/zendframework1/library/Zend/Db/Statement/Pdo.php:228
[0x00007ffa5ec21c80] _execute() /home2/customer/77faf58/vendor/magento/framework/DB/Statement/Pdo/Mysql.php:93
[0x00007ffa5ec21be0] _execute() /home2/customer/77faf58/vendor/magento/zendframework1/library/Zend/Db/Statement.php:303
[0x00007ffa5ec21b30] execute() /home2/customer/77faf58/vendor/magento/zendframework1/library/Zend/Db/Adapter/Abstract.php:480
[0x00007ffa5ec21aa0] query() /home2/customer/77faf58/vendor/magento/zendframework1/library/Zend/Db/Adapter/Pdo/Abstract.php:238
[0x00007ffa5ec219d0] query() /home2/customer/77faf58/vendor/magento/framework/DB/Adapter/Pdo/Mysql.php:541
[0x00007ffa5ec218a0] _query() /home2/customer/77faf58/vendor/magento/framework/DB/Adapter/Pdo/Mysql.php:615
[0x00007ffa5ec21810] query() /home2/customer/77faf58/vendor/magento/zendframework1/library/Zend/Db/Adapter/Abstract.php:737
[0x00007ffa5ec21760] fetchAll() /home2/customer/77faf58/vendor/magento/framework/Data/Collection/Db/FetchStrategy/Query.php:21
[0x00007ffa5ec216e0] fetchAll() /home2/customer/77faf58/vendor/magento/framework/DB/Query.php:182
[0x00007ffa5ec21660] fetchAll() /home2/customer/77faf58/vendor/magento/framework/Data/AbstractSearchResult.php:233
[0x00007ffa5ec215c0] load() /home2/customer/77faf58/vendor/magento/framework/Data/AbstractSearchResult.php:107
[0x00007ffa5ec21550] getItems() /home2/customer/77faf58/vendor/magento/module-catalog-inventory/Model/StockRegistryProvider.php:143
[0x00007ffa5ec21440] getStockItem() /home2/customer/77faf58/vendor/magento/module-catalog-inventory/Model/StockRegistry.php:88
[0x00007ffa5ec213c0] getStockItem() /home2/customer/77faf58/vendor/magento/module-catalog-inventory/Model/Plugin/AfterProductLoad.php:40
[0x00007ffa5ec212b0] afterLoad() /home2/customer/77faf58/vendor/magento/framework/Interception/Interceptor.php:146
[0x00007ffa5ec21150] Magento\Framework\Interception\{closure}() /home2/customer/77faf58/vendor/magento/framework/Interception/Interceptor.php:153
[0x00007ffa5ec21070] ___callPlugins() /home2/customer/77faf58/generated/code/Magento/Catalog/Model/Product/Interceptor.php:65
[0x00007ffa5ec20fe0] load() /home2/customer/77faf58/app/code/Plazathemes/Bestsellerproduct/Block/Bestsellerproduct.php:112
[0x00007ffa5ec20ef0] getBestsellerProduct() /home2/customer/77faf58/app/code/Mageplaza/CatalogPermissions/Observer/ProductLoadAfter.php:79
How do you trace from a hit to a slow log entry
From nginx we can trace to the slow log using a match in the php-fpm access log. We format nginx and php access log in a way that helps tracing.
The nginx log entry that we traced using the format
$remote_addr|$remote_user|$time_local|$request_time|$upstream_response_time|$request|$status|$body_bytes_sent|$http_referer|$http_user_agent|$host|$upstream_addr
127.0.0.1|-|03/Dec/2020:22:55:01 -0600|8.966|8.967|GET /usa/health-and-rejuvenation/cereals-health-mix HTTP/1.1|200|20458|https://www.ishalife.com/usa/yoga-gear/bedding|Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.66 Safari/537.36|www.ishalife.com|10.120.0.7:9000
php access log format used
access.format = %R - %u %t %m %r%Q%q %s %f %{mili}d %{kilo}M %{total}C%% %p
php access log entry to the traced url (matched by time and response time)
10.120.0.2 - 03/Dec/2020:22:54:52 -0600 GET /usa/index.php 200 /home2/customer/www/usa/index.php 8962.264 4096 48.20% 19267
The %p records the process id of php-fpm that processed this hit. Based on the time and process id, the slow log entry can be accurately traced.
Analysis
The stack trace clearly indicated that an observer was called when the event “ProductLoadAfter” was called. For this website, it slowed down the category display as the call was made for each product. A peep into the code in productloadafter observer was loading “Best Seller Products”. So, for each product in the category, it would load the (almost) identical set of best seller products. The observer object was not even used.
Let us look at the code
public function execute(Observer $observer)
{
/** @var AbstractCollection $productCollection */
$productCollection = $this->productBest->getBestsellerProduct();
foreach ($productCollection as $key => $product) {
/** @var product $product */
$productObject = $this->productRepo->getById($product->getId());
if ($this->helperData->validateConditionDefault($productObject, ObjectTypeAction::TYPE_PRODUCT)
&& !$this->helperData->checkIPPassAllRestrict()
) {
/** @var DataObject $productObject */
if ($productObject->getData('mpcp_usecf_hideaction') === '0'
&& $this->helperData->getProductHideCatAndWidget()) {
$productCollection->removeItemByKey($key);
}
// do not use config hide action
if (!$productObject->getData('mpcp_usecf_hideaction')
&& $productObject->getData('mpcp_hideaction') === '1') {
$productCollection->removeItemByKey($key);
}
}
}
}
The solution
Remove the observer as apart from badly written, the result was never used on the website. Code analysis revealed 2 unused plugins.
2 unused plugins and 1 observer call was removed, resulting some category pages loading 10x faster!
Before and After stats
We monitor hits in real time and chart hits / minute and avg response time per minute. In the graphs below, the left axis is hits per minute (plotted in turquoise) and the right axis is average response time in seconds per minute (plotted in black).
BEFORE
AFTER
CPU usage of php servers
BEFORE
AFTER
Database CPU usage across multiple days
Conclusion
The importance on good code and possibly the negative effects of unused functionality was highlighted in this case study.
As users of plugins we need to understand the motivation of plugin vendors to pack in substantial functionality leads to undesired side effects, especially on functionality you don't want to use. Budget to clean up vendor code before using.
