[MDEV-28675] Mariadb report takes over 5hrs to run against Mariadb 10.7.3 server Created: 2022-05-26  Updated: 2023-12-19  Resolved: 2023-12-19

Status: Closed
Project: MariaDB Server
Component/s: Server
Affects Version/s: 10.7.3
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Mike Savoie Assignee: Unassigned
Resolution: Won't Fix Votes: 0
Labels: None

Attachments: Text File Mariadb_10_6_7_GOSALESDW_variables-1.txt     Text File Mariadb_10_6_7_GOSALESDW_variables.txt     Text File Mariadb_10_6_7_gosalesdw_explain_format_json.txt     Text File Mariadb_10_7_3_GOSALESDW_variables-1.txt     Text File Mariadb_10_7_3_GOSALESDW_variables.txt     Text File Mariadb_10_7_3_gosalesdw_explain_format_json.txt     Text File Slowsql.txt     Text File executed_analyze_table_statements_gosalesxx_1021.txt     File gosales_1021.7z     PNG File image-2022-05-26-12-21-48-483.png     PNG File image-2022-05-26-12-22-15-539.png     PNG File image-2022-05-26-12-31-53-239.png     PNG File image-2022-05-26-12-33-16-432.png     Text File show_variables_10.7.3.txt    

 Description   

One of our reports is extremely slow when run against 10.7.3 server. It takes over 5 hours whereas the same report run against 10.6.7 takes only 2 minutes. The SQL has been attached (slowsql.txt)

Screenshot for Results against 10.7.3

Screenshot for Results against 10.6.7

I have reproduced the results in a third party product called Squirrel.

When running the query and returning 100 rows for 10.6.7
the query results are returned in 37.588 seconds

When running the query and returning 100 rows for 10.7.3
the query results are returned in 544.163 seconds

When running the query and returning 1000 rows for 10.6.7
the query results are returned in 86.245 seconds

Screenshot for 10.6.7

When running the query and returning 1000 rows for 10.7.3
the query results are returned in 3376.95 seconds

Screenshot for 10.7.3

Attached is the 7zip compressed file for ddl (gosales_1021.7z) and the sql which is extremely slow (slowsql.txt)

 Comments   
Comment by Elena Stepanova [ 2022-05-27 ]

Could you please run EXPLAIN FORMAT=JSON <slow query> on both versions and paste the result?

I assume gosales_1021.7z was meant to provide the schema to run the query, but the tables within it don't correlate with the query and I don't see an obvious way to match them. Could you please check?

Please also paste or attach your cnf file(s) or the output of SHOW VARIABLES.

Comment by Mike Savoie [ 2022-05-27 ]

I have attached the results for EXPLAIN FORMAT=JSON for both versions

Mariadb_10_7_3_gosalesdw_explain_format_json.txt
Mariadb_10_6_7_gosalesdw_explain_format_json.txt

I have also attached the results of SHOW VARIABLES for both versions

Mariadb_10_7_3_GOSALESDW_variables.txt
Mariadb_10_6_7_GOSALESDW_variables.txt

And I had given the wrong schema. It should have been gosalesdw_1021 schema.
I am trying to attach the zip file for it but it complains that it is too large.

Comment by Mike Savoie [ 2022-05-27 ]

The schema is gosalesdw_1021. I am trying to add the zip, but it complains that it is too large.

How do I provide the zip to you

thanks
Mike

Comment by Elena Stepanova [ 2022-05-27 ]

You can upload zip file to the ftp server as described here: https://mariadb.com/kb/en/meta/mariadb-ftp-server/

Comment by Mike Savoie [ 2022-05-27 ]

I uploaded the file gosalesdw_1021.sql.zip to the private folder

Comment by Elena Stepanova [ 2022-05-28 ]

Thanks, on the new data the query runs smoothly.
However, I can't reproduce the difference.
On 10.6 I'm getting the plan very much like yours, and the query execution time in the range of 30-45 seconds.
On 10.7.3 the plan is quite different, both from yours and from the one we are getting on 10.6, but the execution time is still within the same range.

Maybe there is something in the variables that makes the difference. The variables you attached are truncated, possibly the output was paginated and only the first page got in. Could you please attach the full list?

