[MDEV-31604] scanning table rows is slower (10->20%) in 11.0.2 compared to 10.6 Created: 2023-07-02  Updated: 2023-11-28

Status: Open
Project: MariaDB Server
Component/s: Optimizer, Storage Engine - InnoDB
Affects Version/s: 11.0.2
Fix Version/s: 10.11

Type: Bug Priority: Major
Reporter: Daniel Black Assignee: Unassigned
Resolution: Unresolved Votes: 0
Labels: regression-10.6


 Description   

From SO question (since deleted by author).

Recently we have updated to a latest stable version of 11.0.2 Maria db suddenly i was facing slowness on some of my queries if the same query ran in 10.6 it was fast in 10.6 it was run 5sec but after upgrading it's ran nearly 20 seconds ,i tried this answer too but not helpful ,if any suggestions to overcome this issue.

 SELECT
    `ft_fieldName` AS `Field Name`,
    `prm_id` AS `recipeid`,
    '' AS 'Pricing Type',
    'BOM' AS 'GROUP',
    '' AS 'Qty',
    JSON_UNQUOTE(
        JSON_EXTRACT(cd_custmzdcolrdetails, '$.299')
    ) AS `colorname`,
   
    JSON_UNQUOTE(
        JSON_EXTRACT(cd_custmzdcolrdetails, '$.300')
    ) AS `Color Code`,
  
  
   
    JSON_UNQUOTE(
        JSON_EXTRACT(cd_custmzdcolrdetails, '$.357')
    ) AS `Unit Cost`,
    `dropdown_name` AS `Unit Type`,
    COUNT(pgmm_productmapid) AS pgmm_fabriccolormapid
    
FROM
    `bm_productrecipemap` FORCE INDEX(`prm_status`)
INNER JOIN `bm_productgroupmaterialmap` ON `pgmm_id` = `prm_fieldvalueid` AND `pgmm_status` = 0  
INNER JOIN `bm_fabriccolourmap` ON `pfm_id` = `pgmm_fabriccolormapid` 
INNER JOIN `bm_fabricdetails` ON `pfm_fabricmapid` = `fd_id` AND `fd_status` = 0
INNER JOIN `bm_colordetails` ON `pfm_colourmapid` = `cd_id` AND `cd_status` = 0
INNER JOIN `bm_productInfo` ON `pi_productid` = `pgmm_productmapid` AND `pi_status` = 0
INNER JOIN `bm_productrecipe` ON `pr_id` = `prm_recipeid` AND `pr_status` = 0
INNER JOIN `bm_fieldtypes` ON `ft_id` = `prm_fieldtypeid` AND `ft_status` = 0
LEFT JOIN `bm_common_dropdown_list` ON `dropdown_primaryid` = JSON_UNQUOTE(
        JSON_EXTRACT(cd_custmzdcolrdetails, '$.355')
    ) AND `dropdown_tag_name` = "unit_type"
WHERE
    `prm_status` = 0 AND `prm_recipeid` = 18 AND `prm_fieldtypeid` = 22
GROUP BY
    `pgmm_fabriccolormapid`,
    `pgmm_productmapid`

10.6 analyze format = json

