magento-lts
magento-lts copied to clipboard
Long running queries presumably from layered navigation
Preconditions (*)
- Openmage 20.5.0
- PHP 8.1
- MariaDB 10.617
- Ubuntu 20.04
Steps to reproduce (*)
There are no specific steps to reproduce this , we just see it in the slow query logs
We keep observing some long running queries of this format
SELECT `extra_specs_idx`.`value`, COUNT(extra_specs_idx.entity_id) AS `count` FROM `catalog_product_entity` AS `e` INNER JOIN `catalog_category_product_index` AS `cat_index` ON cat_index.product_id=e.entity_id AND cat_index.store_id=1 AND cat_index.visibility IN(2, 4) AND cat_index.category_id = '15' INNER JOIN `catalog_product_index_price` AS `price_index` ON price_index.entity_id = e.entity_id AND price_index.website_id = '1' AND price_index.customer_group_id = 0 INNER JOIN `catalog_product_index_eav` AS `screen_size_idx` ON screen_size_idx.entity_id = e.entity_id AND screen_size_idx.attribute_id = 187 AND screen_size_idx.store_id = 1 AND screen_size_idx.value = '236' INNER JOIN `catalog_product_index_eav` AS `screen_type_idx` ON screen_type_idx.entity_id = e.entity_id AND screen_type_idx.attribute_id = 189 AND screen_type_idx.store_id = 1 AND screen_type_idx.value = '266' INNER JOIN `catalog_product_index_eav` AS `core_count_idx` ON core_count_idx.entity_id = e.entity_id AND core_count_idx.attribute_id = 193 AND core_count_idx.store_id = 1 AND core_count_idx.value = '41' INNER JOIN `catalog_product_index_eav` AS `memory_idx` ON memory_idx.entity_id = e.entity_id AND memory_idx.attribute_id = 197 AND memory_idx.store_id = 1 AND memory_idx.value = '61' INNER JOIN `catalog_product_index_eav` AS `primary_camera_idx` ON primary_camera_idx.entity_id = e.entity_id AND primary_camera_idx.attribute_id = 198 AND primary_camera_idx.store_id = 1 AND primary_camera_idx.value = '309' INNER JOIN `catalog_product_index_eav` AS `second_camera_idx` ON second_camera_idx.entity_id = e.entity_id AND second_camera_idx.attribute_id = 200 AND second_camera_idx.store_id = 1 AND second_camera_idx.value = '87' INNER JOIN `catalog_product_index_eav` AS `megethossim_idx` ON megethossim_idx.entity_id = e.entity_id AND megethossim_idx.attribute_id = 229 AND megethossim_idx.store_id = 1 AND megethossim_idx.value = '164' INNER JOIN `catalog_product_index_eav` AS `gdiktia_idx` ON gdiktia_idx.entity_id = e.entity_id AND gdiktia_idx.attribute_id = 232 AND gdiktia_idx.store_id = 1 AND gdiktia_idx.value = '168' INNER JOIN `catalog_product_index_eav` AS `ram_idx` ON ram_idx.entity_id = e.entity_id AND ram_idx.attribute_id = 196 AND ram_idx.store_id = 1 AND ram_idx.value = '52' INNER JOIN `catalog_product_index_eav` AS `nfcsosto_idx` ON nfcsosto_idx.entity_id = e.entity_id AND nfcsosto_idx.attribute_id = 258 AND nfcsosto_idx.store_id = 1 AND nfcsosto_idx.value = '376' INNER JOIN `catalog_product_index_eav` AS `extra_specs_idx` ON extra_specs_idx.entity_id = e.entity_id AND extra_specs_idx.attribute_id = 213 AND extra_specs_idx.store_id = '1' GROUP BY `extra_specs_idx`.`value`
Which pretty much never stop executing until they timeout
They appear to be related to counting terms for layered navigation.
The related tables range from 200 rows to 2000 rows so they're not extremely big and the execution shouldn't be that slow for any reason.
We have disabled showing the count in layered navigation
Here's another sample query with very long execution time and explain
# Time: 240405 7:37:19
# User@Host: db_domain3[db_domain3] @ localhost [127.0.0.1]
# Thread_id: 8345298 Schema: db_domain3 QC_hit: No
# Query_time: 140.075668 Lock_time: 0.000176 Rows_sent: 1 Rows_examined: 15
# Rows_affected: 0 Bytes_sent: 148
# Tmp_tables: 1 Tmp_disk_tables: 0 Tmp_table_sizes: 253976
# Full_scan: No Full_join: No Tmp_table: Yes Tmp_table_on_disk: No
# Filesort: Yes Filesort_on_disk: No Merge_passes: 0 Priority_queue: No
#
# explain: id select_type table type possible_keys key key_len ref rows r_rows filtered r_filtered Extra
# explain: 1 SIMPLE ram_idx ref PRIMARY,IDX_CATALOG_PRODUCT_INDEX_EAV_ENTITY_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_ATTRIBUTE_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_STORE_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_VALUE,idx_attribute_store_value_entity IDX_CATALOG_PRODUCT_INDEX_EAV_VALUE 4 const 2 2.00 100.00 100.00 Using where; Using index; Using temporary; Using filesort
# explain: 1 SIMPLE gdiktia_idx ref PRIMARY,IDX_CATALOG_PRODUCT_INDEX_EAV_ENTITY_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_ATTRIBUTE_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_STORE_ID,idx_attribute_store_value_entity IDX_CATALOG_PRODUCT_INDEX_EAV_ENTITY_ID 8 db_domain3.ram_idx.entity_id,const,const 1 1.00 100.00 100.00 Using index
# explain: 1 SIMPLE primary_camera_idx range PRIMARY,IDX_CATALOG_PRODUCT_INDEX_EAV_ENTITY_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_ATTRIBUTE_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_STORE_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_VALUE,idx_attribute_store_value_entity IDX_CATALOG_PRODUCT_INDEX_EAV_VALUE 4 NULL 2 2.00 75.00 25.00 Using where; Using index; Using join buffer (flat, BNL join)
# explain: 1 SIMPLE screen_resolution_idx eq_ref PRIMARY,IDX_CATALOG_PRODUCT_INDEX_EAV_ENTITY_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_ATTRIBUTE_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_STORE_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_VALUE,idx_attribute_store_value_entity PRIMARY 12 db_domain3.ram_idx.entity_id,const,const,const 1 1.00 100.00 100.00 Using index
# explain: 1 SIMPLE memory_idx eq_ref PRIMARY,IDX_CATALOG_PRODUCT_INDEX_EAV_ENTITY_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_ATTRIBUTE_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_STORE_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_VALUE,idx_attribute_store_value_entity PRIMARY 12 db_domain3.ram_idx.entity_id,const,const,const 1 1.00 100.00 100.00 Using index
# explain: 1 SIMPLE second_camera_idx eq_ref PRIMARY,IDX_CATALOG_PRODUCT_INDEX_EAV_ENTITY_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_ATTRIBUTE_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_STORE_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_VALUE,idx_attribute_store_value_entity PRIMARY 12 db_domain3.ram_idx.entity_id,const,const,const 1 1.00 100.00 100.00 Using index
# explain: 1 SIMPLE nfcsosto_idx eq_ref PRIMARY,IDX_CATALOG_PRODUCT_INDEX_EAV_ENTITY_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_ATTRIBUTE_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_STORE_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_VALUE,idx_attribute_store_value_entity PRIMARY 12 db_domain3.ram_idx.entity_id,const,const,const 1 1.00 100.00 100.00 Using index
# explain: 1 SIMPLE price_index eq_ref PRIMARY,IDX_CATALOG_PRODUCT_INDEX_PRICE_CUSTOMER_GROUP_ID,IDX_CATALOG_PRODUCT_INDEX_PRICE_WEBSITE_ID,IDX_CAT_PRD_IDX_PRICE_WS_ID_CSTR_GROUP_ID_MIN_PRICE PRIMARY 8 db_domain3.ram_idx.entity_id,const,const 1 1.00 100.00 100.00 Using index
# explain: 1 SIMPLE core_count_idx eq_ref PRIMARY,IDX_CATALOG_PRODUCT_INDEX_EAV_ENTITY_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_ATTRIBUTE_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_STORE_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_VALUE,idx_attribute_store_value_entity PRIMARY 12 db_domain3.ram_idx.entity_id,const,const,const 1 1.00 100.00 100.00 Using index
# explain: 1 SIMPLE megethossim_idx eq_ref PRIMARY,IDX_CATALOG_PRODUCT_INDEX_EAV_ENTITY_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_ATTRIBUTE_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_STORE_ID,IDX_CATALOG_PRODUCT_INDEX_EAV_VALUE,idx_attribute_store_value_entity PRIMARY 12 db_domain3.ram_idx.entity_id,const,const,const 1 1.00 100.00 100.00 Using index
# explain: 1 SIMPLE cat_index eq_ref PRIMARY,IDX_CAT_CTGR_PRD_IDX_PRD_ID_STORE_ID_CTGR_ID_VISIBILITY,15D3C269665C74C2219037D534F4B0DC PRIMARY 10 const,db_domain3.ram_idx.entity_id,const 1 1.00 100.00 100.00 Using where
# explain: 1 SIMPLE e eq_ref PRIMARY PRIMARY 4 db_domain3.ram_idx.entity_id 1 1.00 100.00 100.00 Using index
#
SET timestamp=1712291839;
SELECT `gdiktia_idx`.`value`, COUNT(gdiktia_idx.entity_id) AS `count` FROM `catalog_product_entity` AS `e`
INNER JOIN `catalog_category_product_index` AS `cat_index` ON cat_index.product_id=e.entity_id AND cat_index.store_id=1 AND cat_index.visibility IN(2, 4) AND cat_index.category_id = '17'
INNER JOIN `catalog_product_index_price` AS `price_index` ON price_index.entity_id = e.entity_id AND price_index.website_id = '1' AND price_index.customer_group_id = 0
INNER JOIN `catalog_product_index_eav` AS `screen_resolution_idx` ON screen_resolution_idx.entity_id = e.entity_id AND screen_resolution_idx.attribute_id = 188 AND screen_resolution_idx.store_id = 1 AND screen_resolution_idx.value = '234'
INNER JOIN `catalog_product_index_eav` AS `core_count_idx` ON core_count_idx.entity_id = e.entity_id AND core_count_idx.attribute_id = 193 AND core_count_idx.store_id = 1 AND core_count_idx.value = '41'
INNER JOIN `catalog_product_index_eav` AS `ram_idx` ON ram_idx.entity_id = e.entity_id AND ram_idx.attribute_id = 196 AND ram_idx.store_id = 1 AND ram_idx.value = '54'
INNER JOIN `catalog_product_index_eav` AS `memory_idx` ON memory_idx.entity_id = e.entity_id AND memory_idx.attribute_id = 197 AND memory_idx.store_id = 1 AND memory_idx.value = '62'
INNER JOIN `catalog_product_index_eav` AS `primary_camera_idx` ON primary_camera_idx.entity_id = e.entity_id AND primary_camera_idx.attribute_id = 198 AND primary_camera_idx.store_id = 1 AND primary_camera_idx.value = '315'
INNER JOIN `catalog_product_index_eav` AS `second_camera_idx` ON second_camera_idx.entity_id = e.entity_id AND second_camera_idx.attribute_id = 200 AND second_camera_idx.store_id = 1 AND second_camera_idx.value = '90'
INNER JOIN `catalog_product_index_eav` AS `megethossim_idx` ON megethossim_idx.entity_id = e.entity_id AND megethossim_idx.attribute_id = 229 AND megethossim_idx.store_id = 1 AND megethossim_idx.value = '164'
INNER JOIN `catalog_product_index_eav` AS `nfcsosto_idx` ON nfcsosto_idx.entity_id = e.entity_id AND nfcsosto_idx.attribute_id = 258 AND nfcsosto_idx.store_id = 1 AND nfcsosto_idx.value = '377'
INNER JOIN `catalog_product_index_eav` AS `gdiktia_idx` ON gdiktia_idx.entity_id = e.entity_id AND gdiktia_idx.attribute_id = 232 AND gdiktia_idx.store_id = '1' GROUP BY `gdiktia_idx`.`value`;
There also doesn't seem to be any form of lock causing this delay
Expected result (*)
- Queries run fast
Actual result (*)
- Queries timeout due to very long execution
Is the version you use in testing OpenMage v20.5.0 + Magento Sample Data?
I'm seeing this on a production site using OpenMage v20.5.0 so it's not using Magento Sample Data.
I've made sure it occurs with all 3rd party extensions removed as well.
It seems to come directly from core.
The more joins are added to the same table, the more the time of execution increases.
would it be possible for you to remove some of those attributes from "available in product listing"?
Actually most of them are already set to No
there are 9 visible in the query
I checked them all and only 3 were used in product listing. I changed them to No as well
Even after changing all to No I still get this query
SELECT `operating_system_idx`.`value`, COUNT(operating_system_idx.entity_id) AS `count`
FROM `catalog_product_entity` AS `e`
INNER JOIN `catalog_category_product_index` AS `cat_index` ON cat_index.product_id=e.entity_id AND cat_index.store_id=1 AND cat_index.visibility IN(2, 4) AND cat_index.category_id = '17'
INNER JOIN `catalog_product_index_price` AS `price_index` ON price_index.entity_id = e.entity_id AND price_index.website_id = '1' AND price_index.customer_group_id = 0
INNER JOIN `catalog_product_index_eav` AS `screen_resolution_idx` ON screen_resolution_idx.entity_id = e.entity_id AND screen_resolution_idx.attribute_id = 188 AND screen_resolution_idx.store_id = 1 AND screen_resolution_idx.value = '265'
INNER JOIN `catalog_product_index_eav` AS `screen_type_idx` ON screen_type_idx.entity_id = e.entity_id AND screen_type_idx.attribute_id = 189 AND screen_type_idx.store_id = 1 AND screen_type_idx.value = '39'
INNER JOIN `catalog_product_index_eav` AS `core_count_idx` ON core_count_idx.entity_id = e.entity_id AND core_count_idx.attribute_id = 193 AND core_count_idx.store_id = 1 AND core_count_idx.value = '41'
INNER JOIN `catalog_product_index_eav` AS `ram_idx` ON ram_idx.entity_id = e.entity_id AND ram_idx.attribute_id = 196 AND ram_idx.store_id = 1 AND ram_idx.value = '54'
INNER JOIN `catalog_product_index_eav` AS `primary_camera_idx` ON primary_camera_idx.entity_id = e.entity_id AND primary_camera_idx.attribute_id = 198 AND primary_camera_idx.store_id = 1 AND primary_camera_idx.value = '309'
INNER JOIN `catalog_product_index_eav` AS `megethossim_idx` ON megethossim_idx.entity_id = e.entity_id AND megethossim_idx.attribute_id = 229 AND megethossim_idx.store_id = 1 AND megethossim_idx.value = '164'
INNER JOIN `catalog_product_index_eav` AS `nfcsosto_idx` ON nfcsosto_idx.entity_id = e.entity_id AND nfcsosto_idx.attribute_id = 258 AND nfcsosto_idx.store_id = 1 AND nfcsosto_idx.value = '377'
INNER JOIN `catalog_product_index_eav` AS `operating_system_idx` ON operating_system_idx.entity_id = e.entity_id AND operating_system_idx.attribute_id = 195 AND operating_system_idx.store_id = '1'
GROUP BY `operating_system_idx`.`value`
I'm thinking that the culprit may be here as it's one of the few areas I can see that match the query about count(attribute_code_idx)
//app/code/core/Mage/Catalog/Model/Layer/Filter/Attribute.php:115
protected function _getItemsData()
{
$attribute = $this->getAttributeModel();
$this->_requestVar = $attribute->getAttributeCode();
$key = $this->getLayer()->getStateKey() . '_' . $this->_requestVar;
$data = $this->getLayer()->getAggregator()->getCacheData($key);
if ($data === null) {
$options = $attribute->getFrontend()->getSelectOptions();
$optionsCount = $this->_getResource()->getCount($this);
$data = [];
foreach ($options as $option) {
if (is_array($option['value'])) {
continue;
}
if (Mage::helper('core/string')->strlen($option['value'])) {
// Check filter type
if ($this->_getIsFilterableAttribute($attribute) == self::OPTIONS_ONLY_WITH_RESULTS) {
if (!empty($optionsCount[$option['value']])) {
$data[] = [
'label' => $option['label'],
'value' => $option['value'],
'count' => $optionsCount[$option['value']],
];
}
} else {
$data[] = [
'label' => $option['label'],
'value' => $option['value'],
'count' => $optionsCount[$option['value']] ?? 0,
];
}
}
}
$tags = [
Mage_Eav_Model_Entity_Attribute::CACHE_TAG . ':' . $attribute->getId()
];
$tags = $this->getLayer()->getStateTags($tags);
$this->getLayer()->getAggregator()->saveCacheData($data, $key, $tags);
}
return $data;
}
Check how I replicated it.
I went in a category page with 16 filters in the sidebar's layered navigation (smartphones as products which have a lot of filters)
I progressively started clicking on filters
At around 12 of them even if it was showing only one product. I reached a query like this
SELECT `manufacturer2_idx`.`value`, COUNT(manufacturer2_idx.entity_id) AS `count`
FROM `catalog_product_entity` AS `e`
INNER JOIN `catalog_category_product_index` AS `cat_index`
ON cat_index.product_id = e.entity_id AND cat_index.store_id = 1 AND
cat_index.visibility IN (2, 4) AND cat_index.category_id = '15'
INNER JOIN `catalog_product_index_price` AS `price_index`
ON price_index.entity_id = e.entity_id AND price_index.website_id = '1' AND
price_index.customer_group_id = 0
INNER JOIN `catalog_product_index_eav` AS `screen_resolution_idx`
ON screen_resolution_idx.entity_id = e.entity_id AND screen_resolution_idx.attribute_id = 188 AND
screen_resolution_idx.store_id = 1 AND screen_resolution_idx.value = '249'
INNER JOIN `catalog_product_index_eav` AS `screen_type_idx`
ON screen_type_idx.entity_id = e.entity_id AND screen_type_idx.attribute_id = 189 AND
screen_type_idx.store_id = 1 AND screen_type_idx.value = '37'
INNER JOIN `catalog_product_index_eav` AS `core_count_idx`
ON core_count_idx.entity_id = e.entity_id AND core_count_idx.attribute_id = 193 AND
core_count_idx.store_id = 1 AND core_count_idx.value = '41'
INNER JOIN `catalog_product_index_eav` AS `operating_system_idx`
ON operating_system_idx.entity_id = e.entity_id AND operating_system_idx.attribute_id = 195 AND
operating_system_idx.store_id = 1 AND operating_system_idx.value = '48'
INNER JOIN `catalog_product_index_eav` AS `ram_idx`
ON ram_idx.entity_id = e.entity_id AND ram_idx.attribute_id = 196 AND ram_idx.store_id = 1 AND
ram_idx.value = '52'
INNER JOIN `catalog_product_index_eav` AS `memory_idx`
ON memory_idx.entity_id = e.entity_id AND memory_idx.attribute_id = 197 AND
memory_idx.store_id = 1 AND memory_idx.value = '62'
INNER JOIN `catalog_product_index_eav` AS `primary_camera_idx`
ON primary_camera_idx.entity_id = e.entity_id AND primary_camera_idx.attribute_id = 198 AND
primary_camera_idx.store_id = 1 AND primary_camera_idx.value = '309'
INNER JOIN `catalog_product_index_eav` AS `second_camera_idx`
ON second_camera_idx.entity_id = e.entity_id AND second_camera_idx.attribute_id = 200 AND
second_camera_idx.store_id = 1 AND second_camera_idx.value = '87'
INNER JOIN `catalog_product_index_eav` AS `megethossim_idx`
ON megethossim_idx.entity_id = e.entity_id AND megethossim_idx.attribute_id = 229 AND
megethossim_idx.store_id = 1 AND megethossim_idx.value = '164'
INNER JOIN `catalog_product_index_eav` AS `nfcsosto_idx`
ON nfcsosto_idx.entity_id = e.entity_id AND nfcsosto_idx.attribute_id = 258 AND
nfcsosto_idx.store_id = 1 AND nfcsosto_idx.value = '377'
INNER JOIN `catalog_product_index_eav` AS `manufacturer2_idx`
ON manufacturer2_idx.entity_id = e.entity_id AND manufacturer2_idx.attribute_id = 186 AND
manufacturer2_idx.store_id = '1'
GROUP BY `manufacturer2_idx`.`value`
This query stopped working entirely giving timeout after 1 hour.
Unfortunately on the demo I can only apply 7-8 filters
They're not enough to test this on default
However check this URL:
After disabling cache open up this url which will load slightly fast.
https://demo.openmage.org/sale/women.html?apparel_type=33&color=18&length=84&occasion=31&price=220-&size=81&sleeve_length=45
It has 7 filters selected
Try to select the last filter
For me it took a couple of seconds more than the previous request.
Progressively adding more should showcase the issue
ah ok so those attributes are still filterable, I don't know if there's anything possible here, the query is very complex
True it's very complex but I think the problem is still that count query. Since I configured the backend not to show the count, shouldn't this count query be totally eliminated?
It also is a significant issue because it makes filters unusable after a point and also with crawlers in the mix it can bring a whole db server down because they will drill down through all the filters
I posted this on https://dba.stackexchange.com/questions/338347/why-is-this-query-running-so-slowly/338372#338372
Where Dan Black was kind enough to take a look at this. His last suggestion was to set the
optimizer_search_depth = 1
From the default value of 62 as suggested in this KB reference https://mariadb.com/kb/en/entity-attribute-value-implementation/ for EAV implementations.
As it turns out this can also be set for the session only and it made the query run instantly.
I was wondering if we can put this in the mix here because for pretty much all collection related queries that use many joins along so many tables it will give a performance boost.
I'm still exploring this over dba.stackexchange.com if you would like to add some input there as well for this.
I am thinking that basically this is only affecting OpenMage because it's using EAV system which is considered an anti-pattern. Therefore it wouldn't make sense in hosting environments to change this globally, and it may not be good for other types of queries so would it be possible to set it in the OpenMage DB adapter class?
@fballiano I found the way to mitigate this for now.
On local.xml there's a section called
<initStatements><![CDATA[SET NAMES utf8]]></initStatements>
I modified it like this for the site experiencing the issue
<initStatements><![CDATA[SET NAMES utf8;SET SESSION optimizer_search_depth = 1;]]></initStatements>
The problem is successfully mitigated for my case.
The underlying issue is still there though about the multiple joins and we need to find a permanent way to do this for the queries that actually suffer from this and not for the whole connection in my opinion.
For now though this helps