[MDEV-28518] After update to 10.5 a lot of time is spent in "Sending data" Created: 2022-05-09  Updated: 2023-01-12  Resolved: 2022-10-17

Status: Closed
Project: MariaDB Server
Component/s: Optimizer
Affects Version/s: 10.5.10, 10.5.15
Fix Version/s: N/A

Type: Bug Priority: Critical
Reporter: Sander Hoentjen Assignee: Sergei Petrunia
Resolution: Fixed Votes: 4
Labels: optimizer, performance, regression
Environment:

CloudLinux release 8.5
Kernel: 4.18.0-305.17.1.lve.el8.x86_64
MariaDB: 10.5.10-MariaDB-log-cll-lve and 10.5.15-MariaDB-cll-lve-log
/var/lib/mysql filesystem: ZFS

Attachments: File db.sql.bz2     PNG File image-2022-05-30-18-26-45-982.png     File largeSQL.sql    
Issue Links:
Relates
relates to MDEV-25020 SELECT if there is IN clause with bin... Closed
relates to MDEV-30390 MariaDB 10.5 gets stuck on "Too many ... Closed
relates to MDEV-27530 InnoDB - Performance issues after upg... Closed

 Description   

Since updating to 10.5, sometimes performance collapses. Queries that normally take less then a second, can take multiple minutes. The time is spent in state "Sending data"

MariaDB [dbname]> SELECT SQL_CALC_FOUND_ROWS DISTINCT lm_posts.ID FROM lm_posts  INNER JOIN lm_postmeta ON ( lm_posts.ID = lm_postmeta.post_id ) LEFT JOIN lm_postmeta espm ON (lm_posts.ID = espm.post_id)  WHERE 1=1  AND (    lm_posts.ID NOT IN (     SELECT object_id     FROM lm_term_relationships     WHERE term_taxonomy_id IN (6)    ) ) AND ( ((lm_posts.post_title LIKE '%test%') OR (lm_posts.post_content LIKE '%test%') OR (espm.meta_key = 'ean_artikel' AND espm.meta_value LIKE '%test%') OR (espm.meta_key = 'hwp_product_gtin' AND espm.meta_value LIKE '%test%') OR (espm.meta_key = '_product_attributes' AND espm.meta_value LIKE '%test%')))  AND (lm_posts.post_password = '')  AND (    lm_postmeta.meta_key = 'webwinkelnummer' ) AND ((lm_posts.post_type = 'product' AND (lm_posts.post_status = 'publish' OR lm_posts.post_status = 'acf-disabled' OR lm_posts.post_status = 'cwg_mailsent' OR lm_posts.post_status = 'cwg_mailnotsent' OR lm_posts.post_status = 'cwg_subscribed' OR lm_posts.post_status = 'cwg_unsubscribed' OR lm_posts.post_status = 'cwg_converted'))) GROUP BY lm_posts.ID ORDER BY lm_postmeta.meta_value ASC LIMIT 0, 18;
 
+-------+
 
| ID    |
 
+-------+
 
| 39617 |
 
| 37285 |
 
| 37288 |
 
| 43343 |
 
| 43624 |
 
+-------+
 
5 rows in set (4.531 sec)
 
 
 
MariaDB [dbname]> SHOW PROFILE ALL;
 
+------------------------+----------+-----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------+---------------+-------------+
 
| Status                 | Duration | CPU_user  | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function | Source_file   | Source_line |
 
+------------------------+----------+-----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------+---------------+-------------+
 
| Starting               | 0.000216 |  0.001321 |   0.000378 |                22 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | NULL            | NULL          |        NULL |
 
| checking permissions   | 0.000010 |  0.000008 |   0.000002 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_parse.cc  |        6810 |
 
| Opening tables         | 0.001523 |  0.002349 |   0.003055 |               174 |                   0 |          119 |             9 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_base.cc   |        4207 |
 
| After opening tables   | 0.000018 |  0.000015 |   0.000003 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_base.cc   |        4464 |
 
| System lock            | 0.000006 |  0.000005 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | lock.cc       |         337 |
 
| table lock             | 0.000007 |  0.000006 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | lock.cc       |         342 |
 
| Opening tables         | 0.000029 |  0.000104 |   0.000025 |                10 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_base.cc   |        4207 |
 
| After opening tables   | 0.000007 |  0.000009 |   0.000002 |                 0 |                   0 |            0 |             8 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_base.cc   |        4464 |
 
