[MDEV-4479] SELECT from InnoDB table hangs in dyn_array_get_element being executed in parallel with replicating LOAD DATA Created: 2013-05-04  Updated: 2014-11-10  Resolved: 2014-11-10

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.0.2, 5.5.30
Fix Version/s: 10.0.8

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Unassigned
Resolution: Fixed Votes: 0
Labels: upstream-fixed

Issue Links:
Relates
relates to MDEV-7056 Upstream bug reports and test cases Closed

 Description   

Also reproducible on MySQL 5.6, 5.7 (didn't try 5.5) and filed as http://bugs.mysql.com/bug.php?id=69141

Reproducible on debug builds, not sure if it's because the issue is debug-specific, or just because release builds are too fast for that.

The provided test case hangs on the next SELECT COUNT after executing several of them reasonably fast (and returning 0).
It stays in this state even when replicating of LOAD DATA ends:

MariaDB [test]> show processlist;
 
+----+-------------+-----------------+------+---------+------+-----------------------------------------------------------------------------+-------------------------+----------+
 
| Id | User        | Host            | db   | Command | Time | State                                                                       | Info                    | Progress |
 
+----+-------------+-----------------+------+---------+------+-----------------------------------------------------------------------------+-------------------------+----------+
 
|  2 | root        | localhost:55696 | test | Sleep   |  252 |                                                                             | NULL                    |    0.000 |
 
|  3 | root        | localhost:55697 | test | Sleep   |  252 |                                                                             | NULL                    |    0.000 |
 
|  6 | root        | localhost:55703 | test | Query   |  145 | Sending data                                                                | SELECT COUNT(*) FROM t1 |    0.000 |
 
|  7 | root        | localhost:55704 | test | Sleep   |  252 |                                                                             | NULL                    |    0.000 |
 
|  8 | system user |                 | NULL | Connect |  252 | Waiting for master to send event                                            | NULL                    |    0.000 |
 
|  9 | system user |                 | NULL | Connect |  252 | Slave has read all relay log; waiting for the slave I/O thread to update it | NULL                    |    0.000 |
 
| 10 | root        | localhost:55708 | test | Query   |    0 | NULL                                                                        | show processlist        |    0.000 |
 
+----+-------------+-----------------+------+---------+------+-----------------------------------------------------------------------------+-------------------------+----------+

Stack trace from the server with the hanging query:

#0  dyn_block_get_used (block=0x7fdc2402bf18) at 10.0-base/storage/xtradb/include/dyn0dyn.ic:100
 
#1  0x0000000000ae69fe in dyn_array_get_element (arr=0x7fdc7fb3ae88, pos=27088) at 10.0-base/storage/xtradb/include/dyn0dyn.ic:300
 
#2  0x0000000000ab63c6 in mtr_memo_contains (mtr=0x7fdc7fb3ae80, object=0x7fdc6cfd0700, type=2) at 10.0-base/storage/xtradb/include/mtr0mtr.ic:163
 
#3  0x0000000000ab72bc in mtr_memo_contains_page (mtr=0x7fdc7fb3ae80, ptr=0x7fdc6f9cc37b "", type=2) at 10.0-base/storage/xtradb/mtr/mtr0mtr.c:369
 
#4  0x00000000009e3d46 in row_vers_build_for_consistent_read (rec=0x7fdc6f9cc37b "", mtr=0x7fdc7fb3ae80, index=0x7fdc2c01f928, offsets=0x7fdc7fb3adc0, view=0x7fdc24013c68, offset_heap=0x7fdc7fb3adb8, in_heap=0x7fdc240245f0, old_vers=0x7fdc7fb3adc8) at 10.0-base/storage/xtradb/row/row0vers.c:502
 
#5  0x00000000009d9bfd in row_sel_build_prev_vers_for_mysql (read_view=0x7fdc24013c68, clust_index=0x7fdc2c01f928, prebuilt=0x7fdc24020718, rec=0x7fdc6f9cc37b "", offsets=0x7fdc7fb3adc0, offset_heap=0x7fdc7fb3adb8, old_vers=0x7fdc7fb3adc8, mtr=0x7fdc7fb3ae80) at 10.0-base/storage/xtradb/row/row0sel.c:2909
 
#6  0x00000000009dcec2 in row_search_for_mysql (buf=0x7fdc24019f48 "\377", ' ' <repeats 128 times>"\245, \245\245\245\245\245\245\377\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245"..., mode=1, prebuilt=0x7fdc24020718, match_mode=0, direction=0) at 10.0-base/storage/xtradb/row/row0sel.c:4536
 
#7  0x00000000009a226e in ha_innobase::index_read (this=0x7fdc2401e6e8, buf=0x7fdc24019f48 "\377", ' ' <repeats 128 times>"\245, \245\245\245\245\245\245\377\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245"..., key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at 10.0-base/storage/xtradb/handler/ha_innodb.cc:7103
 
#8  0x00000000009a2eae in ha_innobase::index_first (this=0x7fdc2401e6e8, buf=0x7fdc24019f48 "\377", ' ' <repeats 128 times>"\245, \245\245\245\245\245\245\377\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245"...) at 10.0-base/storage/xtradb/handler/ha_innodb.cc:7454
 
#9  0x00000000009a3096 in ha_innobase::rnd_next (this=0x7fdc2401e6e8, buf=0x7fdc24019f48 "\377", ' ' <repeats 128 times>"\245, \245\245\245\245\245\245\377\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245"...) at 10.0-base/storage/xtradb/handler/ha_innodb.cc:7551
 
#10 0x00000000005b0aca in handler::ha_rnd_next (this=0x7fdc2401e6e8, buf=0x7fdc24019f48 "\377", ' ' <repeats 128 times>"\245, \245\245\245\245\245\245\377\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245"...) at 10.0-base/sql/sql_class.h:4468
 
#11 0x00000000009144e4 in rr_sequential (info=0x7fdc24009040) at 10.0-base/sql/records.cc:458
 
#12 0x0000000000674762 in join_init_read_record (tab=0x7fdc24008f90) at 10.0-base/sql/sql_select.cc:17673
 
#13 0x00000000006727d1 in sub_select (join=0x7fdc24008050, join_tab=0x7fdc24008f90, end_of_records=false) at 10.0-base/sql/sql_select.cc:16785
 
#14 0x00000000006720ec in do_select (join=0x7fdc24008050, fields=0x7fdc24008410, table=0x0, procedure=0x0) at 10.0-base/sql/sql_select.cc:16458
 
#15 0x000000000065125b in JOIN::exec_inner (this=0x7fdc24008050) at 10.0-base/sql/sql_select.cc:3005
 
#16 0x000000000064e5d9 in JOIN::exec (this=0x7fdc24008050) at 10.0-base/sql/sql_select.cc:2296
 
#17 0x0000000000651afd in mysql_select (thd=0x3db0e10, rref_pointer_array=0x3db3e08, tables=0x7fdc240079b8, wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7fdc24008030, unit=0x3db34d0, select_lex=0x3db3ba8) at 10.0-base/sql/sql_select.cc:3233
 
#18 0x0000000000648403 in handle_select (thd=0x3db0e10, lex=0x3db3418, result=0x7fdc24008030, setup_tables_done_option=0) at 10.0-base/sql/sql_select.cc:376
 
#19 0x000000000061e401 in execute_sqlcom_select (thd=0x3db0e10, all_tables=0x7fdc240079b8) at 10.0-base/sql/sql_parse.cc:4804
 
#20 0x0000000000616aab in mysql_execute_command (thd=0x3db0e10) at 10.0-base/sql/sql_parse.cc:2268
 
#21 0x0000000000620c6b in mysql_parse (thd=0x3db0e10, rawbuf=0x7fdc24007708 "select count(*) from t2", length=23, parser_state=0x7fdc7fb3c570) at 10.0-base/sql/sql_parse.cc:5927
 
#22 0x0000000000613de6 in dispatch_command (command=COM_QUERY, thd=0x3db0e10, packet=0x3db4be1 "", packet_length=23) at 10.0-base/sql/sql_parse.cc:1091
 
#23 0x0000000000613315 in do_command (thd=0x3db0e10) at 10.0-base/sql/sql_parse.cc:810
 
#24 0x000000000072860e in do_handle_one_connection (thd_arg=0x3db0e10) at 10.0-base/sql/sql_connect.cc:1266
 
#25 0x000000000072837c in handle_one_connection (arg=0x3db0e10) at 10.0-base/sql/sql_connect.cc:1181
 
#26 0x00007fdc7f1dae9a in start_thread (arg=0x7fdc7fb3d700) at pthread_create.c:308
 
#27 0x00007fdc7e4cecbd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112

Stack trace is from 

revision-id: knielsen@knielsen-hq.org-20130503092729-gedp152b19k5wdnj
 
revno: 3626
 
branch-nick: 10.0-base

Test case:

--source include/master-slave.inc
 
--source include/have_innodb.inc
 
 
 
--connection master
 
 
 
--perl
 
open (LOAD, ">$ENV{MYSQLTEST_VARDIR}/1.load") || die "Could not create load file\n";
 
foreach (1..1000000) {
 
	print LOAD "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa\n";
 
}
 
close (LOAD);
 
EOF
 
 
 
CREATE TABLE t1 (c CHAR(128)) ENGINE=InnoDB;
 
eval LOAD DATA LOCAL INFILE '$MYSQLTEST_VARDIR/1.load' INTO TABLE t1;
 
 
 
--connection slave
 
 
 
--let $run = 100
 
while ($run)
 
{
 
	SELECT COUNT(*) FROM t1;
 
	sleep 1;
 
	dec $run;
 
}

Reproducible with InnoDB and XtraDB.



 Comments   
Comment by Elena Stepanova [ 2014-11-10 ]

Not reproducible on the current 10.0, apparently the fix was merged along with InnoDB/XtraDB 5.6.15. Upstream bugfix for 5.6.15:

revno: 5457
 
committer: Annamalai Gurusami <annamalai.gurusami@oracle.com>
 
branch nick: mysql-5.6
 
timestamp: Tue 2013-09-17 17:23:58 +0530
 
message:
 
  Bug #16764240 SELECT FROM INNODB TABLE HANGS BEING RUN IN PARALLEL
 
  WITH REPLICATING LOAD DATA
 
  
  Problem:
 
  
  The mtr_memo_contains() function determines if the given object is part
 
  of the memo of the mini transaction.  In the test scenario, this search
 
  is very slow (takes more than 1 hour).   This is because the search in
 
  mtr_memo_contains() involves a nested loop.
 
  
  Solution:
 
  
  Re-write mtr_memo_contains() so that the search involves only one loop.
 
  This is already done by Yasufumi as part of wl#6363.  Backporting the
 
  functions mtr_memo_contains() and mtr_memo_note_modifications() from
 
  mysql-5.7 to mysql-5.6 is sufficient. 
  
  rb#3342 approved by Yasufumi

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