[MDEV-16289] Slow query performance versus MySQL Created: 2018-05-25  Updated: 2022-09-23

Status: Confirmed
Project: MariaDB Server
Component/s: Optimizer
Affects Version/s: 10.1, 10.2.15, 10.2, 10.3
Fix Version/s: 10.3

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

Linux

Attachments: File db_export.sql     File mdev-16289.test     File query.sql    

 Description    

SELECT
 
    *
 
FROM
 
    `matched_activities` AS `ma_main`
 
WHERE
 
    `created_at` < "2018-05-22 18:40:23.700872" AND `created_at` > "2018-05-22 16:50:23.700957" AND NOT EXISTS(
 
    SELECT
 
        1
 
    FROM
 
        `searches`
 
    WHERE
 
        (
 
            searches.id = ma_main.search1_id OR searches.id = ma_main.search2_id
 
        ) AND `deleted_at` IS NOT NULL
 
) AND NOT EXISTS(
 
    SELECT
 
        1
 
    FROM
 
        `searches` AS `searches_outer`
 
    WHERE
 
        searches_outer.id = ma_main.search1_id AND EXISTS(
 
        SELECT
 
            1
 
        FROM
 
            `searches` AS `searches_inner`
 
        WHERE
 
            searches_inner.user_id = searches_outer.user_id AND EXISTS(
 
            SELECT
 
                1
 
            FROM
 
                `matched_activities` AS `ma_same_user`
 
            WHERE
 
                (
 
                    ma_same_user.search1_id = searches_inner.id AND `ma_same_user`.`user1_last_notification_at` > "2018-05-21 18:50:23"
 
                ) OR(
 
                    ma_same_user.search2_id = searches_inner.id AND `ma_same_user`.`user2_last_notification_at` > "2018-05-21 18:50:23"
 
                )
 
        )
 
    )
 
)

MariaDB-10.2.15

Empty set (54.12 sec)
 
 
 
(root:localhost) [test]> explain SELECT     * FROM     `matched_activities` AS `ma_main` WHERE     `created_at` < "2018-05-22 18:40:23.700872" AND `created_at` > "2018-05-22 16:50:23.700957" AND NOT EXISTS(     SELECT         1     FROM         `searches`     WHERE         (             searches.id = ma_main.search1_id OR searches.id = ma_main.search2_id         ) AND `deleted_at` IS NOT NULL ) AND NOT EXISTS(     SELECT         1     FROM         `searches` AS `searches_outer`     WHERE         searches_outer.id = ma_main.search1_id AND EXISTS(         SELECT             1         FROM             `searches` AS `searches_inner`         WHERE             searches_inner.user_id = searches_outer.user_id AND EXISTS(             SELECT                 1             FROM                 `matched_activities` AS `ma_same_user`             WHERE                 (                     ma_same_user.search1_id = searches_inner.id AND `ma_same_user`.`user1_last_notification_at` > "2018-05-21 18:50:23"                 ) OR(                     ma_same_user.search2_id = searches_inner.id AND `ma_same_user`.`user2_last_notification_at` > "2018-05-21 18:50:23"                 )         )     ) );
 
+------+--------------------+----------------+--------+---------------------------------------------------------------------------------------+--------------------------+---------+------+-------+--------------------------+
 
| id   | select_type        | table          | type   | possible_keys                                                                         | key                      | key_len | ref  | rows  | Extra                    |
 
+------+--------------------+----------------+--------+---------------------------------------------------------------------------------------+--------------------------+---------+------+-------+--------------------------+
 
|    1 | PRIMARY            | ma_main        | ALL    | NULL                                                                                  | NULL                     | NULL    | NULL | 23383 | Using where              |
 
|    3 | MATERIALIZED       | searches_outer | index  | PRIMARY,searches_user_id_foreign                                                      | searches_user_id_foreign | 4       | NULL |  8496 | Using index              |
 
|    3 | MATERIALIZED       | <subquery4>    | eq_ref | distinct_key                                                                          | distinct_key             | 4       | func |     1 |                          |
 
|    4 | MATERIALIZED       | searches_inner | index  | searches_user_id_foreign                                                              | searches_user_id_foreign | 4       | NULL |  8496 | Using where; Using index |
 
|    5 | DEPENDENT SUBQUERY | ma_same_user   | ALL    | matched_activities_search1_id_search2_id_unique,matched_activities_search2_id_foreign | NULL                     | NULL    | NULL | 23383 | Using where              |
 
|    2 | DEPENDENT SUBQUERY | searches       | ALL    | PRIMARY                                                                               | NULL                     | NULL    | NULL |  8496 | Using where              |
 
+------+--------------------+----------------+--------+---------------------------------------------------------------------------------------+--------------------------+---------+------+-------+--------------------------+
 