{
  "query_block": {
    "select_id": 1,
    "r_loops": 1,
    "r_total_time_ms": 4362.336552,
    "filesort": {
      "sort_key": "bm_productgroupmaterialmap.pgmm_fabriccolormapid, bm_productgroupmaterialmap.pgmm_productmapid",
      "r_loops": 1,
      "r_total_time_ms": 2.977471882,
      "r_used_priority_queue": false,
      "r_output_rows": 19460,
      "r_buffer_size": "437Kb",
      "r_sort_mode": "sort_key,rowid",
      "temporary_table": {
        "table": {
          "table_name": "bm_productrecipe",
          "access_type": "const",
          "possible_keys": ["PRIMARY", "pr_status"],
          "key": "PRIMARY",
          "key_length": "4",
          "used_key_parts": ["pr_id"],
          "ref": ["const"],
          "r_loops": 0,
          "rows": 1,
          "r_rows": null,
          "filtered": 100,
          "r_filtered": null
        },
        "table": {
          "table_name": "bm_fieldtypes",
          "access_type": "const",
          "possible_keys": ["PRIMARY", "ft_status"],
          "key": "PRIMARY",
          "key_length": "4",
          "used_key_parts": ["ft_id"],
          "ref": ["const"],
          "r_loops": 0,
          "rows": 1,
          "r_rows": null,
          "filtered": 100,
          "r_filtered": null
        },
        "table": {
          "table_name": "bm_productrecipemap",
          "access_type": "ref",
          "possible_keys": ["prm_status"],
          "key": "prm_status",
          "key_length": "4",
          "used_key_parts": ["prm_status"],
          "ref": ["const"],
          "r_loops": 1,
          "rows": 621390,
          "r_rows": 1250923,
          "r_table_time_ms": 1525.038047,
          "r_other_time_ms": 72.17298694,
          "filtered": 100,
          "r_filtered": 26.45182797,
          "attached_condition": "bm_productrecipemap.prm_recipeid = 18 and bm_productrecipemap.prm_fieldtypeid = 22"
        },
        "table": {
          "table_name": "bm_productgroupmaterialmap",
          "access_type": "eq_ref",
          "possible_keys": [
            "PRIMARY",
            "pgmm_status",
            "pgmm_fabriccolormapid",
            "pgmm_productmapid"
          ],
          "key": "PRIMARY",
          "key_length": "4",
          "used_key_parts": ["pgmm_id"],
          "ref": ["CREATIVECURTAINSSUSSEX.bm_productrecipemap.prm_fieldvalueid"],
          "r_loops": 330892,
          "rows": 1,
          "r_rows": 1,
          "r_table_time_ms": 493.5064977,
          "r_other_time_ms": 140.3322178,
          "filtered": 49.99987411,
          "r_filtered": 100,
          "attached_condition": "bm_productgroupmaterialmap.pgmm_status = 0 and bm_productgroupmaterialmap.pgmm_id = bm_productrecipemap.prm_fieldvalueid"
        },
        "table": {
          "table_name": "bm_productInfo",
          "access_type": "eq_ref",
          "possible_keys": ["PRIMARY", "pi_status"],
          "key": "PRIMARY",
          "key_length": "4",
          "used_key_parts": ["pi_productid"],
          "ref": [
            "CREATIVECURTAINSSUSSEX.bm_productgroupmaterialmap.pgmm_productmapid"
          ],
          "r_loops": 330892,
          "rows": 1,
          "r_rows": 1,
          "r_table_time_ms": 0.00474078,
          "r_other_time_ms": 0.002440078,
          "filtered": 86.79244995,
          "r_filtered": 100,
          "attached_condition": "bm_productInfo.pi_status = 0 and bm_productInfo.pi_productid = bm_productgroupmaterialmap.pgmm_productmapid"
        },
        "table": {
          "table_name": "bm_fabriccolourmap",
          "access_type": "eq_ref",
          "possible_keys": ["PRIMARY", "pfm_fabricmapid", "pfm_colourmapid"],
          "key": "PRIMARY",
          "key_length": "4",
          "used_key_parts": ["pfm_id"],
          "ref": [
            "CREATIVECURTAINSSUSSEX.bm_productgroupmaterialmap.pgmm_fabriccolormapid"
          ],
          "r_loops": 330892,
          "rows": 1,
          "r_rows": 1,
          "r_table_time_ms": 309.0945127,
          "r_other_time_ms": 30.59452498,
          "filtered": 100,
          "r_filtered": 100,
          "attached_condition": "bm_fabriccolourmap.pfm_id = bm_productgroupmaterialmap.pgmm_fabriccolormapid and bm_fabriccolourmap.pfm_colourmapid is not null"
        },
        "table": {
          "table_name": "bm_fabricdetails",
          "access_type": "eq_ref",
          "possible_keys": ["PRIMARY", "fd_status"],
          "key": "PRIMARY",
          "key_length": "4",
          "used_key_parts": ["fd_id"],
          "ref": ["CREATIVECURTAINSSUSSEX.bm_fabriccolourmap.pfm_fabricmapid"],
          "r_loops": 330892,
          "rows": 1,
          "r_rows": 1,
          "r_table_time_ms": 290.3357413,
          "r_other_time_ms": 35.36422041,
          "filtered": 49.99639511,
          "r_filtered": 99.97824063,
          "attached_condition": "bm_fabricdetails.fd_status = 0 and bm_fabriccolourmap.pfm_fabricmapid = bm_fabricdetails.fd_id"
        },
        "table": {
          "table_name": "bm_colordetails",
          "access_type": "eq_ref",
          "possible_keys": ["PRIMARY", "cd_status", "cd_fabricmapid"],
          "key": "PRIMARY",
          "key_length": "4",
          "used_key_parts": ["cd_id"],
          "ref": ["CREATIVECURTAINSSUSSEX.bm_fabriccolourmap.pfm_colourmapid"],
          "r_loops": 330820,
          "rows": 1,
          "r_rows": 1,
          "r_table_time_ms": 317.5412715,
          "r_other_time_ms": 373.7023579,
          "filtered": 50,
          "r_filtered": 100,
          "attached_condition": "bm_colordetails.cd_status = 0 and bm_fabriccolourmap.pfm_colourmapid = bm_colordetails.cd_id"
        },
        "table": {
          "table_name": "bm_common_dropdown_list",
          "access_type": "ref",
          "possible_keys": ["dropdown_primaryid"],
          "key": "dropdown_primaryid",
          "key_length": "5",
          "used_key_parts": ["dropdown_primaryid"],
          "ref": ["func"],
          "r_loops": 330820,
          "rows": 2,
          "r_rows": 0.002363823,
          "r_table_time_ms": 182.2695986,
          "r_other_time_ms": 581.7986746,
          "filtered": 100,
          "r_filtered": 4.347826087,
          "attached_condition": "trigcond(bm_common_dropdown_list.dropdown_tag_name = 'unit_type' and bm_common_dropdown_list.dropdown_primaryid = json_unquote(json_extract(bm_colordetails.cd_custmzdcolrdetails,'$.355')))"
        }
      }
    }
  }
}

