[MDEV-15332] Slow query performance from 10.1.29 Created: 2018-02-16  Updated: 2023-10-03

Status: Stalled
Project: MariaDB Server
Component/s: None
Affects Version/s: 10.1.29, 10.2
Fix Version/s: 10.2

Type: Bug Priority: Major
Reporter: Silver Asu Assignee: Sergei Petrunia
Resolution: Unresolved Votes: 2
Labels: None

Attachments: File dz_reduced2.sql.7z    

 Description   

This query is very slow from MariaDB 10.1.29. Also slow with all 10.2 versions
Mariadb 10.1.28 is OK. MySQL 5.7.21 is OK.

SELECT c.id,count(*) AS count,c.group_id FROM cattypes c
LEFT JOIN cattypegroups g ON c.group_id=g.id
RIGHT JOIN itemtocattypes i2c ON i2c.cattypeid=c.id
LEFT JOIN items i ON i2c.itemid=i.id
INNER JOIN itemtocatalogues i2cat ON (i2cat.itemid=i.id AND i2cat.catalogueid=117)
WHERE (g.catalogueid=117 OR g.id=378 AND g.ispricegroup)
AND i.active=1 AND i.dead=0
GROUP BY c.id

Dump file: https://www.upload.ee/files/8044172/dz_reduced2.zip.html



 Comments   
Comment by Alice Sherepa [ 2018-02-19 ]

I tried to reproduce the issue but get little bit different results. On 10.1.28-10.1.31 time of execution was nearly the same for me, around 4-5s. On 10.2.10+10.2.13 it is around 7s, but if I execute it again, then it takes 12-20s.
Query plan was the same, except for examined "rows" for "i2c" table and syntax of parentheses in conditions.

10.2.10

MariaDB [test]> analyze format=json  SELECT c.id,count(*) AS COUNT,c.group_id FROM cattypes c LEFT JOIN cattypegroups g ON c.group_id=g.id RIGHT JOIN itemtocattypes i2c ON i2c.cattypeid=c.id LEFT JOIN items i ON i2c.itemid=i.id INNER JOIN itemtocatalogues i2cat ON (i2cat.itemid=i.id AND i2cat.catalogueid=117) WHERE (g.catalogueid=117 OR g.id=378 AND g.ispricegroup) AND i.active=1 AND i.dead=0 GROUP BY c.id;
+---------------------------------------------------------------------------------------------------------------------------------------------------
| ANALYZE                                                                                                                                           
| {
  "query_block": {
    "select_id": 1,
    "r_loops": 1,
    "r_total_time_ms": 15119,
    "filesort": {
      "sort_key": "c.`id`",
      "r_loops": 1,
      "r_total_time_ms": 0.0157,
      "r_used_priority_queue": false,
      "r_output_rows": 91,
      "r_buffer_size": "2Kb",
      "temporary_table": {
        "table": {
          "table_name": "g",
          "access_type": "index_merge",
          "possible_keys": ["PRIMARY", "cat_ord", "id_pricegroup"],
          "key_length": "5,4",
          "index_merge": {
            "sort_union": {
              "range": {
                "key": "cat_ord",
                "used_key_parts": ["catalogueid"]
              },
              "range": {
                "key": "PRIMARY",
                "used_key_parts": ["id"]
              }
            }
          },
          "r_loops": 1,
          "rows": 5,
          "r_rows": 5,
          "r_total_time_ms": 0.0528,
          "filtered": 100,
          "r_filtered": 100,
          "attached_condition": "g.catalogueid = 117 or g.`id` = 378 and g.ispricegroup <> 0"
        },
        "table": {
          "table_name": "c",
          "access_type": "ref",
          "possible_keys": ["PRIMARY", "group_id", "FK_group", "group_ord"],
          "key": "FK_group",
          "key_length": "4",
          "used_key_parts": ["group_id"],
          "ref": ["test.g.id"],
          "r_loops": 5,
          "rows": 9,
          "r_rows": 20.8,
          "r_total_time_ms": 0.0937,
          "filtered": 100,
          "r_filtered": 100,
          "using_index": true
        },
        "table": {
          "table_name": "i2c",
          "access_type": "ref",
          "possible_keys": ["itemid", "FKIndex1"],
          "key": "FKIndex1",
          "key_length": "4",
          "used_key_parts": ["cattypeid"],
          "ref": ["test.c.id"],
          "r_loops": 104,
          "rows": 82,
          "r_rows": 3437.8,
          "r_total_time_ms": 13701,
          "filtered": 100,
          "r_filtered": 100
        },
        "table": {
          "table_name": "i",
          "access_type": "eq_ref",
          "possible_keys": ["PRIMARY", "id_active_dead"],
          "key": "PRIMARY",
          "key_length": "4",
          "used_key_parts": ["id"],
          "ref": ["test.i2c.itemid"],
          "r_loops": 357527,
          "rows": 1,
          "r_rows": 1,
          "r_total_time_ms": 963.27,
          "filtered": 100,
          "r_filtered": 36.669,
          "attached_condition": "i.active = 1 and i.dead = 0"
        },
        "table": {
          "table_name": "i2cat",
          "access_type": "ref",
          "possible_keys": ["item_cat", "cat_item"],
          "key": "item_cat",
          "key_length": "10",
          "used_key_parts": ["itemid", "catalogueid"],
          "ref": ["test.i2c.itemid", "const"],
          "r_loops": 131102,
          "rows": 1,
          "r_rows": 0.0688,
          "r_total_time_ms": 374.1,
          "filtered": 100,
          "r_filtered": 100,
          "using_index": true
        }
      }
    }
  }
} |