6 rows in set (0.00 sec)

MySQL-5.6

Empty set (0.64 sec)
 
 
 
(root:localhost) [test]> explain SELECT     * FROM     `matched_activities` AS `ma_main` WHERE     `created_at` < "2018-05-22 18:40:23.700872" AND `created_at` > "2018-05-22 16:50:23.700957" AND NOT EXISTS(     SELECT         1     FROM         `searches`     WHERE         (             searches.id = ma_main.search1_id OR searches.id = ma_main.search2_id         ) AND `deleted_at` IS NOT NULL ) AND NOT EXISTS(     SELECT         1     FROM         `searches` AS `searches_outer`     WHERE         searches_outer.id = ma_main.search1_id AND EXISTS(         SELECT             1         FROM             `searches` AS `searches_inner`         WHERE             searches_inner.user_id = searches_outer.user_id AND EXISTS(             SELECT                 1             FROM                 `matched_activities` AS `ma_same_user`             WHERE                 (                     ma_same_user.search1_id = searches_inner.id AND `ma_same_user`.`user1_last_notification_at` > "2018-05-21 18:50:23"                 ) OR(                     ma_same_user.search2_id = searches_inner.id AND `ma_same_user`.`user2_last_notification_at` > "2018-05-21 18:50:23"                 )         )     ) );        
+----+--------------------+----------------+--------+---------------------------------------------------------------------------------------+--------------------------+---------+-----------------------------+-------+------------------------------------------------+
 
| id | select_type        | table          | type   | possible_keys                                                                         | key                      | key_len | ref                         | rows  | Extra                                          |
 
+----+--------------------+----------------+--------+---------------------------------------------------------------------------------------+--------------------------+---------+-----------------------------+-------+------------------------------------------------+
 
|  1 | PRIMARY            | ma_main        | ALL    | NULL                                                                                  | NULL                     | NULL    | NULL                        | 22796 | Using where                                    |
 
|  3 | DEPENDENT SUBQUERY | searches_outer | eq_ref | PRIMARY                                                                               | PRIMARY                  | 4       | test.ma_main.search1_id     |     1 | Using where                                    |
 
|  4 | DEPENDENT SUBQUERY | searches_inner | ref    | searches_user_id_foreign                                                              | searches_user_id_foreign | 4       | test.searches_outer.user_id |     9 | Using where; Using index                       |
 
|  5 | DEPENDENT SUBQUERY | ma_same_user   | ALL    | matched_activities_search1_id_search2_id_unique,matched_activities_search2_id_foreign | NULL                     | NULL    | NULL                        | 22796 | Range checked for each record (index map: 0x6) |
 
|  2 | DEPENDENT SUBQUERY | searches       | ALL    | PRIMARY                                                                               | NULL                     | NULL    | NULL                        |  8496 | Range checked for each record (index map: 0x1) |
 
+----+--------------------+----------------+--------+---------------------------------------------------------------------------------------+--------------------------+---------+-----------------------------+-------+------------------------------------------------+
 
5 rows in set (0.00 sec)



 Comments   
Comment by Alice Sherepa [ 2018-05-29 ]

on 10.2.15 query execution takes around 40-60s. But it looks like it is dependent of time_zone, if I set the same time_zone as it is set in a dump of tables, then results were returned immediately;
same behavior is reproducible with 10.1,10.2,10.3 (mdev-16289.test)

analyze format=json SELECT *
 