11.0.2 analyze explain

{
  "query_optimization": {
    "r_total_time_ms": 7.173012053
  },
  "query_block": {
    "select_id": 1,
    "cost": 18268.14136,
    "r_loops": 1,
    "r_total_time_ms": 9430.630307,
    "filesort": {
      "sort_key": "bm_productgroupmaterialmap.pgmm_fabriccolormapid, bm_productgroupmaterialmap.pgmm_productmapid",
      "r_loops": 1,
      "r_total_time_ms": 3.427513217,
      "r_used_priority_queue": false,
      "r_output_rows": 19460,
      "r_buffer_size": "437Kb",
      "r_sort_mode": "sort_key,rowid",
      "temporary_table": {
        "nested_loop": [
          {
            "table": {
              "table_name": "bm_productrecipe",
              "access_type": "const",
              "possible_keys": ["PRIMARY", "pr_status"],
              "key": "PRIMARY",
              "key_length": "4",
              "used_key_parts": ["pr_id"],
              "ref": ["const"],
              "r_loops": 0,
              "rows": 1,
              "r_rows": null,
              "filtered": 100,
              "r_filtered": null
            }
          },
          {
            "table": {
              "table_name": "bm_fieldtypes",
              "access_type": "const",
              "possible_keys": ["PRIMARY", "ft_status"],
              "key": "PRIMARY",
              "key_length": "4",
              "used_key_parts": ["ft_id"],
              "ref": ["const"],
              "r_loops": 0,
              "rows": 1,
              "r_rows": null,
              "filtered": 100,
              "r_filtered": null
            }
          },
          {
            "table": {
              "table_name": "bm_productrecipemap",
              "access_type": "ref",
              "possible_keys": ["prm_status"],
              "key": "prm_status",
              "key_length": "4",
              "used_key_parts": ["prm_status"],
              "ref": ["const"],
              "loops": 1,
              "r_loops": 1,
              "rows": 1245496,
              "r_rows": 1250925,
              "cost": 1241.246338,
              "r_table_time_ms": 4927.520843,
              "r_other_time_ms": 139.7680558,
              "filtered": 100,
              "r_filtered": 26.45178568,
              "attached_condition": "bm_productrecipemap.prm_recipeid = 18 and bm_productrecipemap.prm_fieldtypeid = 22"
            }
          },
          {
            "table": {
              "table_name": "bm_productgroupmaterialmap",
              "access_type": "eq_ref",
              "possible_keys": [
                "PRIMARY",
                "pgmm_status",
                "pgmm_fabriccolormapid",
                "pgmm_productmapid"
              ],
              "key": "PRIMARY",
              "key_length": "4",
              "used_key_parts": ["pgmm_id"],
              "ref": [
                "CREATIVECURTAINSSUSSEX.bm_productrecipemap.prm_fieldvalueid"
              ],
              "loops": 1245496,
              "r_loops": 330892,
              "rows": 1,
              "r_rows": 1,
              "cost": 1115.676226,
              "r_table_time_ms": 720.8451661,
              "r_other_time_ms": 171.4830087,
              "filtered": 100,
              "r_filtered": 100,
              "attached_condition": "bm_productgroupmaterialmap.pgmm_status = 0 and bm_productgroupmaterialmap.pgmm_id = bm_productrecipemap.prm_fieldvalueid"
            }
          },
          {
            "table": {
              "table_name": "bm_fabriccolourmap",
              "access_type": "eq_ref",
              "possible_keys": ["PRIMARY", "pfm_fabricmapid", "pfm_colourmapid"],
              "key": "PRIMARY",
              "key_length": "4",
              "used_key_parts": ["pfm_id"],
              "ref": [
                "CREATIVECURTAINSSUSSEX.bm_productgroupmaterialmap.pgmm_fabriccolormapid"
              ],
              "loops": 1245496,
              "r_loops": 330892,
              "r_table_loops": 286792,
              "rows": 1,
              "r_rows": 1,
              "cost": 1114.467906,
              "r_table_time_ms": 597.0053344,
              "r_other_time_ms": 53.0959404,
              "filtered": 100,
              "r_filtered": 100,
              "attached_condition": "bm_fabriccolourmap.pfm_id = bm_productgroupmaterialmap.pgmm_fabriccolormapid and bm_fabriccolourmap.pfm_colourmapid is not null"
            }
          },
          {
            "table": {
              "table_name": "bm_fabricdetails",
              "access_type": "eq_ref",
              "possible_keys": ["PRIMARY", "fd_status"],
              "key": "fd_status",
              "key_length": "8",
              "used_key_parts": ["fd_status", "fd_id"],
              "ref": [
                "const",
                "CREATIVECURTAINSSUSSEX.bm_fabriccolourmap.pfm_fabricmapid"
              ],
              "loops": 1245496,
              "r_loops": 330892,
              "r_table_loops": 286219,
              "rows": 1,
              "r_rows": 0.999782406,
              "cost": 1089.076122,
              "r_table_time_ms": 440.3039905,
              "r_other_time_ms": 48.2909558,
              "filtered": 100,
              "r_filtered": 100,
              "attached_condition": "bm_fabriccolourmap.pfm_fabricmapid = bm_fabricdetails.fd_id",
              "using_index": true
            }
          },
          {
            "table": {
              "table_name": "bm_colordetails",
              "access_type": "eq_ref",
              "possible_keys": ["PRIMARY", "cd_status", "cd_fabricmapid"],
              "key": "PRIMARY",
              "key_length": "4",
              "used_key_parts": ["cd_id"],
              "ref": ["CREATIVECURTAINSSUSSEX.bm_fabriccolourmap.pfm_colourmapid"],
              "loops": 1245496,
              "r_loops": 330820,
              "r_table_loops": 286760,
              "rows": 1,
              "r_rows": 1,
              "cost": 1114.520335,
              "r_table_time_ms": 642.1860278,
              "r_other_time_ms": 584.9013592,
              "filtered": 100,
              "r_filtered": 100,
              "attached_condition": "bm_colordetails.cd_status = 0 and bm_fabriccolourmap.pfm_colourmapid = bm_colordetails.cd_id"
            }
          },
          {
            "table": {
              "table_name": "bm_productInfo",
              "access_type": "eq_ref",
              "possible_keys": ["PRIMARY", "pi_status"],
              "key": "pi_status",
              "key_length": "8",
              "used_key_parts": ["pi_status", "pi_productid"],
              "ref": [
                "const",
                "CREATIVECURTAINSSUSSEX.bm_productgroupmaterialmap.pgmm_productmapid"
              ],
              "loops": 1245496,
              "r_loops": 330820,
              "r_table_loops": 1,
              "rows": 1,
              "r_rows": 1,
              "cost": 1089.068749,
              "r_table_time_ms": 0.005281613,
              "r_other_time_ms": 0.021677216,
              "filtered": 100,
              "r_filtered": 100,
              "attached_condition": "bm_productInfo.pi_productid = bm_productgroupmaterialmap.pgmm_productmapid",
              "using_index": true
            }
          },
          {
            "table": {
              "table_name": "bm_common_dropdown_list",
              "access_type": "ref",
              "possible_keys": ["dropdown_primaryid"],
              "key": "dropdown_primaryid",
              "key_length": "5",
              "used_key_parts": ["dropdown_primaryid"],
              "ref": ["func"],
              "loops": 1245496,
              "r_loops": 330820,
              "rows": 5,
              "r_rows": 0.003545735,
              "cost": 7216.307461,
              "r_table_time_ms": 265.3482518,
              "r_other_time_ms": 829.0345013,
              "filtered": 100,
              "r_filtered": 4.347826087,
              "attached_condition": "trigcond(bm_common_dropdown_list.dropdown_tag_name = 'unit_type' and bm_common_dropdown_list.dropdown_primaryid = json_unquote(json_extract(bm_colordetails.cd_custmzdcolrdetails,'$.355')))"
            }
          }
        ]
      }
    }
  }
}

