[MDEV-337] A query with simple join, where clause and order by <datetime column> desc takes very long when executed with ICP Created: 2012-06-13  Updated: 2012-06-28  Resolved: 2012-06-16

Status: Closed
Project: MariaDB Server
Component/s: None
Affects Version/s: 5.5.24
Fix Version/s: 5.5.25

Type: Bug Priority: Major
Reporter: roberto spadim Assignee: Sergei Petrunia
Resolution: Fixed Votes: 0
Labels: None

Attachments: File mdev-337.txt.gz    

 Description   

The following query

SELECT * FROM t1, t2 
WHERE c = i AND a = 1000 AND e = 'cc' AND h = 152 AND g = 'value22.test' AND f > '2012-06-15 20:42:05' 
ORDER BY f DESC;

on the test data (100K rows in t1, 2 rows in t2) takes several seconds on a release build and over a minute on a debug build (and returns an empty set). The same query without DESC, or any of the conditions in WHERE clause finishes in no time.

The test data is attached as mdev-337.txt.gz

Reproducible on 5.5.23, 5.5.24 and current maria/5.5 revno 3426.
In the test data, the first table is Aria. With MyISAM table, you can notice some slowness too, but it's much less perceptible.
Due to this, it's difficult to be certain whether the problem exists on mysql-trunk.
Could not reproduce on maria-5.3.

Minimal optimizer_switch:
index_condition_pushdown=on

Full optimizer_switch (default):

index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=off

EXPLAIN (with the minimal optimizer_switch):

EXPLAIN EXTENDED SELECT * FROM t1, t2 WHERE c = i AND a = 1000 AND e = 'cc' AND h = 152 AND g = 'value22.test' AND f > '2012-06-15 20:42:05' ORDER BY f desc;
+------+-------------+-------+--------+---------------+---------+---------+-----------+------+----------+--------------------------+
| id   | select_type | table | type   | possible_keys | key     | key_len | ref       | rows | filtered | Extra                    |
+------+-------------+-------+--------+---------------+---------+---------+-----------+------+----------+--------------------------+
|    1 | SIMPLE      | t1    | range  | aehgfcd       | aehgfcd | 40      | NULL      |    1 |   100.00 | Using index condition    |
|    1 | SIMPLE      | t2    | eq_ref | PRIMARY       | PRIMARY | 4       | test.t1.c |    1 |   100.00 | Using where; Using index |
+------+-------------+-------+--------+---------------+---------+---------+-----------+------+----------+--------------------------+
| Note  | 1003 | select `test`.`t1`.`a` AS `a`,`test`.`t1`.`b` AS `b`,`test`.`t1`.`c` AS `c`,`test`.`t1`.`d` AS `d`,`test`.`t1`.`e` AS `e`,`test`.`t1`.`f` AS `f`,`test`.`t1`.`g` AS `g`,`test`.`t1`.`h` AS `h`,`test`.`t2`.`i` AS `i` from `test`.`t1` join `test`.`t2` where ((`test`.`t1`.`g` = 'value22.test') and (`test`.`t1`.`h` = 152) and (`test`.`t1`.`e` = 'cc') and (`test`.`t1`.`a` = 1000) and (`test`.`t1`.`c` = `test`.`t2`.`i`) and (`test`.`t1`.`f` > '2012-06-15 20:42:05')) order by `test`.`t1`.`f` desc |

Test case:

- unpack the attached file mdev-337.txt.gz and feed it to the server;
- execute
SELECT * FROM t1, t2 
WHERE c = i AND a = 1000 AND e = 'cc' AND h = 152 AND g = 'value22.test' AND f > '2012-06-15 20:42:05' 
ORDER BY f DESC;



 Comments   
Comment by roberto spadim [ 2012-06-13 ]

maybe mix of myisam and aria engine do this problem?????

Comment by Elena Stepanova [ 2012-06-13 ]

Hi Roberto,

1) How many rows (approximately) do you have in the tables?
2) Please define "never" in "it never return" – how long had you waited?
3) Please provide output of EXPLAIN EXTENDED <your query>; SHOW WARNINGS;

Thank you.

Comment by roberto spadim [ 2012-06-13 ]