FROM `matched_activities` 
WHERE `created_at` < "2018-05-22 18:40:23.700872"
 
  AND `created_at` > "2018-05-22 16:50:23.700957"
 
  AND NOT EXISTS( SELECT 1 FROM `searches` WHERE ( searches.id = matched_activities.search1_id OR searches.id = matched_activities.search2_id ) AND `deleted_at` IS NOT NULL)
 
  AND NOT EXISTS( SELECT 1 FROM `searches` AS `searches_outer` WHERE searches_outer.id = matched_activities.search1_id
 
      AND EXISTS( SELECT 1 FROM `searches` AS `searches_inner`
 
                  WHERE searches_inner.user_id = searches_outer.user_id
 
      AND EXISTS( SELECT 1 FROM `matched_activities` AS `ma_same_user`
 
                WHERE (ma_same_user.search1_id = searches_inner.id AND `ma_same_user`.`user1_last_notification_at` > "2018-05-21 18:50:23") 
                   OR (ma_same_user.search2_id = searches_inner.id AND `ma_same_user`.`user2_last_notification_at` > "2018-05-21 18:50:23"))));


 {
 
  "query_block": {
 
    "select_id": 1,
 
    "r_loops": 1,
 
    "r_total_time_ms": 41199,
 
    "table": {
 
      "table_name": "matched_activities",
 
      "access_type": "ALL",
 
      "r_loops": 1,
 
      "rows": 22796,
 
      "r_rows": 23071,
 
      "r_total_time_ms": 4.9087,
 
      "filtered": 100,
 
      "r_filtered": 0,
 
      "attached_condition": "matched_activities.created_at < '2018-05-22 18:40:23.700872' and matched_activities.created_at > '2018-05-22 16:50:23.700957' and !<in_optimizer>(1,exists(subquery#2)) and !<in_optimizer>(matched_activities.search1_id,matched_activities.search1_id in (subquery#3))"
 
    },
 
    "subqueries": [
 
      {
 
        "query_block": {
 
          "select_id": 3,
 
          "r_loops": 1,
 
          "r_total_time_ms": 41165,
 
          "table": {
 
            "table_name": "searches_outer",
 
            "access_type": "index",
 
            "possible_keys": ["PRIMARY", "searches_user_id_foreign"],
 
            "key": "searches_user_id_foreign",
 
            "key_length": "4",
 
            "used_key_parts": ["user_id"],
 
            "r_loops": 1,
 
            "rows": 8496,
 
            "r_rows": 8496,
 
            "r_total_time_ms": 0.9828,
 
            "filtered": 100,
 
            "r_filtered": 100,
 
            "using_index": true
 
          },
 
          "table": {
 
            "table_name": "<subquery4>",
 
            "access_type": "eq_ref",
 
            "possible_keys": ["distinct_key"],
 
            "key": "distinct_key",
 
            "key_length": "4",
 
            "used_key_parts": ["user_id"],
 
            "ref": ["func"],
 
            "r_loops": 8496,
 
            "rows": 1,
 
            "r_rows": 0.4256,
 
            "r_total_time_ms": 0.1105,
 
            "filtered": 100,
 
            "r_filtered": 100,
 
            "materialized": {
 
              "unique": 1,
 
              "query_block": {
 
                "select_id": 4,
 
                "table": {
 
                  "table_name": "searches_inner",
 
                  "access_type": "index",
 
                  "possible_keys": ["searches_user_id_foreign"],
 
                  "key": "searches_user_id_foreign",
 
                  "key_length": "4",
 
                  "used_key_parts": ["user_id"],
 
                  "r_loops": 1,
 
                  "rows": 8496,
 
                  "r_rows": 8496,
 
                  "r_total_time_ms": 1.443,
 
                  "filtered": 100,
 
                  "r_filtered": 1.7067,
 
                  "attached_condition": "<in_optimizer>(1,exists(subquery#5))",
 
                  "using_index": true
 
                }
 
              }
 
            }
 
          },
 
          "subqueries": [
 
            {
 
              "expression_cache": {
 
                "state": "disabled",
 
                "r_loops": 200,
 
                "r_hit_ratio": 0,
 
                "query_block": {
 
                  "select_id": 5,
 
                  "r_loops": 8496,
 
                  "r_total_time_ms": 41158,
 
                  "table": {
 
                    "table_name": "ma_same_user",
 
                    "access_type": "ALL",
 
                    "possible_keys": [
 
                      "matched_activities_search1_id_search2_id_unique",
 
                      "matched_activities_search2_id_foreign"
 
                    ],
 
                    "r_loops": 8496,
 
                    "rows": 22796,
 
                    "r_rows": 23055,
 
                    "r_total_time_ms": 27456,
 
                    "filtered": 100,
 
                    "r_filtered": 7.4e-5,
 
                    "attached_condition": "ma_same_user.search1_id = searches_inner.`id` and ma_same_user.user1_last_notification_at > '2018-05-21 18:50:23' or ma_same_user.search2_id = searches_inner.`id` and ma_same_user.user2_last_notification_at > '2018-05-21 18:50:23'"
 
                  }
 
                }
 
              }
 
            }
 
          ]
 
        }
 
      },
 
      {
 
        "expression_cache": {
 
          "r_loops": 15,
 
          "r_hit_ratio": 0,
 
          "query_block": {
 
            "select_id": 2,
 
            "r_loops": 15,
 
            "r_total_time_ms": 22.882,
 
            "table": {
 
              "table_name": "searches",
 
              "access_type": "ALL",
 
              "possible_keys": ["PRIMARY"],
 
              "r_loops": 15,
 
              "rows": 8496,
 
              "r_rows": 8496,
 
              "r_total_time_ms": 14.954,
 
              "filtered": 100,
 
              "r_filtered": 0,
 
              "attached_condition": "(searches.`id` = matched_activities.search1_id or searches.`id` = matched_activities.search2_id) and searches.deleted_at is not null"
 
            }
 
          }
 
        }
 
      }
 
    ]
 
  }
 
} |