Notes:

  • The query plan is the same except for the nested loop in 11.0.2
  • the row counts on the explain show the same rows and therefore same data.
  • answered on changing the bm_productrecipemap.prm_status(prm_status, prm_recipeid, prm_fieldtypeid), which reduced this to 11 seconds, still a 6 second gap from 10.6

The timing on the tables:

Table rows 10.6 11.02
bm_productrecipemap 1250925 1525.038 4927.52
bm_productgroupmaterialmap row 1, loops 330892 1525.03 720


 Comments   
Comment by Daniel Black [ 2023-07-03 ]

HammerDB 4.7 TPCH default workload:

query, random one from TPCH workload:

select sum(l_extendedprice * l_discount) as revenue from LINEITEM where l_shipdate >= date '1993-01-01' and l_shipdate < date '1993-01-01' + interval '1' year and l_discount between 0.02 - 0.01 and 0.02 + 0.01 and l_quantity < 24

Server in default configuration. ~4th run of the same query:

10.6.5-6d911219d6b1232b0edb6047da322e791c312ae5

MariaDB [test]> analyze format=json select sum(l_extendedprice * l_discount) as revenue from LINEITEM where l_shipdate >= date '1993-01-01' and l_shipdate < date '1993-01-01' + interval '1' year and l_discount between 0.02 - 0.01 and 0.02 + 0.01 and l_quantity < 24\G
*************************** 1. row ***************************
ANALYZE: {
  "query_block": {
    "select_id": 1,
    "r_loops": 1,
    "r_total_time_ms": 4025.785133,
    "table": {
      "table_name": "LINEITEM",
      "access_type": "ALL",
      "r_loops": 1,
      "rows": 5798931,
      "r_rows": 6002441,
      "r_table_time_ms": 3670.818277,
      "r_other_time_ms": 354.9554929,
      "filtered": 100,
      "r_filtered": 1.891730381,
      "attached_condition": "LINEITEM.L_SHIPDATE >= DATE'1993-01-01' and LINEITEM.L_SHIPDATE < '1994-01-01' and LINEITEM.L_DISCOUNT between 0.01 and 0.03 and LINEITEM.L_QUANTITY < 24"
    }
  }
}
1 row in set (4.026 sec)