Comment by Mike Savoie [ 2022-05-30 ]

I re-attached the variables.

Comment by Elena Stepanova [ 2022-05-30 ]

Sorry, it's still rather badly truncated, now in terms of line length:

optimizer_switch                                    index_merge=on,index_merge_union=on,index_merge_so  
sql_mode                                            IGNORE_SPACE,STRICT_TRANS_TABLES,ERROR_FOR_DIVISIO

etc.

Comment by Mike Savoie [ 2022-05-30 ]

My DBA reran the statement in the mysql cli and captured the output in a text file (show_variables_10.7.3.txt). It has been attached.

Comment by Alice Sherepa [ 2022-08-01 ]

I can't repeat it, on 10.7.3 on my machine I get query execution time around 47s, with limit 100 ~ 13s
and the same query plan as you were getting on 10.6.7:

10.7.3

 
| {
 
  "query_block": {
 
    "select_id": 1,
 
    "table": {
 
      "table_name": "GO_BRANCH_DIM",
 
      "access_type": "const",
 
      "possible_keys": ["PRIMARY", "SQL131018160540360"],
 
      "key": "PRIMARY",
 
      "key_length": "4",
 
      "used_key_parts": ["BRANCH_KEY"],
 
      "ref": ["const"],
 
      "rows": 1,
 
      "filtered": 100
 
    },
 
    "table": {
 
      "table_name": "GO_REGION_DIM",
 
      "access_type": "ALL",
 
      "rows": 21,
 
      "filtered": 100,
 
      "attached_condition": "go_region_dim.REGION_CODE = 740"
 
    },
 
    "block-nl-join": {
 
      "table": {
 
        "table_name": "SLS_PRODUCT_DIM",
 
        "access_type": "ALL",
 
        "possible_keys": ["PRIMARY", "SQL131018160555680"],
 
        "rows": 274,
 
        "filtered": 100
 
      },
 
      "buffer_type": "flat",
 
      "buffer_size": "217",
 
      "join_type": "BNL",
 
      "attached_condition": "sls_product_dim.PRODUCT_COLOR_CODE is not null and sls_product_dim.PRODUCT_BRAND_CODE is not null and sls_product_dim.PRODUCT_SIZE_CODE is not null"
 
    },
 
    "table": {
 
      "table_name": "SLS_PRODUCT_TYPE_LOOKUP",
 
      "access_type": "eq_ref",
 
      "possible_keys": ["PRIMARY", "SQL131018160557050"],
 
      "key": "PRIMARY",
 
      "key_length": "4",
 
      "used_key_parts": ["PRODUCT_TYPE_CODE"],
 
      "ref": ["test.SLS_PRODUCT_DIM.PRODUCT_TYPE_CODE"],
 
      "rows": 1,
 
      "filtered": 100,
 
      "using_index": true
 
    },
 
    "table": {
 
      "table_name": "SLS_PRODUCT_LINE_LOOKUP",
 
      "access_type": "eq_ref",
 
      "possible_keys": ["PRIMARY", "SQL131018160555930"],
 
      "key": "PRIMARY",
 
      "key_length": "4",
 
      "used_key_parts": ["PRODUCT_LINE_CODE"],
 
      "ref": ["test.SLS_PRODUCT_DIM.PRODUCT_LINE_CODE"],
 
      "rows": 1,
 
      "filtered": 100,
 
      "using_index": true
 
    },
 
    "table": {
 
      "table_name": "SLS_PRODUCT_COLOR_LOOKUP",
 
      "access_type": "eq_ref",
 
      "possible_keys": ["PRIMARY", "SQL131018160555400"],
 
      "key": "PRIMARY",
 
      "key_length": "4",
 
      "used_key_parts": ["PRODUCT_COLOR_CODE"],
 
      "ref": ["test.SLS_PRODUCT_DIM.PRODUCT_COLOR_CODE"],
 
      "rows": 1,
 
      "filtered": 100,
 
      "using_index": true
 
    },
 
    "table": {
 
      "table_name": "SLS_PRODUCT_BRAND_LOOKUP",
 
      "access_type": "eq_ref",
 
      "possible_keys": ["PRIMARY", "SQL131018160555130"],
 
      "key": "PRIMARY",
 
      "key_length": "4",
 
      "used_key_parts": ["PRODUCT_BRAND_CODE"],
 
      "ref": ["test.SLS_PRODUCT_DIM.PRODUCT_BRAND_CODE"],
 
      "rows": 1,
 
      "filtered": 100,
 
      "using_index": true
 
    },
 
    "table": {
 
      "table_name": "SLS_PRODUCT_SIZE_LOOKUP",
 
      "access_type": "eq_ref",
 
      "possible_keys": ["PRIMARY", "SQL131018160556800"],
 
      "key": "PRIMARY",
 
      "key_length": "4",
 
      "used_key_parts": ["PRODUCT_SIZE_CODE"],
 
      "ref": ["test.SLS_PRODUCT_DIM.PRODUCT_SIZE_CODE"],
 
      "rows": 1,
 
      "filtered": 100,
 
      "using_index": true
 
    },
 
    "table": {
 
      "table_name": "SLS_PRODUCT_DIM",
 
      "access_type": "eq_ref",
 
      "possible_keys": ["PRIMARY", "SQL131018160555680"],
 
      "key": "PRIMARY",
 
      "key_length": "4",
 
      "used_key_parts": ["PRODUCT_KEY"],
 
      "ref": ["test.SLS_PRODUCT_DIM.PRODUCT_KEY"],
 
      "rows": 1,
 
      "filtered": 100,
 
      "attached_condition": "sls_product_dim.PRODUCT_TYPE_KEY = 961 and sls_product_dim.PRODUCT_BRAND_CODE is not null and sls_product_dim.PRODUCT_COLOR_CODE is not null and sls_product_dim.PRODUCT_SIZE_CODE is not null"
 
    },
 
    "table": {
 
      "table_name": "SLS_PRODUCT_BRAND_LOOKUP",
 
      "access_type": "eq_ref",
 
      "possible_keys": ["PRIMARY", "SQL131018160555130"],
 
      "key": "PRIMARY",
 
      "key_length": "4",
 
      "used_key_parts": ["PRODUCT_BRAND_CODE"],
 
      "ref": ["test.SLS_PRODUCT_DIM.PRODUCT_BRAND_CODE"],
 
      "rows": 1,
 
      "filtered": 100,
 
      "using_index": true
 
    },
 
    "table": {
 
      "table_name": "SLS_PRODUCT_COLOR_LOOKUP",
 
      "access_type": "eq_ref",
 
      "possible_keys": ["PRIMARY", "SQL131018160555400"],
 
      "key": "PRIMARY",
 
      "key_length": "4",
 
      "used_key_parts": ["PRODUCT_COLOR_CODE"],
 
      "ref": ["test.SLS_PRODUCT_DIM.PRODUCT_COLOR_CODE"],
 
      "rows": 1,
 
      "filtered": 100,
 
      "using_index": true
 
    },
 
    "table": {
 
      "table_name": "SLS_PRODUCT_SIZE_LOOKUP",
 
      "access_type": "eq_ref",
 
      "possible_keys": ["PRIMARY", "SQL131018160556800"],
 
      "key": "PRIMARY",
 
      "key_length": "4",
 
      "used_key_parts": ["PRODUCT_SIZE_CODE"],
 
      "ref": ["test.SLS_PRODUCT_DIM.PRODUCT_SIZE_CODE"],
 
      "rows": 1,
 
      "filtered": 100,
 
      "using_index": true
 
    },
 
    "table": {
 
      "table_name": "SLS_PRODUCT_LINE_LOOKUP",
 
      "access_type": "eq_ref",
 
      "possible_keys": ["PRIMARY", "SQL131018160555930"],
 
      "key": "PRIMARY",
 
      "key_length": "4",
 
      "used_key_parts": ["PRODUCT_LINE_CODE"],
 
      "ref": ["test.SLS_PRODUCT_DIM.PRODUCT_LINE_CODE"],
 
      "rows": 1,
 
      "filtered": 100,
 
      "using_index": true
 
    },
 
    "table": {
 
      "table_name": "SLS_PRODUCT_TYPE_LOOKUP",
 
      "access_type": "eq_ref",
 
      "possible_keys": ["PRIMARY", "SQL131018160557050"],
 
      "key": "PRIMARY",
 
      "key_length": "4",
 
      "used_key_parts": ["PRODUCT_TYPE_CODE"],
 
      "ref": ["test.SLS_PRODUCT_DIM.PRODUCT_TYPE_CODE"],
 
      "rows": 1,
 
      "filtered": 100,
 
      "using_index": true
 
    },
 
    "table": {
 
      "table_name": "SLS_PRODUCT_LOOKUP",
 
      "access_type": "eq_ref",
 
      "possible_keys": ["PRIMARY", "SQL131018160556220"],
 
      "key": "PRIMARY",
 
      "key_length": "96",
 
      "used_key_parts": ["PRODUCT_NUMBER", "PRODUCT_LANGUAGE"],
 
      "ref": ["test.SLS_PRODUCT_DIM.PRODUCT_NUMBER", "const"],
 
      "rows": 1,
 
      "filtered": 100,
 
      "attached_condition": "sls_product_lookup.PRODUCT_LANGUAGE = 'EN'",
 
      "using_index": true
 
    },
 
    "table": {
 
      "table_name": "SLS_PRODUCT_LOOKUP",
 
      "access_type": "eq_ref",
 
      "possible_keys": ["PRIMARY", "SQL131018160556220"],
 
      "key": "PRIMARY",
 
      "key_length": "96",
 
      "used_key_parts": ["PRODUCT_NUMBER", "PRODUCT_LANGUAGE"],
 
      "ref": ["test.SLS_PRODUCT_DIM.PRODUCT_NUMBER", "const"],
 
      "rows": 1,
 
      "filtered": 100,
 
      "attached_condition": "sls_product_lookup.PRODUCT_LANGUAGE = 'EN'",
 
      "using_index": true
 
    },
 
    "block-nl-join": {
 
      "table": {
 
        "table_name": "GO_TIME_DIM",
 
        "access_type": "ALL",
 
        "possible_keys": ["PRIMARY", "SQL131018160542120"],
 
        "rows": 1413,
 
        "filtered": 100
 
      },
 
      "buffer_type": "flat",
 
      "buffer_size": "2047Kb",
 
      "join_type": "BNL"
 
    },
 
    "table": {
 
      "table_name": "SLS_SALES_FACT",
 
      "access_type": "ref",
 
      "possible_keys": ["PRIMARY", "SQL131018160557610"],
 
      "key": "PRIMARY",
 
      "key_length": "4",
 
      "used_key_parts": ["ORDER_DAY_KEY"],
 
      "ref": ["test.GO_TIME_DIM.DAY_KEY"],
 
      "rows": 503,
 
      "filtered": 100,
 
      "attached_condition": "sls_sales_fact.PRODUCT_KEY = sls_product_dim.PRODUCT_KEY"
 
    },
 
    "table": {
 
      "table_name": "SLS_RETAILER_DIM",
 
      "access_type": "eq_ref",
 
      "possible_keys": ["PRIMARY", "SQL131018160557300"],
 
      "key": "PRIMARY",
 
      "key_length": "4",
 
      "used_key_parts": ["RETAILER_SITE_KEY"],
 
      "ref": ["test.SLS_SALES_FACT.RETAILER_SITE_KEY"],
 
      "rows": 1,
 
      "filtered": 100,
 
      "attached_condition": "sls_retailer_dim.RTL_COUNTRY_CODE = go_region_dim.COUNTRY_CODE"
 
    },
 
    "table": {
 
      "table_name": "EMP_EMPLOYEE_DIM",
 
      "access_type": "eq_ref",
 
      "possible_keys": ["PRIMARY", "SQL131018160520020"],
 
      "key": "PRIMARY",
 
      "key_length": "4",
 
      "used_key_parts": ["EMPLOYEE_KEY"],
 
      "ref": ["test.SLS_SALES_FACT.EMPLOYEE_KEY"],
 
      "rows": 1,
 
      "filtered": 100,
 
      "attached_condition": "emp_employee_dim.BRANCH_CODE = 40"
 
    },
 
    "table": {
 
      "table_name": "<derived8>",
 
      "access_type": "ref",
 
      "possible_keys": ["key0"],
 
      "key": "key0",
 
      "key_length": "4",
 
      "used_key_parts": ["Retailer_key"],
 
      "ref": ["test.SLS_RETAILER_DIM.RETAILER_KEY"],
 
      "rows": 10,
 
      "filtered": 100,
 
      "attached_condition": "retailer.Retailer_type_code = 7",
 
      "materialized": {
 
        "query_block": {
 
          "select_id": 8,
 
          "filesort": {
 
            "sort_key": "sls_retailer_dim.RETAILER_KEY",
 
            "temporary_table": {
 
              "table": {
 
                "table_name": "SLS_RETAILER_DIM",
 
                "access_type": "ALL",
 
                "rows": 763,
 
                "filtered": 100,
 
                "attached_condition": "sls_retailer_dim.RETAILER_TYPE_CODE = 7"
 
              }
 
            }
 
          }
 
        }
 
      }
 
    }
 
  }
 
} |
 
 
 
