5

Shop facts:

  • around 100 categories
  • but in the main category, there are ~ 70.000 products (because filtering is heavily used)

After moving a shop developed by us to a production server of an external hosting company, we experience the problem, that the php bin/magento index:reindex command is stuck during the catalog category index.

On our local systems, this action takes less than two minutes. On the production server it takes more than 1 hour (we did not wait longer) and SHOW PROCESSLIST\G in mysql shows:

*************************** 1. row ***************************
      Id: 538862
    User: shop_production
    Host: localhost
      db: shop_production
 Command: Query
    Time: 169
   State: Sending data
    Info: INSERT INTO `catalog_category_product_index_store2_tmp` (`category_id`, `product_id`, `position`, `i
Progress: 0.000
*************************** 2. row ***************************
      Id: 538888
    User: shop_production
    Host: localhost
      db: shop_production
 Command: Query
    Time: 136
   State: Sending data
    Info: INSERT INTO `catalog_category_product_index_store1_tmp` (`category_id`, `product_id`, `position`, `i
Progress: 0.000

The Time spent goes higher and higher.

The production system is based on CloudLinux, uses CageFS and Plesk.

The MariaDB version in use is similar, but different.

This is the diff between the configurations:

https://gist.github.com/amenk/049480614ac7ff1daf6b6cadbbcdacaf

  • How can this be debugged?
  • Did anybody have such a problem before and it rings a bell?

EDIT

  • mysql_upgrade -f shows no problems for the tables shop_production (but some in Plesk's )

Output of top during indexing:

top - 20:21:38 up 21 days,  2:36,  3 users,  load average: 1,76, 1,19, 0,95
Tasks: 216 total,   1 running, 215 sleeping,   0 stopped,   0 zombie
%Cpu(s): 22,7 us,  1,0 sy,  0,1 ni, 76,1 id,  0,0 wa,  0,0 hi,  0,0 si,  0,0 st
KiB Mem : 15878512 total,  1608264 free,  5029540 used,  9240708 buff/cache
KiB Swap:  4095996 total,  4095996 free,        0 used.  8572156 avail Mem 

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                   
3477819 mysql     20   0 3507868 813656  14688 S 168,8  5,1   4:27.35 mysqld                                    
3478187 shop-fo+  20   0  992172 180892  41912 S  18,6  1,1   0:19.42 php-fpm                                   
3478175 shop-fo+  20   0  907396  94840  38424 S  12,3  0,6   0:20.54 php-fpm                                   
2438090 root      30  10  481408  38412   1220 S   0,7  0,2  56:29.47 python2.7                                 
2438127 root      30  10  430592  59036   4380 S   0,7  0,4  49:54.24 python2.7                                 
      9 root      20   0       0      0      0 S   0,3  0,0  30:00.48 rcu_sched                                 
    584 root      20   0       0      0      0 S   0,3  0,0   5:07.81 jbd2/sda3-8                               
2438015 root      30  10  333944  39984   2832 S   0,3  0,3  22:22.89 python2.7                                 
2912509 root      20   0  919048  20148   1612 S   0,3  0,1  24:55.24 containerd                                
3127797 nginx     20   0   67228  13084   2644 S   0,3  0,1   4:13.13 nginx                                     
3127798 nginx     20   0   67584  13504   2640 S   0,3  0,1   2:39.75 nginx                                     
3127799 nginx     20   0   78492  22100   2632 S   0,3  0,1   2:15.81 nginx                                     
3373021 root      20   0  751756  26348  25416 S   0,3  0,2   0:10.24 rsyslogd                                  
3474176 root      20   0       0      0      0 S   0,3  0,0   0:00.14 kworker/4:0                               
3478507 postfix   20   0  106288   5184   4096 S   0,3  0,0   0:00.01 plesk_saslauthd                           
      1 root      20   0  191308   3808   2040 S   0,0  0,0  13:50.14 systemd                                   
      2 root      20   0       0      0      0 S   0,0  0,0   0:00.75 kthreadd                                  
      3 root      20   0       0      0      0 S   0,0  0,0   0:39.93 ksoftirqd/0                               
      5 root       0 -20       0      0      0 S   0,0  0,0   0:00.00 kworker/0:0H                    

Output of mytop:

MySQL on localhost (10.3.18-MariaDB)                                                                                                                                                                                up 0+00:05:45 [20:22:30]
 Queries: 74.1k  qps:  220 Slow:     0.0         Se/In/Up/De(%):    156/00/01/00 
         qps now:  197 Slow qps: 0.0  Threads:    8 (   8/   3) 165/01/00/00 
 Cache Hits: 46.5k Hits/s: 137.9 Hits now: 133.7  Ratio: 40.2% Ratio now: 41.2% 
 Key Efficiency: 99.7%  Bps in/out: 361.6k/474.6k   Now in/out: 501.3k/761.7k

      Id      User         Host/IP         DB      Time    Cmd Query or State                                                                                                                                                              
       --      ----         -------         --      ----    --- ----------                                                                                                                                                                  
    1 system us                                    0 Daemon InnoDB purge coordinator                                                                                                                                                    
    2 system us                                    0 Daemon InnoDB purge worker                                                                                                                                                         
    3 system us                                    0 Daemon InnoDB purge worker                                                                                                                                                         
    4 system us                                    0 Daemon InnoDB purge worker                                                                                                                                                         
    5 system us                                    0 Daemon InnoDB shutdown handler                                                                                                                                                     
      136     admin       localhost shop_produ         0  Query show full processlist                                                                                                                                                       
      186 shop_prod       localhost shop_produ         0  Sleep                                                                                                                                                                             
      187 shop_prod       localhost shop_produ         0  Sleep                                                                                                                                                                             
      188 shop_prod       localhost shop_produ         0  Sleep                                                                                                                                                                             
      189 shop_prod       localhost shop_produ         0  Sleep                                                                                                                                                                             
      275 shop_prod       localhost shop_produ         0  Query INSERT INTO `search_tmp_5da75fe6204cb3_57318472` SELECT `main_select`.`entity_id`, SUM(score) AS `relevance` FROM (SELECT DISTINCT `search_index`.`entity_id`, (((0) + (0) +
      153     admin       localhost        psa       148  Sleep                                                                                                                                                                             
      148 shop_prod       localhost shop_produ       151  Query INSERT INTO `catalog_category_product_index_store2_tmp` (`category_id`, `product_id`, `position`, `is_parent`, `store_id`, `visibility`) SELECT 2 AS `category_id`, `cp`.`en

EDIT2

This is the query which is hanging.

INSERT INTO `catalog_category_product_index_store2_tmp` (`category_id`, `product_id`, `position`, `is_parent`, `store_id`, `visibility`) SELECT 2 AS `category_id`, `cp`.`entity_id` AS `product_id`, IF(ccp.product_id IS NOT NULL, ccp.position, 0) AS `position`, IF(ccp.product_id IS NOT NULL, 1, 0) AS `is_parent`, 2 AS `store_id`, IFNULL(cpvs.value, cpvd.value) AS `visibility` FROM `catalog_product_entity` AS `cp`
 INNER JOIN `catalog_product_website` AS `cpw` ON cpw.product_id = cp.entity_id
 INNER JOIN `catalog_product_entity_int` AS `cpsd` ON cpsd.entity_id = cp.entity_id AND cpsd.store_id = 0 AND cpsd.attribute_id = 97
 LEFT JOIN `catalog_product_entity_int` AS `cpss` ON cpss.entity_id = cp.entity_id AND cpss.attribute_id = cpsd.attribute_id AND cpss.store_id = 2
 INNER JOIN `catalog_product_entity_int` AS `cpvd` ON cpvd.entity_id = cp.entity_id AND cpvd.store_id = 0 AND cpvd.attribute_id = 99
 LEFT JOIN `catalog_product_entity_int` AS `cpvs` ON cpvs.entity_id = cp.entity_id AND cpvs.attribute_id = cpvd.attribute_id  AND cpvs.store_id = 2
 LEFT JOIN `catalog_category_product` AS `ccp` ON ccp.product_id = cp.entity_id WHERE (cpw.website_id = '1') AND (IFNULL(cpss.value, cpsd.value) = 1) AND (IFNULL(cpvs.value, cpvd.value) IN (2, 3, 4)) AND (cp.entity_id IN ('107280', '107281', '107282', '107283', '107284', '107285', '107286', '107287', '107288', '107289', '107290', '107291', '107292', '107293', '107294', '107295', '107296', '107297', '107298', '107299', '107300', '107301', '107302', '107303', '107304', '107305',

[ ... around 700 Kilobyte of query in total ... ]

5', '187946', '187947', '187948', '187949', '187950', '187951', '187952', '187953', '187954', '187955', '187956', '187957', '187958', '187959', '187960', '187961', '187962', '187963', '187964', '187965', '187966')) GROUP BY `cp`.`entity_id` ON DUPLICATE KEY UPDATE `category_id` = VALUES(`category_id`), `product_id` = VALUES(`product_id`), `position` = VALUES(`position`), `is_parent` = VALUES(`is_parent`), `store_id` = VALUES(`store_id`), `visibility` = VALUES(`visibility`)

In the full query there are 73607 ",", so in the WHERE clause there are a bit less than 73600 values. I guess Magento is not very well prepared, that all products are in one category.

But still: It works locally, but not on the production server.

EDIT3 More debug Info

show global status\G;
show global variables\G;
show engine innodb status\G;

https://gist.github.com/amenk/424acf3567486f4f94cb3086e6bf3380

EDIT5 Version without \G:

https://gist.github.com/amenk/7d6a94536b28b4564a611e6adbdc1a3c

EDIT4

The problem can be reproduced locally by

  • Starting MariaDB 10.3.18 in a docker container
  • Importing the Prod database
  • Reindexing

So it is related to that specific database version in combination with the massive queries Magento runs, that were running fine on previous versions.

  • 1
    @MagenX thanks, information added – Alex Oct 16 at 18:23
  • 1
    @alex Why are you already running 10.3.18 that just became GA on 9/11/2019? Many people would avoid new version for 6 calendar months to avoid the 'bug' reporting, wait for corrective action cycle for any production system. But since you are here, we can try to rescue your situation, if you will post additional information listed in previous comment. – Wilson Hauck Oct 17 at 19:41
  • 1
    @WilsonHauck More debug info added in EDIT3 above, SHOW CREATE TABLE Is not working ,because the table is temporary and seems to be inside a transaction. The 10.3.18 version is supplied by the hoster, that was not our choice. It currently looks like I might be able to reproduce it with that version locally. – Alex Oct 18 at 16:15
  • 1
    @WilsonHauck okay, here you go: gist.github.com/amenk/7d6a94536b28b4564a611e6adbdc1a3c – Alex Oct 19 at 7:22
  • 1
    It's 8 vCore, datastorage is currently unkown for me. It does not seem to be a hardware-dependent problem, as I can now reproduce locally where it worked with 10.1 but does not with 10.3. Unfortunately downgrading might not be so easy, but still easier than debugging this all to the bones :) SET GLOBAL innodb_buffer_pool_size to 8GB did not have a drastic effect (still takes more > 5 minutes, stopped the script then) – Alex Oct 19 at 15:49
4

@Alex In your value list of id's to be managed, the quotes are likely causing the processing to work harder than when you use simply the number to be managed as an INT data type. If you find this suggestion helpful, please consider upvote and accept.

5

And another Answer --- thanks to the Chat with Wilson Hauck:

He pointed out, that the quotes might confuse the new optimized in 10.3

I took the full query.sql from above and extracted only the select part:

SELECT 2 AS `category_id`, `cp`.`entity_id` AS `product_id`, IF(ccp.product_id IS NOT NULL, ccp.position, 0) AS `position`, IF(ccp.product_id IS NOT NULL, 1, 0) AS `is_parent`, 2 AS `store_id`, IFNULL(cpvs.value, cpvd.value) AS `visibility` FROM `catalog_product_entity` AS `cp`
 INNER JOIN `catalog_product_website` AS `cpw` ON cpw.product_id = cp.entity_id
 INNER JOIN `catalog_product_entity_int` AS `cpsd` ON cpsd.entity_id = cp.entity_id AND cpsd.store_id = 0 AND cpsd.attribute_id = 97
 LEFT JOIN `catalog_product_entity_int` AS `cpss` ON cpss.entity_id = cp.entity_id AND cpss.attribute_id = cpsd.attribute_id AND cpss.store_id = 2
 INNER JOIN `catalog_product_entity_int` AS `cpvd` ON cpvd.entity_id = cp.entity_id AND cpvd.store_id = 0 AND cpvd.attribute_id = 99
 LEFT JOIN `catalog_product_entity_int` AS `cpvs` ON cpvs.entity_id = cp.entity_id AND cpvs.attribute_id = cpvd.attribute_id  AND cpvs.store_id = 2
 LEFT JOIN `catalog_category_product` AS `ccp` ON ccp.product_id = cp.entity_id WHERE (cpw.website_id = '1') AND (IFNULL(cpss.value, cpsd.value) = 1) AND           (IFNULL(cpvs.value, cpvd.value) IN (2, 3, 4)) AND (cp.entity_id IN ('107280', '107281', '107282', '107283', '107284'
    [... around 70 K entity IDs ...]
    187965', '187966')) GROUP BY `cp`.`entity_id`;

This query alone runs 8 minutes on Maria DB 10.3.18

When I simply remove all the quotes via s/'//g in vi in the line with the "IN" statement I get

SELECT 2 AS `category_id`, `cp`.`entity_id` AS `product_id`, IF(ccp.product_id IS NOT NULL, ccp.position, 0) AS `position`, IF(ccp.product_id IS NOT NULL, 1, 0) AS `is_parent`, 2 AS `store_id`, IFNULL(cpvs.value, cpvd.value) AS `visibility` FROM `catalog_product_entity` AS `cp`
 INNER JOIN `catalog_product_website` AS `cpw` ON cpw.product_id = cp.entity_id
 INNER JOIN `catalog_product_entity_int` AS `cpsd` ON cpsd.entity_id = cp.entity_id AND cpsd.store_id = 0 AND cpsd.attribute_id = 97
 LEFT JOIN `catalog_product_entity_int` AS `cpss` ON cpss.entity_id = cp.entity_id AND cpss.attribute_id = cpsd.attribute_id AND cpss.store_id = 2
 INNER JOIN `catalog_product_entity_int` AS `cpvd` ON cpvd.entity_id = cp.entity_id AND cpvd.store_id = 0 AND cpvd.attribute_id = 99
 LEFT JOIN `catalog_product_entity_int` AS `cpvs` ON cpvs.entity_id = cp.entity_id AND cpvs.attribute_id = cpvd.attribute_id  AND cpvs.store_id = 2
 LEFT JOIN `catalog_category_product` AS `ccp` ON ccp.product_id = cp.entity_id WHERE (cpw.website_id = '1') AND (IFNULL(cpss.value, cpsd.value) = 1) AND           (IFNULL(cpvs.value, cpvd.value) IN (2, 3, 4)) AND (cp.entity_id IN (107280, 107281, 107282, 107283, 107284
    [... around 70 K entity IDs ...]
    187965, 187966)) GROUP BY `cp`.`entity_id`;

The essentially same query runs in less than 3 seconds.

Gotcha!

Magento issue: https://github.com/magento/magento2/issues/25199 MariaDB issue: https://jira.mariadb.org/browse/MDEV-20871

  • Please let us know status from the Magento MDEV-20871 open issue in a week or so. It is not obvious looking at the issue details you went from 8 Minutes to 3 seconds for query completion. Please consider attributing the suggestion to our website. Thanks – Wilson Hauck Oct 22 at 15:32
  • Since this has been reported to MariaDB with MDEV-20871, they may or may not 'cover' this coding error of using quotes in the 'selection' IN list. Please consider reporting this discovery to Magento for their corrective action since it is their code that should not be using quoted IN values when their datatype is INT. Please report this discovery to Magento for their code correction to benefit their World Wide Base of customers with 3 second completion vs 8 minutes when dealing with 70,000 items in the catalog. 480 / 3 = 160 times faster completion of this query. – Wilson Hauck Oct 25 at 10:34
  • 1
    See the issue link in the Magento tracker, already done – Alex Oct 25 at 16:18
  • @Alex Could you please help me on this question. magento.stackexchange.com/questions/293336/… – Kirti Nariya Oct 31 at 5:39
2

I would suggest you to create a temporary Table. Only one Column, which is the category entity Id afterwards make an insert statement to insert all entity ids into this tmp table. Afterwards convert the way to big in condition into an Join.

  • Does that mean I have to patch the magento core? – Alex Oct 19 at 6:41
  • 1
    Beware: This is standard Magento code -- we did not customize anything in this regards, only we have lots of products in the category. In MariaDB 10.1 it works pretty well though, just not in MariaDB 10.3 – Alex Oct 19 at 7:30
  • 1
    Yes patch or write a Plugin. Yes its standard Magento stuff. Bur magento declined mysql only optimations so they can switch the engines. I already made a pull request with optimations was declined with the argument this is a mysql only optimation. – sqlexception Oct 19 at 10:02
  • Ah okay, we will consider that, if the hoster is not able to downgrade MariaDB to a supported version. – Alex Oct 19 at 12:23
  • Okay if u need help, i poked you on twitter. Anyways it will be faster. – sqlexception Oct 19 at 13:06
1

Partial answer - better debugging welcome.

Turns out that the issue is reproducible with MariaDB 10.3.18 locally as well.

According to DevDocs "Magento is also compatible with MySQL NDB Cluster 7.4.*, MariaDB 10.0, 10.1, 10.2, Percona 5.7, and other binary-compatible MySQL technologies."

This does not mention 10.3.x

1

Rate per Second=RPS - Suggestions to consider for your MariaDB 10.3.18 instance my.cnf [mysqld] section

innodb_buffer_pool_size=8G  # from 512M to reduce innodb_buffer_pool_reads RPS of ~ 5
innodb_io_capacity=1900  # from 200 to enable higher IOPS to your data devices
read_buffer_size=256K  # from 128K to reduce handler_read_next RPS of 136,418
read_rnd_buffer_size=128K  # from 256K to recude handler_read_rnd_next RPS of 320,764

There are many more tuning opportunities to improve performance. After implementation + 24 hours, please post observation of better/worse from your client's perspective.

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.