7

Issue:

Product save has become incrementally slower over the past 12 months

Background:

  • Magento Enterprise 1.14.1 (Issue also present in 1.13.0.2)
  • ~15,000 Products, ~700 Categories, 2 Stores
  • Solr 3.6

Investigation:

After the slower product save became an issue we investigate the slow query log an found the same query popping up: "UPDATE `catalogsearch_query` SET `is_processed`=0" coming in at around 2-3 seconds, running the same on local this was upping to 7-10 seconds.

The reason for this slow query is the site is search heavy and they're over 400,000 rows in in the catalogsearch_query table that are all being updated with a 0 which isn't a huge amount of data to store in a MySQL table but is a huge amount to update on such a frequent event.

To make matters worse after xdebugging the process Magento is hitting the Mage_CatalogSearch_Model_Resource_Fulltext::resetSearchResults() method 5 times during each product save off the back of catalog_product_save_commit_after event calling Enterprise_CatalogSearch_Model_Observer::processProductSaveDeleteEvent()

So 5 times * 3 seconds results in 15 seconds being added to each product save. 5 times seems overkill and it seems an oversight that the resetSearchResults() is called so many times at the end of the process triggered by this observer.

Investigating further there seems to be very little use for this is_processed field in the database when the Solr integration is in place.

  1. Has anyone ran into this issue?
  2. What actions did you take?
  3. Any suggestions for approaching?

My initial thoughts is to restructure the process to remove the query on the catalogsearch_query after fully investigating its impact.

  • Did you try rebuilding the index on the db table? Most of the time the index on the table is the reason. – andy1786 Jan 27 '15 at 20:48
  • There is no index for catalogsearch_query, there wouldn't really be a need for it with how the data is used. The issue is more an inefficiency with Magento core code structure larger datasets. – john-jh Jan 28 '15 at 7:46
5

I'm running into this issue while upgrading from EE 1.13.0.2 to 1.14.1.0 right now. We experience this when bulk updating product attributes and stock in cronjobs. In 1.13, the jobs take ~3 seconds and ~90 seconds respectively. In 1.14, it's more like ~10 minutes and I-don't-want-to-know-how-long.

There is an EE patch PATCH_SUPEE-4945_EE_1.14.0.1_v2.sh regarding the slow product save. You can request it from the support.

Another tip I found was to only update the rows which are not set to 0 already (of course only change the core file temporarily to test if it has any effect for you):