10.1.31

MariaDB [test]> analyze format=json  SELECT c.id,count(*) AS COUNT,c.group_id FROM cattypes c LEFT JOIN cattypegroups g ON c.group_id=g.id RIGHT JOIN itemtocattypes i2c ON i2c.cattypeid=c.id LEFT JOIN items i ON i2c.itemid=i.id INNER JOIN itemtocatalogues i2cat ON (i2cat.itemid=i.id AND i2cat.catalogueid=117) WHERE (g.catalogueid=117 OR g.id=378 AND g.ispricegroup) AND i.active=1 AND i.dead=0 GROUP BY c.id;
+---------------------------------------------------------------------------------------------------------------------------------------------------
| ANALYZE                                                                                                                                           
| {
  "query_block": {
    "select_id": 1,
    "r_loops": 1,
    "r_total_time_ms": 3676.3,
    "filesort": {
      "r_loops": 1,
      "r_total_time_ms": 0.0147,
      "r_used_priority_queue": false,
      "r_output_rows": 91,
      "r_buffer_size": "2Kb",
      "temporary_table": {
        "table": {
          "table_name": "g",
          "access_type": "index_merge",
          "possible_keys": ["PRIMARY", "cat_ord", "id_pricegroup"],
          "key_length": "5,4",
          "index_merge": {
            "sort_union": {
              "range": {
                "key": "cat_ord",
                "used_key_parts": ["catalogueid"]
              },
              "range": {
                "key": "PRIMARY",
                "used_key_parts": ["id"]
              }
            }
          },
          "r_loops": 1,
          "rows": 5,
          "r_rows": 5,
          "r_total_time_ms": 0.3423,
          "filtered": 100,
          "r_filtered": 100,
          "attached_condition": "((g.catalogueid = 117) or ((g.`id` = 378) and (g.ispricegroup <> 0)))"
        },
        "table": {
          "table_name": "c",
          "access_type": "ref",
          "possible_keys": ["PRIMARY", "group_id", "FK_group", "group_ord"],
          "key": "FK_group",
          "key_length": "4",
          "used_key_parts": ["group_id"],
          "ref": ["test.g.id"],
          "r_loops": 5,
          "rows": 9,
          "r_rows": 20.8,
          "r_total_time_ms": 0.642,
          "filtered": 100,
          "r_filtered": 100,
          "using_index": true
        },
        "table": {
          "table_name": "i2c",
          "access_type": "ref",
          "possible_keys": ["itemid", "FKIndex1"],
          "key": "FKIndex1",
          "key_length": "4",
          "used_key_parts": ["cattypeid"],
          "ref": ["test.c.id"],
          "r_loops": 104,
          "rows": 82,
          "r_rows": 3437.8,
          "r_total_time_ms": 2200.3,
          "filtered": 100,
          "r_filtered": 100
        },
        "table": {
          "table_name": "i",
          "access_type": "eq_ref",
          "possible_keys": ["PRIMARY", "id_active_dead"],
          "key": "PRIMARY",
          "key_length": "4",
          "used_key_parts": ["id"],
          "ref": ["test.i2c.itemid"],
          "r_loops": 357527,
          "rows": 1,
          "r_rows": 1,
          "r_total_time_ms": 1030.2,
          "filtered": 100,
          "r_filtered": 36.669,
          "attached_condition": "((i.active = 1) and (i.dead = 0))"
        },
        "table": {
          "table_name": "i2cat",
          "access_type": "ref",
          "possible_keys": ["item_cat", "cat_item"],
          "key": "item_cat",
          "key_length": "10",
          "used_key_parts": ["itemid", "catalogueid"],
          "ref": ["test.i2c.itemid", "const"],
          "r_loops": 131102,
          "rows": 1,
          "r_rows": 0.0688,
          "r_total_time_ms": 365.45,
          "filtered": 100,
          "r_filtered": 100,
          "using_index": true
        }
      }
    }
  }
} |