| System lock            | 0.000007 |  0.000005 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | lock.cc       |         337 |
 
| table lock             | 0.000063 |  0.000186 |   0.000043 |                12 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 1 |     0 | <unknown>       | lock.cc       |         342 |
 
| Unlocking tables       | 0.000010 |  0.000008 |   0.000002 |                 0 |                   0 |            0 |             8 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | lock.cc       |         429 |
 
| closing tables         | 0.000011 |  0.000009 |   0.000002 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_base.cc   |         784 |
 
| init                   | 0.000059 |  0.000085 |   0.000020 |                 1 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_select.cc |        4735 |
 
| Optimizing             | 0.000043 |  0.000109 |   0.000025 |                10 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_select.cc |        1833 |
 
| Statistics             | 0.004121 |  0.008060 |   0.006150 |               245 |                   1 |         1458 |           219 |             0 |                 0 |                 0 |                 1 |     0 | <unknown>       | sql_select.cc |        2292 |
 
| Preparing              | 0.000128 |  0.000847 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_select.cc |        2367 |
 
| Optimizing             | 0.000010 |  0.000011 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_select.cc |        1833 |
 
| Statistics             | 0.000648 |  0.002006 |   0.000000 |                56 |                   0 |          140 |            38 |             0 |                 0 |                 0 |                 2 |     0 | <unknown>       | sql_select.cc |        2292 |
 
| Preparing              | 0.000024 |  0.000019 |   0.000004 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_select.cc |        2367 |
 
| Creating tmp table     | 0.000012 |  0.000010 |   0.000003 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_select.cc |        3773 |
 
| Sorting result         | 0.000011 |  0.000008 |   0.000002 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_select.cc |        3654 |
 
| Executing              | 0.000004 |  0.000004 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_select.cc |        4303 |
 
| Sending data           | 0.001191 |  0.001120 |   0.001020 |                64 |                   0 |          405 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_select.cc |        4499 |
 
| Executing              | 0.000011 |  0.000023 |   0.000005 |                 0 |                   0 |           32 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_select.cc |        4303 |
 
| Sending data           | 0.614984 |  1.434036 |   0.425445 |             21108 |                 613 |        77905 |          7601 |             0 |                 0 |                 0 |              4917 |     0 | <unknown>       | sql_select.cc |        4499 |
 
| Removing tmp table     | 0.000062 |  0.000000 |   0.000496 |                 7 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_select.cc |       20099 |
 
| Sending data           | 3.907354 | 11.211695 |   2.927629 |            167971 |                2303 |       430289 |         64814 |             0 |                 0 |                 0 |             22580 |     0 | <unknown>       | sql_select.cc |       20132 |
 
| Creating sort index    | 0.000083 |  0.000178 |   0.000042 |                 1 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 1 |     0 | <unknown>       | sql_select.cc |       21811 |
 
| Removing tmp table     | 0.000102 |  0.000156 |   0.000036 |                 1 |                   0 |            0 |            16 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_select.cc |       20099 |
 
| Creating sort index    | 0.000007 |  0.000006 |   0.000002 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_select.cc |       20132 |
 
| End of update loop     | 0.000006 |  0.000006 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_select.cc |        4779 |
 
| Query end              | 0.000004 |  0.000002 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_parse.cc  |        6117 |
 
| Commit                 | 0.000007 |  0.000006 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_parse.cc  |        6163 |
 
| closing tables         | 0.000003 |  0.000003 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_base.cc   |         784 |
 
| Unlocking tables       | 0.000004 |  0.000003 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | lock.cc       |         429 |
 
| closing tables         | 0.000014 |  0.000011 |   0.000003 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | lock.cc       |         442 |
 
| Starting cleanup       | 0.000005 |  0.000004 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_parse.cc  |        6229 |
 
| Freeing items          | 0.000015 |  0.000012 |   0.000002 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_parse.cc  |        8177 |
 
| Removing tmp table     | 0.000005 |  0.000004 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_select.cc |       20099 |
 
| Freeing items          | 0.000038 |  0.000030 |   0.000008 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_select.cc |       20132 |
 
| Updating status        | 0.000012 |  0.000010 |   0.000002 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_parse.cc  |        2522 |
 
| Logging slow query     | 0.000567 |  0.001816 |   0.000000 |                 9 |                   0 |           55 |             2 |             0 |                 0 |                 0 |                 7 |     0 | <unknown>       | sql_parse.cc  |        2671 |
 