diff --git a/app/code/core/Enterprise/CatalogSearch/Model/Index/Action/Fulltext/Refresh.php b/app/code/core/Enterprise/CatalogSearch/Model/Index/Action/Fulltext/Refresh.php
index c6273a1..95e6d4c 100644
--- a/app/code/core/Enterprise/CatalogSearch/Model/Index/Action/Fulltext/Refresh.php
+++ b/app/code/core/Enterprise/CatalogSearch/Model/Index/Action/Fulltext/Refresh.php
@@ -668,7 +668,7 @@ class Enterprise_CatalogSearch_Model_Index_Action_Fulltext_Refresh
     protected function _resetSearchResults()
     {
         $adapter = $this->_getWriteAdapter();
-        $adapter->update($this->_getTable('catalogsearch/search_query'), array('is_processed' => 0));
+        $adapter->update($this->_getTable('catalogsearch/search_query'), array('is_processed' => 0), array('is_processed != 0'));
         $adapter->delete($this->_getTable('catalogsearch/result'));

         $this->_app->dispatchEvent('enterprise_catalogsearch_reset_search_result', array());
diff --git a/app/code/core/Mage/CatalogSearch/Model/Resource/Fulltext.php b/app/code/core/Mage/CatalogSearch/Model/Resource/Fulltext.php
index ee8b1c3..1d89146 100755
--- a/app/code/core/Mage/CatalogSearch/Model/Resource/Fulltext.php
+++ b/app/code/core/Mage/CatalogSearch/Model/Resource/Fulltext.php
@@ -299,7 +299,7 @@ class Mage_CatalogSearch_Model_Resource_Fulltext extends Mage_Core_Model_Resourc
     public function resetSearchResults()
     {
         $adapter = $this->_getWriteAdapter();
-        $adapter->update($this->getTable('catalogsearch/search_query'), array('is_processed' => 0));
+        $adapter->update($this->getTable('catalogsearch/search_query'), array('is_processed' => 0), array('is_processed != 0'));
         $adapter->delete($this->getTable('catalogsearch/result'));

         Mage::dispatchEvent('catalogsearch_reset_search_result');

And last, there was a recommendation to add an index to the is_processed column:

ALTER TABLE `database`.`catalogsearch_query` ADD INDEX `IDX_CATALOGSEARCH_QUERY_IS_PROCESSED` (`is_processed`) COMMENT '';

I've tried all of them and while they brought minor performance improvements none of them got me near the performance of EE 1.13.

An easy fix (on the surface) would be to add back

if (!$this->_isFulltextOn()) {
    return $this;
}

at the beginning of execute() for these classes:

  • Enterprise_CatalogSearch_Model_Index_Action_Fulltext_Refresh
  • Enterprise_CatalogSearch_Model_Index_Action_Fulltext_Refresh_Changelog
  • Enterprise_CatalogSearch_Model_Index_Action_Fulltext_Refresh_Row

If I do that, the code following isn't executed because Solr is configured to be used. As the core team deprecated this method for 1.14 it's ugly though and I'll try to stay away from that at all costs.

I'm only investigating this since yesterday so I hope I can follow up with a proper solution.

Update 09.02.2015

I found out by creating a xdebug profile dump that the communication between Magento and Solr takes up most of the time System > Configuration > Advanced > Index Management > Index Options > Catalog Search Index is set to Update on Save. Setting the Catalog Search Index to Update when scheduled significantly improves the speed.

Update 03.03.2015

In the meanwhile, the Enterprise support explained why $this->_isFulltextOn() is deprecated:

We removed $this->_isFulltextOn() from execute method because we refactored current mysql_fulltext indexer to encapsulate actual indexing work and adapt Catalog Search SOLR Index to use new Mview based indexer model.

The Enterprise_CatalogSearch module implemented new indexer model which utilizes changelog for partial reindexing. Currently when SOLR is used as catalog search engine, the catalogsearch_fulltext indexer falls back to use old indexer model. We utilize the new indexer model in Enterprise_CatalogSearch module when SOLR is set as catalog search engine.

Therefore, if merchant wants to skip fulltext indexation while saving products, please ask him/her to change index mode to update on schedule.

So the official solution pretty much is to change the Index Mode to Update when scheduled. We're using it for a few weeks without problems now. If your cron is running every minute you'll experience only a minor delay until the search is updated.

  • I'm in the middle of investigating having the search index set to update on schedule rather than update on save. Getting under 1 second product save at the moment down from 15-30 seconds. It's not a fix to the process but the alternative index method will result in the incremental index schedule handling the changes rather than the users request. Just need to investigate if the scheduled indexer suffers from the same issue. – john-jh Feb 3 '15 at 14:11
-2

Also check that your log tables are clean and not bloated. This can normally account for 95% of the database size and performance degradation if not correctly maintained.

Run this command on SSH console from within your website root:

php -f shell/log.php status

and to safely clean

php -f shell/log.php clean

  • It's not related to the log files at all. I've stepped through every part of the process with xdebug and it's purely the query mentioned above running 5 times and taking 3 seconds or more each time due to it updating every row in the catalogsearch_query table (400,000+ rows). – john-jh Jan 28 '15 at 7:43
  • I disagree as the size of your overall database can impact all queries irrelevant of size. If like I've seen before the log_* tables are taking up 80% of the database size then that is innodb_buffer_pool memory being wasted. Since default Magento search always sets the relevance to 0 as per the query you are seeing running you might want to review changing this option: System → Configuration → Catalogue → Catalog Search → Search Type Related answer to the same question: stackoverflow.com/questions/9117162/… – Stuart Jan 29 '15 at 13:07
  • The database is under 6GB (tiny) the logs are cleaned after 30 days by the cron. We're using Solr not MySQL Fulltext so the issue in the linked post isn't quite there. Like I've said before 400,000+ rows in catalogsearch_query all being updates 5 times on each product save is going to be slow and from what I can work out at the moment isn't needed. It's not setting the relevance to 0 it's setting the is_processing value to 0 – john-jh Jan 29 '15 at 15:27
-3

We have always found that when you have to start changing the core functionality it opens up a whole host of problems. Now there is the high likelihood of custom functionality or an extension causing the problem, obviously the simplest is to switch all that off and then try, preferably on a site copy. We found in the past a truncate and reindex can help, again with a backup. We run on different setup which is preventative and therefore does not run in to these issues, but that would not be applicable in your case.

  • It is not due to 3rd party functionality. If you read the issue again there's a full breakdown of what's happening, how and why, it's all core. – john-jh Jan 28 '15 at 13:39
  • Incorrect, on a business view worked on sites with Solr, over 100,000 products, 15stores, and never an issue. Now it may be because of inadequate servers, or an extension or custom functionality but the core works perfectly fine with much larger installs. The core is not the problem, now it may be your site and how it interacts with the core but that is something different. – Acornia Jan 28 '15 at 16:08
  • How many rows in the catalogsearch_query table though? Core Magento EE calls "UPDATE catalogsearch_query SET is_processed=0" 5 times on each product save, meaning it has to update ~400,000 5 times. That's 2,000,000 row updates per product save. 400,000 updates in 2 seconds I wouldn't class as slow. – john-jh Jan 28 '15 at 16:48

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.