10.2.14-MariaDB-debug

| {
  "query_block": {
    "select_id": 1,
    "r_loops": 1,
    "r_total_time_ms": 42568,
    "filesort": {
      "sort_key": "c.`id`",
      "r_loops": 1,
      "r_total_time_ms": 0.098,
      "r_used_priority_queue": false,
      "r_output_rows": 91,
      "r_buffer_size": "2Kb",
      "temporary_table": {
        "table": {
          "table_name": "g",
          "access_type": "index_merge",
          "possible_keys": ["PRIMARY", "cat_ord", "id_pricegroup"],
          "key_length": "5,4",
          "index_merge": {
            "sort_union": {
              "range": {
                "key": "cat_ord",
                "used_key_parts": ["catalogueid"]
              },
              "range": {
                "key": "PRIMARY",
                "used_key_parts": ["id"]
              }
            }
          },
          "r_loops": 1,
          "rows": 5,
          "r_rows": 5,
          "r_total_time_ms": 0.6519,
          "filtered": 100,
          "r_filtered": 100,
          "attached_condition": "g.catalogueid = 117 or g.`id` = 378 and g.ispricegroup <> 0"
        },
        "table": {
          "table_name": "c",
          "access_type": "ref",
          "possible_keys": ["PRIMARY", "group_id", "FK_group", "group_ord"],
          "key": "FK_group",
          "key_length": "4",
          "used_key_parts": ["group_id"],
          "ref": ["test.g.id"],
          "r_loops": 5,
          "rows": 9,
          "r_rows": 20.8,
          "r_total_time_ms": 0.5217,
          "filtered": 100,
          "r_filtered": 100,
          "using_index": true
        },
        "table": {
          "table_name": "i2c",
          "access_type": "ref",
          "possible_keys": ["itemid", "FKIndex1"],
          "key": "FKIndex1",
          "key_length": "4",
          "used_key_parts": ["cattypeid"],
          "ref": ["test.c.id"],
          "r_loops": 104,
          "rows": 91,
          "r_rows": 3437.8,
          "r_total_time_ms": 33209,
          "filtered": 100,
          "r_filtered": 100
        },
        "table": {
          "table_name": "i",
          "access_type": "eq_ref",
          "possible_keys": ["PRIMARY", "id_active_dead"],
          "key": "PRIMARY",
          "key_length": "4",
          "used_key_parts": ["id"],
          "ref": ["test.i2c.itemid"],
          "r_loops": 357527,
          "rows": 1,
          "r_rows": 1,
          "r_total_time_ms": 4288,
          "filtered": 100,
          "r_filtered": 36.669,
          "attached_condition": "i.active = 1 and i.dead = 0"
        },
        "table": {
          "table_name": "i2cat",
          "access_type": "ref",
          "possible_keys": ["item_cat", "cat_item"],
          "key": "item_cat",
          "key_length": "10",
          "used_key_parts": ["itemid", "catalogueid"],
          "ref": ["test.i2c.itemid", "const"],
          "r_loops": 131102,
          "rows": 1,
          "r_rows": 0.0688,
          "r_total_time_ms": 4321.7,
          "filtered": 100,
          "r_filtered": 100,
          "using_index": true
        }
      }
    }
  }
} |

Comment by Silver Asu [ 2018-02-19 ]

In MySQL this query takes 0.0x seconds...

Comment by Indrek Altpere [ 2018-02-20 ]

10.1.10 is fast: 0.04 sec, 10.1.28 and 10.1.15 are slow but seem to use more aggressive cache.