1 row in set (11.864 sec)
 
 
 
MariaDB [test]> select version();
 
+--------------------+
 
| version()          |
 
+--------------------+
 
| 10.7.3-MariaDB-log |
 
+--------------------+
 
1 row in set (0.000 sec)
 
 
 
bulk_insert_buffer_size  =   16777216
 
innodb_buffer_pool_size = 268435456
 
innodb_log_buffer_size = 8388608
 
innodb_open_files = 400
 
innodb_strict_mode = off
 
join_buffer_size = 2097152
 
lower_case_table_names = 1
 
max_binlog_size = 104857600
 
max_heap_table_size = 67108864
 
max_relay_log_size = 104857600
 
myisam_sort_buffer_size = 536870912
 
query_cache_limit = 131072
 
query_cache_size = 134217728
 
query_cache_type = on
 
read_buffer_size = 2097152
 
read_rnd_buffer_size = 8388608
 
skip_name_resolve = on
 
slow_query_log = on
 
table_definition_cache   =   4096
 
table_open_cache         =   1024
 
table_open_cache_instances = 8   
tcp_keepalive_interval   =   0   
tcp_keepalive_probes    =    0   
tcp_keepalive_time      =    0   
tcp_nodelay           =      ON  
thread_cache_size     =      500 
tmp_memory_table_size    =   67108864                  
tmp_table_size         =     67108864 
character_set_database = 'utf8mb4'
 
