[MDEV-32775] Performance degradation after Migrating from Mysql 5.6 to Mariadb 10.6 Created: 2023-11-11  Updated: 2024-01-16  Resolved: 2024-01-16

Status: Closed
Project: MariaDB Server
Component/s: None
Affects Version/s: 10.3.39, 10.4.31, 10.5.22, 10.6.15
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Noor Beegum Assignee: Unassigned
Resolution: Incomplete Votes: 0
Labels: None

Attachments: PNG File screenshot-1.png     PNG File screenshot-2.png    

 Description   

Hello,

I recently migrated a client environment from Mysql 5.6 to Mariad 10.6. Since then, almost every queries are slow on the database.

Here is an example of a query that is taking 22 minutes now to execute, when on Mysql 5.6 it took around 25 seconds or less.

+------+-------------+-------+--------+---------------------------------------+------------------------------+---------+--------------------------------------+------+---------------------------------+
 
| id   | select_type | table | type   | possible_keys                         | key                          | key_len | ref                                  | rows | Extra                           |
 
+------+-------------+-------+--------+---------------------------------------+------------------------------+---------+--------------------------------------+------+---------------------------------+
 
|    1 | SIMPLE      | fd    | ALL    | PRIMARY                               | NULL                         | NULL    | NULL                                 | 95   | Using temporary; Using filesort |
 
|    1 | SIMPLE      | a     | ref    | PRIMARY,ID_2                          | ID_2                         | 5       | X.fd.ID_2                            | 19   | Using index                     |
 
|    1 | SIMPLE      | cp    | ref    | ID_1,ID_2,ID_4                        | ID_4                         | 5       | X.a.4                                | 453  |                                 |
 
|    1 | SIMPLE      | p     | eq_ref | PRIMARY                               | PRIMARY                      | 4       | X.cp.2                               | 1    |                                 |
 
|    1 | SIMPLE      | ptyp  | eq_ref | PRIMARY                               | PRIMARY                      | 4       | X.p.ID_2                             | 1    | Using where                     |
 
|    1 | SIMPLE      | tbr   | eq_ref | PRIMARY                               | PRIMARY                      | 4       | X.p.ID_TIMBRE_CPMA                   | 1    | Using where                     |
 
|    1 | SIMPLE      | c     | eq_ref | PRIMARY                               | PRIMARY                      | 4       | X.cp.ID_3                            | 1    | Using where                     |
 
|    1 | SIMPLE      | ptrad | ref    | ID_PRODUIT                            | ID_PRODUIT                   | 4       | X.ptyp.ID_3                          | 2    | Using where                     |
 
|    1 | SIMPLE      | adh   | eq_ref | PRIMARY                               | PRIMARY                      | 4       | X.c.ID_ADHERENT                      | 1    | Using where                     |
 
+------+-------------+-------+--------+---------------------------------------+------------------------------+---------+--------------------------------------+------+---------------------------------+
 
 
 
9 rows in set (0,001 sec)

Note that i modified the the names of Keys, database and table to blur client's information. But the point is to show that there are no full table scan being done.

And still this query is taking 22 minutes to execute on mariadb 10.6.

My server has 32 Gb or RAM.
My Innodb_Buffer_Pool_Size is 20Gb
I tried adjusting by increasing the tmp_table_size , join_buffer_size (As the query does a lot of LEFT and INNER join).
I Compared the GLOBAL variables on both platform and everything seems to be pretty much the same.
I tried comparing the optimzer_switch and adjusted it accordingly.

The Query has the same Execution plan on both platform.

My final test to try debug was :

Desactivate : innodb_stats_persistent
Increase :innodb_stats_transient_sample_pages from 8 to 64.
Downgrade from Mariadb 10.6 > 10.5 > 10.4 > 10.3

All versions had the same problems.

Is there anything i can try?

 Comments   
Comment by Sergei Golubchik [ 2023-11-12 ]

it doesn't look like a 22-minute plan. The number of rows that optimizer expects to see is rather small. Do they look about right to you or are the estimations way off? Try ANALYZE SELECT, what will it show?

Comment by Noor Beegum [ 2023-11-13 ]

Hi Sergei,

Indeed it doesnt look like a 22 minutes exec plan.
Thank you for your reply, i will try to test and get back to you.

Comment by Noor Beegum [ 2023-11-14 ]

Hi serg

Here is the ANALYZE SELECT :

+------+-------------+-------+--------+---------------------------------------+------------------------------+---------+--------------------------------------+------+--------+----------+------------+---------------------------------+
 