{
  "query_block": {
    "select_id": 1,
    "r_loops": 1,
    "r_total_time_ms": 41.303,
    "filesort": {
      "r_loops": 1,
      "r_total_time_ms": 0.0372,
      "r_used_priority_queue": false,
      "r_output_rows": 91,
      "r_buffer_size": "2Kb",
      "temporary_table": {
        "table": {
          "table_name": "i2cat",
          "access_type": "ref",
          "possible_keys": ["item_cat", "cat_item"],
          "key": "cat_item",
          "key_length": "5",
          "used_key_parts": ["catalogueid"],
          "ref": ["const"],
          "r_loops": 1,
          "rows": 3682,
          "r_rows": 3683,
          "r_total_time_ms": 0.9596,
          "filtered": 100,
          "r_filtered": 99.973,
          "attached_condition": "((i2cat.itemid is not null) and (i2cat.itemid is not null))",
          "using_index": true
        },
        "table": {
          "table_name": "i",
          "access_type": "eq_ref",
          "possible_keys": ["PRIMARY", "id_active_dead"],
          "key": "PRIMARY",
          "key_length": "4",
          "used_key_parts": ["id"],
          "ref": ["dz.i2cat.itemid"],
          "r_loops": 3682,
          "rows": 1,
          "r_rows": 1,
          "r_total_time_ms": 6.9129,
          "filtered": 100,
          "r_filtered": 43.292,
          "attached_condition": "((i.active = 1) and (i.dead = 0))"
        },
        "table": {
          "table_name": "i2c",
          "access_type": "ref",
          "possible_keys": ["itemid", "FKIndex1"],
          "key": "itemid",
          "key_length": "4",
          "used_key_parts": ["itemid"],
          "ref": ["dz.i2cat.itemid"],
          "r_loops": 1594,
          "rows": 5,
          "r_rows": 11.669,
          "r_total_time_ms": 7.873,
          "filtered": 100,
          "r_filtered": 100,
          "using_index": true
        },
        "table": {
          "table_name": "c",
          "access_type": "eq_ref",
          "possible_keys": ["PRIMARY", "group_id", "FK_group", "group_ord"],
          "key": "PRIMARY",
          "key_length": "4",
          "used_key_parts": ["id"],
          "ref": ["dz.i2c.cattypeid"],
          "r_loops": 18600,
          "rows": 1,
          "r_rows": 1,
          "r_total_time_ms": 8.9305,
          "filtered": 100,
          "r_filtered": 100
        },
        "table": {
          "table_name": "g",
          "access_type": "eq_ref",
          "possible_keys": ["PRIMARY", "cat_ord", "id_pricegroup"],
          "key": "PRIMARY",
          "key_length": "4",
          "used_key_parts": ["id"],
          "ref": ["dz.c.group_id"],
          "r_loops": 18600,
          "rows": 1,
          "r_rows": 1,
          "r_total_time_ms": 8.7364,
          "filtered": 100,
          "r_filtered": 48.473,
          "attached_condition": "((g.catalogueid = 117) or ((c.group_id = 378) and (g.ispricegroup <> 0)))"
        }
      }
    }
  }
}

Main slowness seems to occur whenever sort_union is used.

EDIT:
Did some more testing with SQL_NO_CACHE modifier and 10.1.14 was the last fast version.
Starting from 10.1.15 on my machine, the query time jumps from 0.04s to ~8s, 200 times slower and sort_union appears in the analyze/explain result.

Comment by Indrek Altpere [ 2018-03-05 ]

Any news or questions? 20 000% slowdown seems like a big regression.

Comment by Varun Gupta (Inactive) [ 2018-04-05 ]

Output for explain:

+------+-------------+-------+-------------+-------------------------------------+-----------------+---------+-----------------------+------+---------------------------------------------------------------------------------+
| id   | select_type | table | type        | possible_keys                       | key             | key_len | ref                   | rows | Extra                                                                           |
+------+-------------+-------+-------------+-------------------------------------+-----------------+---------+-----------------------+------+---------------------------------------------------------------------------------+
|    1 | SIMPLE      | g     | index_merge | PRIMARY,cat_ord,id_pricegroup       | cat_ord,PRIMARY | 5,4     | NULL                  |    5 | Using sort_union(cat_ord,PRIMARY); Using where; Using temporary; Using filesort |
|    1 | SIMPLE      | c     | ref         | PRIMARY,group_id,FK_group,group_ord | FK_group        | 4       | test.g.id             |    9 | Using index                                                                     |
|    1 | SIMPLE      | i2c   | ref         | itemid,FKIndex1                     | FKIndex1        | 4       | test.c.id             |   92 |                                                                                 |
|    1 | SIMPLE      | i     | eq_ref      | PRIMARY,id_active_dead              | PRIMARY         | 4       | test.i2c.itemid       |    1 | Using where                                                                     |
|    1 | SIMPLE      | i2cat | ref         | item_cat,cat_item                   | item_cat        | 10      | test.i2c.itemid,const |    1 | Using index                                                                     |
+------+-------------+-------+-------------+-------------------------------------+-----------------+---------+-----------------------+------+---------------------------------------------------------------------------------+