if we have SET time_zone = "+00:00";

 {
 
  "query_block": {
 
    "select_id": 1,
 
    "r_loops": 1,
 
    "r_total_time_ms": 12.433,
 
    "table": {
 
      "table_name": "matched_activities",
 
      "access_type": "ALL",
 
      "r_loops": 1,
 
      "rows": 23383,
 
      "r_rows": 23071,
 
      "r_total_time_ms": 7.0843,
 
      "filtered": 100,
 
      "r_filtered": 0,
 
      "attached_condition": "matched_activities.created_at < '2018-05-22 18:40:23.700872' and matched_activities.created_at > '2018-05-22 16:50:23.700957' and !<in_optimizer>(1,exists(subquery#2)) and !<in_optimizer>(matched_activities.search1_id,matched_activities.search1_id in (subquery#3))"
 
    },
 
    "subqueries": [
 
      {
 
        "query_block": {
 
          "select_id": 3,
 
          "table": {
 
            "table_name": "searches_outer",
 
            "access_type": "index",
 
            "possible_keys": ["PRIMARY", "searches_user_id_foreign"],
 
            "key": "searches_user_id_foreign",
 
            "key_length": "4",
 
            "used_key_parts": ["user_id"],
 
            "r_loops": 0,
 
            "rows": 8496,
 
            "r_rows": null,
 
            "filtered": 100,
 
            "r_filtered": null,
 
            "using_index": true
 
          },
 
          "table": {
 
            "table_name": "<subquery4>",
 
            "access_type": "eq_ref",
 
            "possible_keys": ["distinct_key"],
 
            "key": "distinct_key",
 
            "key_length": "4",
 
            "used_key_parts": ["user_id"],
 
            "ref": ["func"],
 
            "r_loops": 0,
 
            "rows": 1,
 
            "r_rows": null,
 
            "filtered": 100,
 
            "r_filtered": null,
 
            "materialized": {
 
              "unique": 1,
 
              "query_block": {
 
                "select_id": 4,
 
                "table": {
 
                  "table_name": "searches_inner",
 
                  "access_type": "index",
 
                  "possible_keys": ["searches_user_id_foreign"],
 
                  "key": "searches_user_id_foreign",
 
                  "key_length": "4",
 
                  "used_key_parts": ["user_id"],
 
                  "r_loops": 0,
 
                  "rows": 8496,
 
                  "r_rows": null,
 
                  "filtered": 100,
 
                  "r_filtered": null,
 
                  "attached_condition": "<in_optimizer>(1,exists(subquery#5))",
 
                  "using_index": true
 
                }
 
              }
 
            }
 
          },
 
          "subqueries": [
 
            {
 
              "expression_cache": {
 
                "state": "uninitialized",
 
                "r_loops": 0,
 
                "query_block": {
 
                  "select_id": 5,
 
                  "table": {
 
                    "table_name": "ma_same_user",
 
                    "access_type": "ALL",
 
                    "possible_keys": [
 
                      "matched_activities_search1_id_search2_id_unique",
 
                      "matched_activities_search2_id_foreign"
 
                    ],
 
                    "r_loops": 0,
 
                    "rows": 23383,
 
                    "r_rows": null,
 
                    "filtered": 100,
 
                    "r_filtered": null,
 
                    "attached_condition": "ma_same_user.search1_id = searches_inner.`id` and ma_same_user.user1_last_notification_at > '2018-05-21 18:50:23' or ma_same_user.search2_id = searches_inner.`id` and ma_same_user.user2_last_notification_at > '2018-05-21 18:50:23'"
 
                  }
 
                }
 
              }
 
            }
 
          ]
 
        }
 
      },
 
      {
 
        "expression_cache": {
 
          "state": "uninitialized",
 
          "r_loops": 0,
 
          "query_block": {
 
            "select_id": 2,
 
            "table": {
 
              "table_name": "searches",
 
              "access_type": "ALL",
 
              "possible_keys": ["PRIMARY"],
 
              "r_loops": 0,
 
              "rows": 8496,
 
              "r_rows": null,
 
              "filtered": 100,
 
              "r_filtered": null,
 
              "attached_condition": "(searches.`id` = matched_activities.search1_id or searches.`id` = matched_activities.search2_id) and searches.deleted_at is not null"
 
            }
 
          }
 
        }
 
      }
 
    ]
 
  }
 
}

Comment by Lingmei Weng [ 2022-09-23 ]

I run into this bug report while exploring the unresolved bug for our research project on performance diagnosis. With our tool, we noticed the different time zones resulted in different clust_index and result_rec access patterns in row_search_mvcc. The processing time for an individual result_rec is similar. Therefore we suspected it was not a performance bug. The root cause is that at different timezones, the results for the query are different, and so do the query time.

We verified it by setting the timezone and the timestamp conditions in the query correspondingly to ensure they return the same results. By measuring the execution time, there is no difference.

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