| id   | select_type | table | type   | possible_keys                         | key                          | key_len | ref                                  | rows | r_rows | filtered | r_filtered | Extra                           |
 
+------+-------------+-------+--------+---------------------------------------+------------------------------+---------+--------------------------------------+------+--------+----------+------------+---------------------------------+
 
|    1 | SIMPLE      | fd    | ALL    | PRIMARY                               | NULL                         | NULL    | NULL                                 | 95   | 95.00  |   100.00 |     100.00 | Using temporary; Using filesort |
 
|    1 | SIMPLE      | a     | ref    | PRIMARY,ID_2                          | ID_FEDERATION_XXX            | 5       | X.fd.ID_2                            | 19   | 39.12  |   100.00 |     100.00 | Using index                     |
 
|    1 | SIMPLE      | cp    | ref    | ID_COMMANDE,ID_PRODUIT,ID_ASSOCIATION | ID_ASSOCIATION               | 5       | X.a.ID_3                             | 453  | 873.34 |   100.00 |     100.00 |                                 |
 
|    1 | SIMPLE      | p     | eq_ref | PRIMARY                               | PRIMARY                      | 4       | X.cp.ID_PRODUIT                      | 1    | 1.00   |   100.00 |     100.00 |                                 |
 
|    1 | SIMPLE      | ptyp  | eq_ref | PRIMARY                               | PRIMARY                      | 4       | X.p.ID_PRODUITTYPE                   | 1    | 0.96   |   100.00 |     100.00 | Using where                     |
 
|    1 | SIMPLE      | tbr   | eq_ref | PRIMARY                               | PRIMARY                      | 4       | X.p.ID_4                             | 1    | 0.94   |   100.00 |     100.00 | Using where                     |
 
|    1 | SIMPLE      | c     | eq_ref | PRIMARY                               | PRIMARY                      | 4       | X.cp.5                               | 1    | 1.00   |   100.00 |       3.11 | Using where                     |
 
|    1 | SIMPLE      | ptrad | ref    | ID_PRODUIT                            | ID_PRODUIT                   | 4       | X.ptyp.ID_PRODUITTYPE                | 2    | 3.81   |   100.00 |      25.00 | Using where                     |
 
|    1 | SIMPLE      | adh   | eq_ref | PRIMARY                               | PRIMARY                      | 4       | X.c.ID_ADHERENT                      | 1    | 1.00   |   100.00 |     100.00 | Using where                     |
 
+------+-------------+-------+--------+---------------------------------------+------------------------------+---------+--------------------------------------+------+--------+----------+------------+---------------------------------+
 
9 rows in set (21 min 10,879 sec)

Comment by Noor Beegum [ 2023-11-14 ]

Comment by Noor Beegum [ 2023-11-14 ]

I added a screenshot so that it is more readable for you

Comment by Sergei Golubchik [ 2023-11-14 ]

So, optimizer estimates are not 100x off. Can you show the output CREATE TABLE for all affected tables? Anonymized, that's fine.

Comment by Michael Widenius [ 2023-11-14 ]

Can you please also do:
ANALYZE FORMAT=JSON SELECT....
This will show us the time spent retrieving rows from each table.

Comment by Michael Widenius [ 2023-11-14 ]

Any chance you can also provide the EXPLAIN for MySQL so that we can check the number of estimated and found rows.

Comment by Noor Beegum [ 2023-11-14 ]

Comment by Noor Beegum [ 2023-11-14 ]

ANALYZE FORMAT=JSON on Mariadb 10.6 (i obfuscated some data, hopefully this doesnt prevent you from analysing it):