never = 5012 seconds and i killed the query since some users was trying to INSERT into table and it was
'waiting resource' before kill, (waiting resource in INSERT queries... the SELECT was sending data, when the query return nice (with concat), it return 0 rows (yes that´s right 0 rows was expected), since there is no data in this WHERE clausule)

after kill -> INSERT gone 'waiting table lock', and done (no more query running)
there was about 50 queries of INSERT waiting this SELECT
some show table status:

"Name" "Engine" "Version" "Row_format" "Rows" "Avg_row_length" "Data_length" "Max_data_length" "Index_length" "Data_free" "Auto_increment" "Create_time" "Update_time" "Check_time" "Collation" "Checksum" "Create_options" "Comment"

"est_mov" "Aria" "10" "Page" "15032596" "479" "7209508864" "68719484928" "6843211776" "0" NULL "2011-01-20 19:07:58" "2012-06-13 14:52:19" "2011-05-15 17:45:01" "latin1_swedish_ci" NULL "page_checksum=1" ""
"estoque_itens" "MyISAM" "10" "Dynamic" "1381" "550" "760688" "281474976710655" "177152" "0" NULL "2012-01-25 14:01:23" "2012-06-13 10:07:59" "2012-05-18 07:07:25" "latin1_swedish_ci" NULL "" ""

select count from est_mov -> 15.032.707
select count from estoque_itens -> 1381

show index from est_mov

"Table" "Non_unique" "Key_name" "Seq_in_index" "Column_name" "Collation" "Cardinality" "Sub_part" "Packed" "Null" "Index_type" "Comment" "Index_comment"
"est_mov" "0" "PRIMARY" "1" "mov_id" "A" "5010907" NULL NULL "" "BTREE" "" ""
"est_mov" "0" "PRIMARY" "2" "unidade_id" "A" "5010907" NULL NULL "" "BTREE" "" ""
"est_mov" "0" "PRIMARY" "3" "oe_tipo" "A" "15032723" NULL NULL "" "BTREE" "" ""
"est_mov" "0" "PRIMARY" "4" "oe" "A" "15032723" NULL NULL "" "BTREE" "" ""
"est_mov" "0" "PRIMARY" "5" "oe_seq" "A" "15032723" NULL NULL "" "BTREE" "" ""
"est_mov" "0" "PRIMARY" "6" "item_id" "A" "15032723" NULL NULL "" "BTREE" "" ""
"est_mov" "0" "PRIMARY" "7" "item_id_red" "A" "15032723" NULL NULL "" "BTREE" "" ""
"est_mov" "0" "PRIMARY" "8" "lote_tipo" "A" "15032723" NULL NULL "" "BTREE" "" ""
"est_mov" "0" "PRIMARY" "9" "lote_spa" "A" "15032723" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "lote" "1" "unidade_id" "A" "3" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "lote" "2" "lote_tipo" "A" "11" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "lote" "3" "lote_spa" "A" "15840" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "lote" "4" "item_id" "A" "15840" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "lote" "5" "item_id_red" "A" "61609" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "lote" "6" "mov_id" "A" "15032723" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "lote" "7" "oe_tipo" "A" "15032723" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "lote" "8" "oe" "A" "15032723" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "lote" "9" "oe_seq" "A" "15032723" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "oe" "1" "unidade_id" "A" "3" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "oe" "2" "oe_tipo" "A" "27" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "oe" "3" "oe" "A" "24285" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "oe" "4" "oe_seq" "A" "3006544" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "oe" "5" "item_id" "A" "3006544" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "oe" "6" "item_id_red" "A" "3758180" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "item" "1" "item_id" "A" "7" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "item" "2" "item_id_red" "A" "1377" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "item" "3" "data_estoque" "A" "7516361" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "ponto_movimentacao" "1" "unidade_id" "A" "3" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "ponto_movimentacao" "2" "oe_tipo" "A" "27" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "ponto_movimentacao" "3" "ponto_movimentacao" "A" "170" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "ponto_movimentacao" "4" "usuario" "A" "456" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "ponto_movimentacao" "5" "data_estoque" "A" "7516361" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "ponto_movimentacao" "6" "item_id" "A" "7516361" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "ponto_movimentacao" "7" "item_id_red" "A" "7516361" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "rastro_mov_id" "1" "mov_id" "A" "5010907" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "rastro_mov_id" "2" "data_estoque" "A" "15032723" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "rendimento_transfs" "1" "unidade_id" "A" "3" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "rendimento_transfs" "2" "item_id" "A" "7" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "rendimento_transfs" "3" "oe_tipo" "A" "31" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "rendimento_transfs" "4" "data_estoque" "A" "7516361" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "rendimento_transfs" "5" "oe" "A" "7516361" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "rendimento_transfs" "6" "ponto_movimentacao" "A" "7516361" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "transferencias" "1" "item_id" "A" "7" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "transferencias" "2" "data_estoque" "A" "5010907" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "transferencias" "3" "oe_tipo" "A" "7516361" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "transferencias" "4" "item_id_red" "A" "7516361" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "tabela_temp_rendimento" "1" "rendimento" "A" "7" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "tabela_temp_rendimento" "2" "lote_rendimento_data" "A" "2028" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "tabela_temp_rendimento" "3" "item_id_red" "A" "66812" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "tabela_temp_rendimento" "4" "item_id" "A" "66812" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "data_est" "1" "data_estoque" "A" "5010907" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "data_est" "2" "item_id_red" "A" "7516361" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "data_est" "3" "item_id" "A" "7516361" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "cfop" "1" "cfop_id" "A" "3" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "cfop" "2" "cfop_id_red" "A" "111" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "cfop" "3" "item_id" "A" "115" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "cfop" "4" "item_id_red" "A" "8073" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "lote_sif" "1" "lote_sif_data" "A" "1564" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "lote_sif" "2" "lote_sif" "A" "9222" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "lote_sif" "3" "item_id" "A" "9222" NULL NULL "" "BTREE" "" ""
"est_mov" "1" "lote_sif" "4" "item_id_red" "A" "81699" NULL NULL "" "BTREE" "" ""