| Reset for next command | 0.000017 |  0.000017 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | <unknown>       | sql_parse.cc  |        2546 |
 
+------------------------+----------+-----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------+---------------+-------------+
 
43 rows in set (0.000 sec)

This this on a shared database of a hosting company, with many concurrent accesses. After restarting MariaDB things are a bit better for a while, but not as good as it was with 10.4
It might be a configuration issue, but I couldn't find anything obvious, and the same config was fine with 10.4.

Apart from this, we also see that (some) queries spend a lot more time in "Statistics" state than they used to.

If I can provide any more information, please let me know!

 Comments   
Comment by Sander Hoentjen [ 2022-05-10 ]

In the logs we see multiple occurences of
2022-05-10 4:20:55 2263080 [Note] InnoDB: Cannot close file ./<db_name>/<table name>.ibd because of pending fsync

Where dbname and table name can differ

Also, most queries are in "Statistics" state now

# mysql -e "SHOW PROCESSLIST" | wc -l
 
500
 
# mysql -e "SHOW PROCESSLIST" | grep Statistics | wc -l
 
394

Comment by Sergei Petrunia [ 2022-05-10 ]

"Sending data" is a poor name for "Running the join operation and sending result to output" . (Inherited from the time when most of the queries were really basic).

It would be helpful if we had ANALYZE FORMAT=JSON output for a "fast" query run and a "slow" run of the same query.

Comment by Sergei Petrunia [ 2022-05-10 ]

Re-formatted the query:

SELECT SQL_CALC_FOUND_ROWS DISTINCT 
  lm_posts.ID 
FROM 
  lm_posts  
  INNER JOIN lm_postmeta ON ( lm_posts.ID = lm_postmeta.post_id ) 
  LEFT JOIN lm_postmeta espm ON (lm_posts.ID = espm.post_id)
 
WHERE 
  1=1  AND 
  lm_posts.ID NOT IN ( SELECT object_id     
                       FROM lm_term_relationships     
                       WHERE term_taxonomy_id IN (6)) AND 
  (
 
     (lm_posts.post_title LIKE '%test%') OR 
     (lm_posts.post_content LIKE '%test%') OR 
     (espm.meta_key = 'ean_artikel' AND espm.meta_value LIKE '%test%') OR 
     (espm.meta_key = 'hwp_product_gtin' AND espm.meta_value LIKE '%test%') OR 
     (espm.meta_key = '_product_attributes' AND espm.meta_value LIKE '%test%')
 
  ) 
  AND 
  lm_posts.post_password = '' AND 
  lm_postmeta.meta_key = 'webwinkelnummer' AND 
  lm_posts.post_type = 'product' AND 
  (
 
     lm_posts.post_status = 'publish' OR 
     lm_posts.post_status = 'acf-disabled' OR 
     lm_posts.post_status = 'cwg_mailsent' OR 
     lm_posts.post_status = 'cwg_mailnotsent' OR 
     lm_posts.post_status = 'cwg_subscribed' OR 
     lm_posts.post_status = 'cwg_unsubscribed' OR 
     lm_posts.post_status = 'cwg_converted'
 
  )
 
GROUP BY 
  lm_posts.ID 
ORDER BY 
  lm_postmeta.meta_value ASC LIMIT 0, 18;