Comment by Varun Gupta (Inactive) [ 2018-04-05 ]

Taking from 10.2.14-MariaDB debug's output of ANALYZE FORMAT=JSON

"table": {
          "table_name": "i2c",
          "access_type": "ref",
          "possible_keys": ["itemid", "FKIndex1"],
          "key": "FKIndex1",
          "key_length": "4",
          "used_key_parts": ["cattypeid"],
          "ref": ["test.c.id"],
          "r_loops": 104,
          "rows": 91,
          "r_rows": 3437.8,
          "r_total_time_ms": 33209,
          "filtered": 100,
          "r_filtered": 100
        },

This is the table where most of the time is spent about 33s

Comment by Varun Gupta (Inactive) [ 2018-04-06 ]

Removing Group by from the query does not affect the query time, still slow.

Comment by Varun Gupta (Inactive) [ 2018-04-06 ]

With EITS the estimates made by the optimizer for the i2c table increases a little but still the estimate is no way close to the real calculations

"table": {
      "table_name": "i2c",
      "access_type": "ref",
      "possible_keys": ["itemid", "FKIndex1"],
      "key": "FKIndex1",
      "key_length": "4",
      "used_key_parts": ["cattypeid"],
      "ref": ["test.c.id"],
      "r_loops": 8,
      "rows": 236,
      "r_rows": 42675,
      "r_total_time_ms": 52447,
      "filtered": 100,
      "r_filtered": 100
    },

Comment by Varun Gupta (Inactive) [ 2018-04-06 ]

The commit that causes this slowness is

commit 5c68bc2c3264fa2c4832c468bad32701dd3d4ed0
Author: Sergei Petrunia <psergey@askmonty.org>
Date:   Fri May 6 12:30:01 2016 +0300
 
    MDEV-10006: optimizer doesn't convert outer join to inner on views with WHERE clause
    
    When simplify_joins() converts an outer join to an inner, it should
    reset the value of TABLE::dep_tables.  This is needed, because the
    function may have already set TABLE::dep_tables according to the outer
    join dependency.

Comment by Varun Gupta (Inactive) [ 2018-04-09 ]

== Slow join order ==
 
1) g
records= 5(no ref access, using quick select here)
time=7.059
current_record_count=5
current_read_time= 0 + 7.059 + 1= 8.059
 
2) g,c
records=9
time=5.039
current_record_count = 5 * 9 =45
current_read_time= 8.059 + 5.039 + 45/ 5 =22.098
 
3) g,c,i2c
records=173
time=7830
current_record_count = 5 * 9 * 173 =7785
current_read_time= 22.098 + 7830 + 7787/5 = 9409.098
 
4) g,c,i2c,i
records=1
time= 7785
current_record_count = 5 * 9 * 173 * 1 =7785
current_read_time= 9409.098 + 7785 + 7785/5 = 18751.098
 
5) g,c,i2,i,i2cat
records=1
time= 7785
current_record_count = 5 * 9 * 173 * 1 =7785
current_read_time= 18751.098 + 7785 + 7785/5 = 28093.098
 
Two miscalculations with the slow query plan
1) i2c table underestimates the rows read (10x is the difference here)
2) c table underestimates the rows read (2x is the difference here)
 

Comment by Indrek Altpere [ 2018-05-15 ]

Is there any easy fix for this miscalculation?

Comment by Indrek Altpere [ 2019-12-27 ]

Is there any chance of getting this 200x slowdown fixed?

Comment by Varun Gupta (Inactive) [ 2020-01-13 ]

I will try to look at it again, but if the INNODB estimates are way off then it make take some time to get resolved.

In the meantime did you try to switch off index_merge as a workaround?

Comment by Indrek Altpere [ 2020-01-13 ]

Glad to hear about updates
Indeed I added USE INDEX() to the query which improved things a bit, but still did not get to the same speed as it was before.

Generated at Thu Feb 08 08:20:28 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.