show index from estoque_itens

"Table" "Non_unique" "Key_name" "Seq_in_index" "Column_name" "Collation" "Cardinality" "Sub_part" "Packed" "Null" "Index_type" "Comment" "Index_comment"
"estoque_itens" "0" "PRIMARY" "1" "plano_conta_id" "A" "5" NULL NULL "" "BTREE" "" ""
"estoque_itens" "0" "PRIMARY" "2" "plano_conta_id_red" "A" "1381" NULL NULL "" "BTREE" "" ""
"estoque_itens" "0" "plano_conta_numero" "1" "plano_conta_id" "A" "5" NULL NULL "" "BTREE" "" ""
"estoque_itens" "0" "plano_conta_numero" "2" "plano_conta_numero" "A" "1381" NULL NULL "" "BTREE" "" ""
"estoque_itens" "0" "codigo_busca" "1" "plano_conta_id" "A" "5" NULL NULL "" "BTREE" "" ""
"estoque_itens" "0" "codigo_busca" "2" "codigo_busca" "A" "1381" NULL NULL "" "BTREE" "" ""
"estoque_itens" "0" "cb" "1" "codigo_busca" "A" "1381" NULL NULL "" "BTREE" "" ""
"estoque_itens" "0" "cb" "2" "plano_conta_id" "A" "1381" NULL NULL "" "BTREE" "" ""
"estoque_itens" "0" "cb" "3" "plano_conta_id_red" "A" "1381" NULL NULL "" "BTREE" "" ""
"estoque_itens" "0" "cb" "4" "plano_conta_numero" "A" "1381" NULL NULL "" "BTREE" "" ""
"estoque_itens" "1" "ean13" "1" "barcode_number" "A" "125" NULL NULL "" "BTREE" "" ""

Comment by Elena Stepanova [ 2012-06-14 ]

Hi Roberto,

You keep changing your ORDER BY clause, so it's hard to follow. Several times you said that you had a problem with
"ORDER BY unidade_id,oe_tipo,ponto_movimentacao,usuario,data_estoque desc"
and yet your EXPLAIN contains "ORDER BY data_estoque desc". Please provide output of EXPLAIN EXTENDED for the exact query you are having the problem with.

Comment by Elena Stepanova [ 2012-06-14 ]

Thanks Roberto, it's all right, please leave the older posts as is.