The optimizer can pick multiple join orders for it (either lm_posts, lm_postmeta or lm_postmeta,lm_posts.
Based on the observed behavior, it looks like the optimizer picks a wrong query plan sometimes? (And I think the most probable reason is that statistics changes).

Comment by Sander Hoentjen [ 2022-05-20 ]

Because the situation was awful for our customers, we moved away some of them to reduce the load. The situation is much better now, it seems there is some tipping point where if you move past that, things fall all over each other. While the situation is better, it is still worse than with 10.4. But, since it is better, it is harder to reproduce and run tests. I will keep trying to get relevant data.

Comment by Sander Hoentjen [ 2022-05-24 ]

With the help of the plugin author of mysites.guru we found a query that performs extremely bad on MariaDB 10.5+.

I attached the reproducers here db.sql.bz2 largeSQL.sql

On the system we tested, with 10.4, running largeSQL.sql on the db created with db.sql.bz2 takes about 0.2s, whereas with 10.5 it takes more than 30s!

Of course I don't know if this is all related, but I have good hope that if this is fixed, overall performance will improve as well.

Comment by Sander Hoentjen [ 2022-05-25 ]

Git bisect shows c36720388d598ca3aa1c4d2dab2266656c528b50 is the offending commit. Versions before complete the above in 200ms, after that it takes 30s+

Comment by Sander Hoentjen [ 2022-05-26 ]

Setting optimizer_max_sel_arg_weight to a low value helps performance for this query

Comment by Ludovic Monnier [ 2022-05-30 ]

We observed the same issue since Maria 10.5 using a SELECT ... FROM... GROUP BY.... syntax

Very poor performance using mariadb 10.5 and after !!

I check the same request with same data using few version of mariadb :

#Version: 10.3.34-MariaDB-0+deb10u1-log (Debian 10).

Query_time: 724.197647 Lock_time: 0.037806 Rows_sent: 0 Rows_examined: 82160658
#Version: 10.4.24-MariaDB-1:10.4.24+maria~buster-log (mariadb.org binary distribution) Avant derniere 10.4

Query_time: 564.029273 Lock_time: 0.044647 Rows_sent: 0 Rows_examined: 82160658
#Version: 10.4.25-MariaDB-1:10.4.25+maria~buster-log (mariadb.org binary distribution)

Query_time: 546.300378 Lock_time: 0.123554 Rows_sent: 0 Rows_examined: 82160658
With update 10.5.* , 10.6.* and 10.7.* :

Query_time: 2116.641373 Lock_time: 0.024204 Rows_sent: 0 Rows_examined: 82160658
=> 35 minutes
Since 10.5.* we can observe a large tempory file .MAI during the request. This one was empty (only few Ko) using mariadb 10.4 and before.
Since 10.5.* we can observe a INNODB_BUFFER_POOL_PAGES_FREE going down to zero.

Comment by Sander Hoentjen [ 2022-05-30 ]

Can you confirm that if you do:

SET optimizer_max_sel_arg_weight=1;

before the query, that performance is okay with 10.5?

Comment by Ludovic Monnier [ 2022-05-30 ]

Hi,

I tried it. But performance are always poor using mariadb 10.5.16.

    1. Query_time: 1814.171778 Lock_time: 0.000112 Rows_sent: 1274204 Rows_examined: 82160658*

VS mariadb 10.3.34:

  1. Query_time: 573.644309 Lock_time: 0.000114 Rows_sent: 1274204 Rows_examined: 82160658

During request, we can observe a large MAI create using 10.5.16. (With 10.3 or 10.4 the MAI file don't exceed 2M)
[15:31:28] # ls -rtlh /mnt/mysqldata/tmp/
total 96M
rw-rw--- 1 mysql mysql 73M mai 30 15:32 '#sql-temptable-17de-2c-7c.MAD'
rw-rw--- 1 mysql mysql 79M mai 30 15:32 '#sql-temptable-17de-2c-7c.MAI'

[15:32:58] # ls -rtlh /mnt/mysqldata/tmp/
total 181M
rw-rw--- 1 mysql mysql 143M mai 30 15:36 '#sql-temptable-17de-2c-7c.MAI'
rw-rw--- 1 mysql mysql 129M mai 30 15:36 '#sql-temptable-17de-2c-7c.MAD'

[15:36:14] root@sfr-bdprod-5-restore:~# ls -rtlh /mnt/mysqldata/tmp/
total 181M
rw-rw--- 1 mysql mysql 129M mai 30 15:36 '#sql-temptable-17de-2c-7c.MAD'
rw-rw--- 1 mysql mysql 143M mai 30 15:36 '#sql-temptable-17de-2c-7c.MAI'

[15:36:23] # ls -rtlh /mnt/mysqldata/tmp/
total 203M
rw-rw--- 1 mysql mysql 143M mai 30 15:38 '#sql-temptable-17de-2c-7c.MAI'
rw-rw--- 1 mysql mysql 129M mai 30 15:38 '#sql-temptable-17de-2c-7c.MAD'

[15:38:04] # ls -rtlh /mnt/mysqldata/tmp/
total 340M
rw-rw--- 1 mysql mysql 184M mai 30 15:47 '#sql-temptable-17de-2c-7c.MAD'
rw-rw--- 1 mysql mysql 208M mai 30 15:47 '#sql-temptable-17de-2c-7c.MAI'

[15:47:40] # ls -rtlh /mnt/mysqldata/tmp/
total 415M
rw-rw--- 1 mysql mysql 239M mai 30 15:52 '#sql-temptable-17de-2c-7c.MAD'
rw-rw--- 1 mysql mysql 273M mai 30 15:52 '#sql-temptable-17de-2c-7c.MAI'

Comment by Sander Hoentjen [ 2022-05-30 ]

@Ludovic Monnier Then I don't think this is the same underlying issue.

Comment by Ludovic Monnier [ 2022-05-30 ]

Perhaps is not the same issue. but query time is x 4 between mariadb 10.4 and 10.5

I add the SHOW PROFILE FOR QUERY
We can see "'Sending data', 999.999999" !!

  1. Query_time: 1966.653865 Lock_time: 0.000153 Rows_sent: 1274204 Rows_examined: 82160658
  2. Rows_affected: 0 Bytes_sent: 181442152
  3. Tmp_tables: 2 Tmp_disk_tables: 1 Tmp_table_sizes: 582377472
  4. Full_scan: Yes Full_join: No Tmp_table: Yes Tmp_table_on_disk: Yes
  5. Filesort: Yes Filesort_on_disk: No Merge_passes: 5 Priority_queue: No
    #
  6. explain: id select_type table type possible_keys key key_len ref rows r_rows filtered r_filtered Extra
  7. explain: 1 SIMPLE T ALL NULL NULL NULL NULL 74632078 79612250.00 100.00 100.00 Using temporary; Using filesort

'Starting', 0.000006
'Waiting for query cache lock', 0.000003
'starting', 0.000002
'Checking query cache for query', 0.000073
'checking permissions', 0.000003
'Opening tables', 0.000012
'After opening tables', 0.000013
'System lock', 0.000015
'table lock', 0.000006
'Opening tables', 0.000015
'After opening tables', 0.000002
'System lock', 0.000003
'table lock', 0.000041
'Unlocking tables', 0.000003
'closing tables', 0.000006
'Waiting for query cache lock', 0.000002
'closing tables', 0.000084
'init', 0.000066
'Optimizing', 0.000012
'Statistics', 0.000030
'Preparing', 0.000014
'Creating tmp table', 0.000050
'Sorting result', 0.000013
'Executing', 0.000002
'Sending data', 50.688711
'Converting HEAP to Aria', 0.082659
'Creating index', 0.000083
'Repair by sorting', 0.209375
'Saving state', 0.000026
'Creating index', 0.000004
'Converting HEAP to Aria', 0.000142
'Sending data', 999.999999
'Creating sort index', 2.887901
'Waiting for query cache lock', 0.000010
'Creating sort index', 0.000252
'Waiting for query cache lock', 0.000002
'Creating sort index', 0.000176
'Waiting for query cache lock', 0.000001
'Creating sort index', 0.000181
'Waiting for query cache lock', 0.000001
'Creating sort index', 0.000177
'Waiting for query cache lock', 0.000002
'Creating sort index', 0.000176
'Waiting for query cache lock', 0.000002
'Creating sort index', 0.000179
'Waiting for query cache lock', 0.000001
'Creating sort index', 0.000180
'Waiting for query cache lock', 0.000002
'Creating sort index', 0.000179
'Waiting for query cache lock', 0.000002
'Creating sort index', 39.707058
'Removing tmp table', 0.076693
'Creating sort index', 0.000075
'End of update loop', 0.000021
'Query end', 0.000003
'Commit', 0.000005
'closing tables', 0.000008
'Unlocking tables', 0.000002
'closing tables', 0.000051
'Starting cleanup', 0.000004
'Freeing items', 0.000011
'Updating status', 0.000015
'Logging slow query', 0.000082
'Reset for next command', 0.000178

Comment by Joris de Leeuw [ 2022-09-22 ]

This issue seems to be fixed with MDEV-25020. I'm currently testing it on one of our systems to be sure.

Comment by Joris de Leeuw [ 2022-10-12 ]

This issue can be closed.

The example shared by my colleague Sander Hoentjen has very positive differences between 10.6.16 and 10.5.17.
The query which first took 59.3507 seconds now just finishes in 0.1273 seconds.

After updating production servers from 10.5.16 to 10.5.17 we don't see queries stuck in "Statistics" state as before.
Also upgrading some of the remaining servers from 10.4 to 10.5 we don't notice huge performance differences anymore.

Also we see less crashes with MariaDB 10.5.17 than with MariaDB 10.4.x and 10.5.16--.

We however see still rarely that MariaDB 10.5.x gets stuck in an 'too many connections' state without any clear cause. This seems a separate issue that we are still investigating.

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