[[ | {
 
  "query_block": {
 
    "select_id": 1,
 
    "r_loops": 1,
 
    "r_total_time_ms": 1289999.405,
 
    "filesort": {
 
      "sort_key": "c.COM_DATEINSERT, c.ID_COMMANDE, cp.ID_COMMANDE_PRODUIT",
 
      "r_loops": 1,
 
      "r_total_time_ms": 48.206,
 
      "r_used_priority_queue": false,
 
      "r_output_rows": 100495,
 
      "r_sort_passes": 1,
 
      "r_buffer_size": "2047Kb",
 
      "r_sort_mode": "sort_key,rowid",
 
      "duplicate_removal": {
 
        "temporary_table": {
 
          "temporary_table": {
 
            "table": {
 
              "table_name": "c",
 
              "access_type": "range",
 
              "possible_keys": [
 
                "PRIMARY",
 
                "COM_1",
 
                "COM_2",
 
                "COM_3",
 
                "COM_4",
 
                "composite_index_NB"
 
              ],
 
              "key": "composite_index_NB",
 
              "key_length": "47",
 
              "used_key_parts": [
 
                "COM_SAISON",
 
                "COM_TYPE",
 
                "COM_DATEINSERT",
 
                "COM_TOTAL",
 
                "COM_3"
 
              ],
 
              "r_loops": 1,
 
              "rows": 231838,
 
              "r_rows": 86732,
 
              "r_table_time_ms": 249.48,
 
              "r_other_time_ms": 1285263.296,
 
              "r_engine_stats": {
 
                "pages_accessed": 260409
 
              },
 
              "filtered": 7.855368137,
 
              "r_filtered": 100,
 
              "index_condition": "c.1 = 2023 and c.2 >= 1680300000 and c.3 < 1682891999 and c.4 >= 0 and (c.1 = 3 or c.2 = 1 or c.3 = 4) and c.COM_TYPE = 'Internet'"
 
            },
 
            "table": {
 
              "table_name": "cp",
 
              "access_type": "ref",
 
              "possible_keys": ["ID_COMMANDE", "ID_PRODUIT", "ID_ASSOCIATION"],
 
              "key": "ID_COMMANDE",
 
              "key_length": "4",
 
              "used_key_parts": ["ID_COMMANDE"],
 
              "ref": ["X.c.ID_COMMANDE"],
 
              "r_loops": 86732,
 
              "rows": 1,
 
              "r_rows": 1.165452198,
 
              "r_table_time_ms": 448.526,
 
              "r_other_time_ms": 47.437,
 
              "r_engine_stats": {
 
                "pages_accessed": 563592
 
              },
 
              "filtered": 100,
 
              "r_filtered": 100,
 
              "attached_condition": "cp.ID_ASSOCIATION is not null"
 
            },
 
            "table": {
 
              "table_name": "p",
 
              "access_type": "eq_ref",
 
              "possible_keys": ["PRIMARY"],
 
              "key": "PRIMARY",
 
              "key_length": "4",
 
              "used_key_parts": ["ID_PRODUIT"],
 
              "ref": ["X.cp.ID_PRODUIT"],
 
              "r_loops": 101082,
 
              "rows": 1,
 
              "r_rows": 1,
 
              "r_table_time_ms": 148.676,
 
              "r_other_time_ms": 87.39,
 
              "r_engine_stats": {
 
                "pages_accessed": 170805
 
              },
 
              "filtered": 100,
 
              "r_filtered": 100
 
            },
 
            "table": {
 
              "table_name": "ptyp",
 
              "access_type": "eq_ref",
 
              "possible_keys": ["PRIMARY"],
 
              "key": "PRIMARY",
 
              "key_length": "4",
 
              "used_key_parts": ["ID_PRODUITTYPE"],
 
              "ref": ["X.p.ID_PRODUITTYPE"],
 
              "r_loops": 101082,
 
              "rows": 1,
 
              "r_rows": 0.953018342,
 
              "r_table_time_ms": 59.441,
 
              "r_other_time_ms": 12.446,
 
              "r_engine_stats": {
 
                "pages_accessed": 61553
 
              },
 
              "filtered": 100,
 
              "r_filtered": 100,
 
              "attached_condition": "trigcond(trigcond(p.ID_PRODUITTYPE is not null))"
 
            },
 
            "table": {
 
              "table_name": "tbr",
 
              "access_type": "eq_ref",
 
              "possible_keys": ["PRIMARY"],
 
              "key": "PRIMARY",
 
              "key_length": "4",
 
              "used_key_parts": ["ID_TIMBRE"],
 
              "ref": ["X.p.ID_TIMBRE_CPMA"],
 
              "r_loops": 101082,
 
              "rows": 1,
 
              "r_rows": 0.952246691,
 
              "r_table_time_ms": 68.881,
 
              "r_other_time_ms": 11.941,
 
              "r_engine_stats": {
 
                "pages_accessed": 61578
 
              },
 
              "filtered": 100,
 
              "r_filtered": 100,
 
              "attached_condition": "trigcond(trigcond(p.ID_TIMBRE_CPMA is not null))"
 
            },
 
            "table": {
 
              "table_name": "a",
 
              "access_type": "eq_ref",
 
              "possible_keys": ["PRIMARY", "ID_FEDERATION_DEPARTEMENTALE"],
 
              "key": "PRIMARY",
 
              "key_length": "4",
 
              "used_key_parts": ["ID_ASSOCIATION"],
 
              "ref": ["X.cp.ID_ASSOCIATION"],
 
              "r_loops": 101082,
 
              "rows": 1,
 
              "r_rows": 1,
 
              "r_table_time_ms": 148.212,
 
              "r_other_time_ms": 37.04,
 
              "r_engine_stats": {
 
                "pages_accessed": 177614
 
              },
 
              "filtered": 100,
 
              "r_filtered": 100,
 
              "attached_condition": "a.ID_FEDERATION_DEPARTEMENTALE is not null"
 
            },
 
            "table": {
 
              "table_name": "fd",
 
              "access_type": "eq_ref",
 
              "possible_keys": ["PRIMARY"],
 
              "key": "PRIMARY",
 
              "key_length": "4",
 
              "used_key_parts": ["ID_FEDERATION_DEPARTEMENTALE"],
 
              "ref": ["X.a.ID_FEDERATION_DEPARTEMENTALE"],
 
              "r_loops": 101082,
 
              "rows": 1,
 
              "r_rows": 1,
 
              "r_table_time_ms": 137.637,
 
              "r_other_time_ms": 20.649,
 
              "r_engine_stats": {
 
                "pages_accessed": 182033
 
              },
 
              "filtered": 100,
 
              "r_filtered": 100
 
            },
 
            "table": {
 
              "table_name": "ptrad",
 
              "access_type": "ref",
 
              "possible_keys": ["ID_PRODUIT"],
 
              "key": "ID_PRODUIT",
 
              "key_length": "4",
 
              "used_key_parts": ["ID_PRODUITTYPE"],
 
              "ref": ["X.ptyp.ID_PRODUITTYPE"],
 
              "r_loops": 101082,
 
              "rows": 2,
 
              "r_rows": 3.812073366,
 
              "r_table_time_ms": 440.395,
 
              "r_other_time_ms": 350.178,
 
              "r_engine_stats": {
 
                "pages_accessed": 481665
 
              },
 
              "filtered": 100,
 
              "r_filtered": 25,
 
              "attached_condition": "trigcond(ptrad.LNG_CODE = 'fr_FR' or ptrad.LNG_CODE is null) and trigcond(trigcond(ptyp.ID_PRODUITTYPE is not null))"
 
            },
 
            "table": {
 
              "table_name": "adh",
 
              "access_type": "eq_ref",
 
              "possible_keys": ["PRIMARY"],
 
              "key": "PRIMARY",
 
              "key_length": "4",
 
              "used_key_parts": ["ID_ADHERENT"],
 
              "ref": ["X.c.ID_ADHERENT"],
 
              "r_loops": 101082,
 
              "rows": 1,
 
              "r_rows": 1,
 
              "r_table_time_ms": 320.968,
 
              "r_other_time_ms": 1925.311,
 
              "r_engine_stats": {
 
                "pages_accessed": 262183
 
              },
 
              "filtered": 100,
 
              "r_filtered": 100,
 
              "attached_condition": "trigcond(trigcond(c.ID_ADHERENT is not null))"
 
            }
 
          }
 
        }
 
      }
 
    }
 
  }
 
} ]]