Please also provide your defaults file (my.cnf or whatever it's called on your server).

Comment by Elena Stepanova [ 2012-06-14 ]

On synthetic data I'm getting the same exact execution plan as you provided, but the query finishes momentarily.
If you can provide full dumps of your tables, it could help to reproduce the problem (you can upload the dumps to our FTP into the private section, so only MariaDB developers could use it).
If you cannot do it because the data is too sensitive, please at least quote/attach your defaults file and let me know which exact MariaDB distribution you are using. It might also help if you provide partial counts, so I could generate synthetic data better. By partial counts I mean

SELECT COUNT FROM est_mov AS a,estoque_itens AS b
WHERE a.item_id=b.plano_conta_id ;

SELECT COUNT FROM est_mov AS a,estoque_itens AS b
WHERE a.item_id=b.plano_conta_id AND a.item_id_red=b.plano_conta_id_red ;

SELECT COUNT FROM est_mov AS a
WHERE a.unidade_id=1000 ;

SELECT COUNT FROM est_mov AS a
WHERE a.oe_tipo='tr' ;

SELECT COUNT FROM est_mov AS a
WHERE a.ponto_movimentacao=152 ;

SELECT COUNT FROM est_mov AS a
WHERE a.usuario="ind4.bx" ;

SELECT COUNT FROM est_mov AS a
WHERE a.data_estoque>="2012-06-15 20:42:05" ;

SELECT COUNT FROM est_mov AS a
WHERE a.item_id=b.plano_conta_id AND a.item_id_red=b.plano_conta_id_red AND a.unidade_id=1000 AND a.oe_tipo='tr' AND a.ponto_movimentacao=152 AND a.usuario="ind4.bx" AND a.data_estoque>="2012-06-15 20:42:05" ;

Upd: okay, I see you have already added defaults file, thanks.

Comment by Elena Stepanova [ 2012-06-14 ]

Just update the field and proceed with whatever data described above you can provide. I've switched to 5.5.23 and the query is still fast for me, so it's not about 5.5.23 / 5.5.24 (please still point at the exact distribution though).

Comment by Elena Stepanova [ 2012-06-14 ]

Thanks, I'll try to generate better data now. No need to upload your 14GB just yet, but if possible please take and store the dumps now (first, it will be easier while your system is idle, and second, the data might change later and the problem will be gone).

Comment by Elena Stepanova [ 2012-06-14 ]

>> and about two queries... no return yet, should i continue?

Not necessarily, if they bother you anyhow, you can kill them.

Comment by Elena Stepanova [ 2012-06-14 ]

Hi Roberto,

Thank you. I was able to reproduce the problem with your data.
As a workaround, you can set index_condition_pushdown=off in optiimizer switch, it should help:
execute

set global optimizer_switch = 'index_condition_pushdown=off';

on the running server, and add

optimizer_switch=index_condition_pushdown=off

to your cnf file for future sessions.

Comment by Elena Stepanova [ 2012-06-14 ]

Test data (~6.5 Mb when unpacked). Feed to mysql client before executing the query in question.

Comment by Elena Stepanova [ 2012-06-15 ]

Roberto,

Setting the switch to OFF is just a workaround, in general it is expected to be ON.

Sergei will investigate the problem from the optimizer point of view and will decide whether it's a localized bug which can be fixed in 5.5, in which case the fix will be pushed into one of the next releases (most likely not the nearest one, but possibly the next). If it turns out that the slowdown is a part of a deeper deficiency, it might have to wait longer.

Comment by roberto spadim [ 2012-06-15 ]

hummm nice elena
i will check what´s best in my case if the concat (|| "") or the icp switch

Comment by Sergei Petrunia [ 2012-06-16 ]

This is the same problem as https://bugs.launchpad.net/maria/+bug/1000051 . It is fixed, and the fix is in 5.3 and 5.5 trees (=> will be in the next release).

Meanwhile, one can use optimizer_switch='index_condition_pushdown=off' as a workaround.

Comment by Sergei Petrunia [ 2012-06-16 ]

Verified that the bug can be repeated right-before the mentioned bug was fixed, and is not repeatable right after.

Comment by roberto spadim [ 2012-06-28 ]

guys i tested now in production, icp off, and no more problems... thanks

Generated at Thu Feb 08 06:28:00 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.