character_set_server = 'utf8mb4'
 
collation_database = 'utf8mb4_general_ci'
 
collation_server = 'utf8mb4_general_ci'

Could you please try to run ANALYZE for all tables and run the query again?

Comment by Mike Savoie [ 2022-08-18 ]

ok, we will run ANALYZE for all tables and run the query again.

Comment by Mike Savoie [ 2022-09-06 ]

Attached the file: executed_analyze_table_statements_gosalesxx_1021.txt which did Analyze for all tables.

Comment by Mike Savoie [ 2022-09-06 ]

Attached our DBA's comments after he ran the Analyze for all tables

Hi Mike,

Generated the analyze table statements for all the tables in all the sample schemas and ran them ok.
This didn't change anything - the execution time is still astronomical... for 10.7.3

You can see a snippet of some of the statements that I've ran down below.

Few thoughts on this:
1.. Analyzing tables implies that we're making lots of changes to these tables...
Well... we don't... They're all read-only and they don't change...
2.. The config parameters are the same for all the versions, including: 10.6.7, 10.7.3, 10.7.4, 10.8.3
Despite that fact, for 10.7.3 the query completed in a very long time, while for all the other versions the query is executed in 50 sec or less.

I can clearly see that 10.7.3 behaves differently than the rest of the versions - even though it was configured in the same way as the rest of the versions.

This is an example of running the analyze table statements for some of the tables ( I can include them all if needed as a proof) / schemas:

Comment by Sergei Golubchik [ 2023-12-19 ]

10.7 is no longer maintained. 10.6 is but it doesn't exhibit this slowdown, according to the last comment. 10.8 didn't either, so presumably all later versions (10.9, 10.10, 10.11) don't.

Thus I'm closing this issue as the only affected version is now beyond EOL.

Please, do comment if you'll see this slowdown in any maintained versions (say, in 10.11) and we'll reopen the issue.

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