Comment by Noor Beegum [ 2023-11-14 ]

@Sergei Golubchik , i will be sending you the SHOW CREATE TABLES tomorrow, as there are quite a few, and i will need to obfuscate a lot of the information.

Regards,
Noor

Comment by Noor Beegum [ 2023-11-17 ]

Hello,

Just found out something in my query. So my query ends with some GROUP BY and ORDER BY like this :

[...]
GROUP BY c.qwe,
cp.abc,
p.def
ORDER BY c.COM_DATEINSERT ASC,
c.ID_COMMANDE ASC,
cp.ID_COMMANDE_PRODUIT ASC
[...]

This takes 24 minutes to execute.

Whereas when i modify it to this (only uses 1 GROUP BY):

[...]
GROUP BY
c.qwe
ORDER BY c.COM_DATEINSERT ASC,
c.ID_COMMANDE ASC,
cp.ID_COMMANDE_PRODUIT ASC;
[...]

The execution time is 2.4s

Comment by Sergei Golubchik [ 2023-12-18 ]

it's not clear, sorry. could you please, when obfuscating, consistently use the same obfuscation everywhere, if possible?

I don't see a GROUP BY in the ANALYZE FORMAT=JSON SELECT output, and I don't see qwe, abc, def there.

Is group by on only one column acceptable for you, meaning, does it deliver the result that you need?

Generated at Thu Feb 08 10:33:55 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.