replica of the 10.6 instance

10.11.5 71a1a28a49075f0dcf280d5653d13fca22de0d7a

MariaDB [test]> analyze format=json select sum(l_extendedprice * l_discount) as revenue from LINEITEM where l_shipdate >= date '1993-01-01' and l_shipdate < date '1993-01-01' + interval '1' year and l_discount between 0.02 - 0.01 and 0.02 + 0.01 and l_quantity < 24\G
*************************** 1. row ***************************
ANALYZE: {
  "query_optimization": {
    "r_total_time_ms": 0.156203573
  },
  "query_block": {
    "select_id": 1,
    "r_loops": 1,
    "r_total_time_ms": 4919.301461,
    "nested_loop": [
      {
        "table": {
          "table_name": "LINEITEM",
          "access_type": "ALL",
          "r_loops": 1,
          "rows": 5977482,
          "r_rows": 6002441,
          "r_table_time_ms": 4533.667656,
          "r_other_time_ms": 385.6227895,
          "filtered": 100,
          "r_filtered": 1.891730381,
          "attached_condition": "LINEITEM.L_SHIPDATE >= DATE'1993-01-01' and LINEITEM.L_SHIPDATE < '1994-01-01' and LINEITEM.L_DISCOUNT between 0.01 and 0.03 and LINEITEM.L_QUANTITY < 24"
        }
      }
    ]
  }
}
1 row in set (4.906 sec)

