Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-28518

After update to 10.5 a lot of time is spent in "Sending data"

    XMLWordPrintable

Details

    • Bug
    • Status: Closed (View Workflow)
    • Critical
    • Resolution: Fixed
    • 10.5.10, 10.5.15
    • N/A
    • Optimizer
    • 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

    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!

      Attachments

        1. db.sql.bz2
          225 kB
        2. largeSQL.sql
          107 kB
        3. image-2022-05-30-18-26-45-982.png
          image-2022-05-30-18-26-45-982.png
          14 kB

        Issue Links

          Activity

            People

              psergei Sergei Petrunia
              shoentjen Sander Hoentjen
              Votes:
              4 Vote for this issue
              Watchers:
              8 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.