22% slower on query run.

Version Time on client after 4th run
10.7-latest 3.906
10.8-latest 3.743
10.9.8 latest e1a631fecc364ce1268b13a8108a3186556d660c 4.470
10.10.6 latest 135e9766963ab55e9a1716e98f8b9960759049af 4.594
Comment by Michael Widenius [ 2023-07-07 ]

There seams to be a slowness in InnoDB of about 2-3x.
From the above logs:
10.6:
bm_productrecipemap
"rows": 621390,
"r_rows": 1250923,
"r_table_time_ms": 1525.038047,

11.2:
"rows": 1245496,
"r_rows": 1250925,
"r_table_time_ms": 4927.520843

The difference in rows can be ignore as this is just an estimate from the optimizer.
However the time spent in InnoDB to read the same amount of rows in 11.2 is much higher in 11.2.
This indicates the problem is in InnoDB. Maybe related to pre fetching?

Comment by Marko Mäkelä [ 2023-07-07 ]

I think that to really analyze things like this, we need the data from MDEV-31558. Specifically, the number of pages and undo log records accessed in the InnoDB buffer pool, and the time spent waiting on page reads, during the execution of the statement.

Also, to have a somewhat deterministic starting point, we should start the server with empty undo logs and with no buffer pool warm-up:

  1. initialize the database
  2. load the data
  3. SET GLOBAL innodb_fast_shutdown=0, innodb_buffer_pool_dump_at_shutdown=0
  4. restart
  5. run the benchmark statements

See today’s first update in MDEV-30986 for an example of this.

Comment by Daniel Black [ 2023-07-07 ]

the TPCH datadir is on the ftp server (MDEV-31604.tar.bz2) (apologies for bloat, should of removed binlogs first).

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