| Bug #13379 | Loss of DB connection with certain subselects | ||
|---|---|---|---|
| Submitted: | 21 Sep 2005 13:42 | Modified: | 13 Sep 2006 12:20 |
| Reporter: | Dave Neary | Email Updates: | |
| Status: | Duplicate | Impact on me: | |
| Category: | MySQL Server: Optimizer | Severity: | S3 (Non-critical) |
| Version: | 4.1.11/BK source | OS: | Linux (Linux 2.4.21) |
| Assigned to: | Assigned Account | CPU Architecture: | Any |
[21 Sep 2005 14:04]
MySQL Verification Team
Thank you for the bug report.
This bug not affects 5.0.XX.
miguel@hegel:~/dbs/4.1> bin/mysql -uroot
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 1 to server version: 4.1.15-debug-log
Type 'help;' or '\h' for help. Type '\c' to clear the buffer.
mysql> create database hk;
Query OK, 1 row affected (0.04 sec)
mysql> use hk;
Database changed
mysql> CREATE TABLE tab1 (
-> id INT,
-> uid INT,
-> state INT,
-> PRIMARY KEY (id, uid)) ENGINE=InnoDB;
Query OK, 0 rows affected (0.06 sec)
mysql>
mysql> CREATE TABLE tab2 (
-> id INT,
-> uid INT,
-> date DATETIME,
-> PRIMARY KEY (id, uid, date)) ENGINE=InnoDB;
Query OK, 0 rows affected (0.06 sec)
mysql> INSERT INTO tab1 VALUES (1,2,1), (1,1,2), (2,3,1);
Query OK, 3 rows affected (0.01 sec)
Records: 3 Duplicates: 0 Warnings: 0
mysql> INSERT INTO tab2 VALUES (1, 2, '2005-01-01'), (1, 1, '2005-01-01'), (2, 3,
-> '2005-01-01');
Query OK, 3 rows affected (0.01 sec)
Records: 3 Duplicates: 0 Warnings: 0
mysql> SELECT * FROM tab1 WHERE (id,uid) IN
-> (SELECT tab2.id,tab2.uid FROM tab2,tab1
-> WHERE tab1.id=tab2.id
-> AND tab2.id=1
-> AND tab1.uid = tab2.uid
-> AND tab2.uid=2
-> AND tab1.state=1
-> AND tab2.date BETWEEN '2005-01-01 00:00:00'
-> AND '2005-01-01 00:00:00');
ERROR 2013 (HY000): Lost connection to MySQL server during query
mysql> exit
miguel@hegel:~/dbs/4.1> libexec/mysqld
050921 10:50:18 InnoDB: Started; log sequence number 0 135091
libexec/mysqld: ready for connections.
Version: '4.1.15-debug-log' socket: '/tmp/mysql.sock' port: 3306 Source distribution
len 108; hex 6884214188c04a41000000000000000003000000010000000300000000000000010000000300000000000000000000000000000000000000010000008344510$
InnoDB: Failing assertion: 0
InnoDB: We intentionally generate a memory trap.
[21 Sep 2005 20:52]
Heikki Tuuri
Hi!
The assertion failure happens because of this: for the PRIMARY index of tab2, MySQL calls
ha_innobase::index_init(unsigned) (this=0x8b2dbe8...
and then
ha_innobase::index_next_same(char*, char const*, unsigned) (
this=0x8b2dbe8...
but since the table handle cursor was not positioned after the ::index_init, InnoDB cannot process ::index_next_same in a sensible way!
Breakpoint 7, ha_innobase::change_active_index(unsigned) (this=0x8b2dbe8,
keynr=0) at ha_innodb.cc:3134
3134 row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_pre
built;
Current language: auto; currently c++
(gdb) bt
#0 ha_innobase::change_active_index(unsigned) (this=0x8b2dbe8, keynr=0)
at ha_innodb.cc:3134
#1 0x081dcc9f in ha_innobase::index_init(unsigned) (this=0x8b2dbe8,
keynr=145939432) at ha_innodb.cc:2889
#2 0x081ccf0d in init_read_record(st_read_record*, THD*, st_table*, SQL_SELECT*
, int, bool) (info=0x8b481a0, thd=0x8b294c0, table=0x8b48570,
select=0x8b48570, use_record_cache=1, print_error=true) at handler.h:322
#3 0x0818eb1b in join_init_read_record (tab=0x8b4817c) at sql_select.cc:6450
#4 0x0818dcb6 in sub_select (join=0x8b46070, join_tab=0x8b4817c,
end_of_records=232) at sql_select.cc:6011
#5 0x0818d979 in do_select (join=0x8b46070, fields=0x8b4817c, table=0x0,
procedure=0x8b2dbe8) at sql_select.cc:5919
#6 0x08182b73 in JOIN::exec() (this=0x8b46070) at sql_select.cc:1498
#7 0x0811c388 in subselect_single_select_engine::exec() (this=0x8b28238)
at item_subselect.cc:1441
#8 0x081181ce in Item_subselect::exec() (this=0x8b281a8)
at item_subselect.cc:204
#9 0x081194a9 in Item_in_subselect::val_int() (this=0x8b281a8)
at item_subselect.cc:628
#10 0x080d8c01 in Item::val_int_result() (this=0x8b2dbe8) at item.h:220
#11 0x080f2301 in Item_in_optimizer::val_int() (this=0x8b46b00)
at item_cmpfunc.cc:650
#12 0x0818dd4e in sub_select (join=0x8b28398, join_tab=0x8b47340,
end_of_records=232) at sql_select.cc:6033
#13 0x0818d979 in do_select (join=0x8b28398, fields=0x8b47340, table=0x0,
procedure=0x8b2dbe8) at sql_select.cc:5919
#14 0x08182b73 in JOIN::exec() (this=0x8b28398) at sql_select.cc:1498
#15 0x08182fde in mysql_select(THD*, Item***, st_table_list*, unsigned, List<Ite
m>&, Item*, unsigned, st_order*, st_order*, Item*, st_order*, unsigned long, sel
ect_result*, st_select_lex_unit*, st_select_lex*) (thd=0x8b294c0,
rref_pointer_array=0x8b296d0, tables=0x8b26fe8, wild_num=1,
fields=@0x8b2dbe8, conds=0x8b281a8, og_num=0, order=0x0, group=0x0,
having=0x0, proc_param=0x0, select_options=2156153344, result=0x8b28388,
unit=0x8b29508, select_lex=0x8b295e8) at sql_select.cc:1619
#16 0x0817f127 in handle_select(THD*, st_lex*, select_result*) (thd=0x8b294c0,
lex=0x8b294fc, result=0x8b28388) at sql_select.cc:179
#17 0x08155035 in mysql_execute_command(THD*) (thd=0x8b294c0)
at sql_parse.cc:2090
#18 0x0815a8ea in mysql_parse(THD*, char*, unsigned) (thd=0x8b294c0,
---Type <return> to continue, or q <return> to quit---q
inBuf=0x8b2Quit
) at sql_parse.cc:4295
#19 0x0815385b in dispatch_command(enum_server_command, THD*, char*, unsigned)
(command=COM_QUERY, thd=0x8b294c0, packet=0x8b22d89 "", packet_length=361)
at sql_parse.cc:1500
#20 0x08153164 in do_command(THD*) (thd=0x8b294c0) at sql_parse.cc:1313
#21 0x081525bf in handle_one_connection (arg=0x8b2dbe8) at sql_parse.cc:1045
#22 0x40062f60 in pthread_start_thread () from /lib/i686/libpthread.so.0
#23 0x400630fe in pthread_start_thread_event () from /lib/i686/libpthread.so.0
#24 0x401f5327 in clone () from /lib/i686/libc.so.6
(gdb) c
Continuing.
[21 Sep 2005 20:54]
Heikki Tuuri
Breakpoint 5, handler::read_range_next() (this=0x8b2dbe8) at handler.cc:1646
1646 DBUG_ENTER("handler::read_range_next");
(gdb) bt
#0 handler::read_range_next() (this=0x8b2dbe8) at handler.cc:1646
#1 0x081ca6b0 in QUICK_SELECT::get_next() (this=0x8b2f678)
at opt_range.cc:2682
#2 0x081cd1ee in rr_quick (info=0x8b481a0) at records.cc:178
#3 0x0818eb21 in join_init_read_record (tab=0x8b4817c) at sql_select.cc:6452
#4 0x0818dcb6 in sub_select (join=0x8b46070, join_tab=0x8b4817c,
end_of_records=136) at sql_select.cc:6011
#5 0x0818d979 in do_select (join=0x8b46070, fields=0x8b4817c, table=0x0,
procedure=0x8b2dbe8) at sql_select.cc:5919
#6 0x08182b73 in JOIN::exec() (this=0x8b46070) at sql_select.cc:1498
#7 0x0811c388 in subselect_single_select_engine::exec() (this=0x8b28238)
at item_subselect.cc:1441
#8 0x081181ce in Item_subselect::exec() (this=0x8b281a8)
at item_subselect.cc:204
#9 0x081194a9 in Item_in_subselect::val_int() (this=0x8b281a8)
at item_subselect.cc:628
#10 0x080d8c01 in Item::val_int_result() (this=0x8b2dbe8) at item.h:220
#11 0x080f2301 in Item_in_optimizer::val_int() (this=0x8b46b00)
at item_cmpfunc.cc:650
#12 0x0818dd4e in sub_select (join=0x8b28398, join_tab=0x8b47340,
end_of_records=136) at sql_select.cc:6033
#13 0x0818d979 in do_select (join=0x8b28398, fields=0x8b47340, table=0x0,
procedure=0x8b2dbe8) at sql_select.cc:5919
#14 0x08182b73 in JOIN::exec() (this=0x8b28398) at sql_select.cc:1498
#15 0x08182fde in mysql_select(THD*, Item***, st_table_list*, unsigned, List<Ite
m>&, Item*, unsigned, st_order*, st_order*, Item*, st_order*, unsigned long, sel
ect_result*, st_select_lex_unit*, st_select_lex*) (thd=0x8b294c0,
rref_pointer_array=0x8b296d0, tables=0x8b26fe8, wild_num=1,
fields=@0x8b2dbe8, conds=0x8b281a8, og_num=0, order=0x0, group=0x0,
having=0x0, proc_param=0x0, select_options=2156153344, result=0x8b28388,
unit=0x8b29508, select_lex=0x8b295e8) at sql_select.cc:1619
#16 0x0817f127 in handle_select(THD*, st_lex*, select_result*) (thd=0x8b294c0,
lex=0x8b294fc, result=0x8b28388) at sql_select.cc:179
#17 0x08155035 in mysql_execute_command(THD*) (thd=0x8b294c0)
at sql_parse.cc:2090
#18 0x0815a8ea in mysql_parse(THD*, char*, unsigned) (thd=0x8b294c0,
inBuf=0x8b26dc0 "SELECT * FROM tab1 WHERE (id,uid) IN\n (SELECT tab2.i
d,tab2.uid FROM tab2,tab1\n", ' ' <repeats 12 times>, "WHERE tab1.id=tab2.id\n",
' ' <repeats 14 times>, "AND tab2.id=1\n", ' ' <repeats 14 times>, "AND tab1.ui
---Type <return> to continue, or q <return> to quit---q
Quit
) at sql_parse.cc:4295
#19 0x0815385b in dispatch_command(enum_server_command, THD*, char*, unsigned)
(command=COM_QUERY, thd=0x8b294c0, packet=0x8b22d89 "", packet_length=361)
at sql_parse.cc:1500
#20 0x08153164 in do_command(THD*) (thd=0x8b294c0) at sql_parse.cc:1313
#21 0x081525bf in handle_one_connection (arg=0x8b2dbe8) at sql_parse.cc:1045
#22 0x40062f60 in pthread_start_thread () from /lib/i686/libpthread.so.0
#23 0x400630fe in pthread_start_thread_event () from /lib/i686/libpthread.so.0
#24 0x401f5327 in clone () from /lib/i686/libc.so.6
(gdb) c
Continuing.
Breakpoint 4, ha_innobase::index_next_same(char*, char const*, unsigned) (
this=0x8b2dbe8, buf=0x8b2dcf0 "ÿ\001", key=0x8b4e7a8 "\001", keylen=16)
at ha_innodb.cc:3285
3285 statistic_increment(ha_read_next_count, &LOCK_status);
(gdb) c
Continuing.
Breakpoint 1, row_search_for_mysql (buf=0x8b2dcf0 "ÿ\001", mode=0,
prebuilt=0x40acb668, match_mode=1, direction=1) at row0sel.c:2858
2858 dict_index_t* index = prebuilt->index;
Current language: auto; currently c
(gdb)
Continuing.
len 108; hex 68c4ac408880d84000000000000000000300000001000000030000000000000001
00000003000000000000000000000000000000000000000100000083445107000000000000000000
000000000000000000000060e111770200000000000000000000000000000000000000; asc h @
@ DQ
` w ;050922 0:01:08InnoDB: Assertion failure in thread 1474
66 in file btr0pcur.c line 213
InnoDB: Failing assertion: 0
[31 Oct 2005 13:22]
Roberto Bertó
I fix this problem here. I guess InnoDB indexes get corrupt after update mySQL from 4.x to 5, so, dumping all mysql databases and recreating it all solves the problem. I'm sure there are another solution, but this one fixes (do not run it without understanding all above): # mkdir /root/mysqlbkp # cd /root/mysqlbkp # mysqldump -u root -p --opt --all-databases > bkp.sql # service mysql stop # mv /var/lib/mysql bkp # rpm -e MySQL-server # rpm -Uvh /root/MySQL-server*.rpm # service mysql start # mysql -u root < bkp.sql # service mysql stop # service mysql start # cd /var/lib/mysql # rmdir test
[3 May 2006 11:49]
Heikki Tuuri
Alex, is there progress in this? Regards, Heikki
[24 May 2006 0:09]
Srinivas Bolisetty
Hi
I have seen the similar/same issue on 5.0.20-standard.
060523 15:30:20 InnoDB: error clustered record for sec rec not found
InnoDB: index `CI_emlhdr_profile_dt` of table `habeas/eml_header`
InnoDB: sec index record PHYSICAL RECORD: n_fields 3; 1-byte offsets; info bits 0
0: len 8; hex 800000000000139b; asc ;; 1: len 8; hex 8000123c5a3a562e; asc <Z:V.;; 2: len 8; hex 8000000000051ad7; asc ;;
InnoDB: clust index record PHYSICAL RECORD: n_fields 20; 2-byte offsets; info bits 0
0: len 8; hex 80000000004a426a; asc JBj;; 1: len 6; hex 000001b075cb; asc u ;; 2: len 7; hex 8000026c1f0110; asc l ;; 3: len 8; hex 80000000000013ab; asc ;; 4: len 8; hex 800000000000000d; asc ;; 5: len 8; hex 8000000000000156; asc V;; 6: len 8; hex 8000000000029836; asc 6;; 7: len 8; hex 800000000008f49d; asc ;; 8: len 8; hex 800000000001fda6; asc ;; 9: len 8; hex 8000000000013f5b; asc ?[;; 10: len 8; hex 8000000000002556; asc %V;; 11: len 8; hex 8000123eb45aca5c; asc > Z \;; 12: len 26; hex 3233204d617920323030362031313a35303a3434202d30373030; asc 23 May 2006 11:50:44 -0700;; 13: len 8; hex 8000123eb45ab224; asc > Z $;; 14: len 14; hex 36332e3230372e3231382e313333; asc 63.207.218.133;; 15: len 30; hex 3c424159302d4d43352d4631345570616744674d30303538386664614062; asc <BAY0-MC5-F14UpagDgM00588fda@b;...(truncated); 16: len 30; hex 6864745f71613240686f746d61696c2e636f6d2f494e424f582f68647431; asc hdt_qa2@hotmail.com/INBOX/hdt1;...(truncated); 17: len 1; hex 80; asc ;; 18: len 8; hex 8000123eb45ab21e; asc > Z ;; 19: len 8; hex 8000123eb45ab224; asc > Z $;;
TRANSACTION 0 28354003, ACTIVE 1 sec, process no 20873, OS thread id 10738608 fetching rows, thread declared inside InnoDB 19
mysql tables in use 2, locked 2
2317 lock struct(s), heap size 142656
MySQL thread id 5085, query id 926878 dev-db1.habeas.com 10.20.30.7 opstats Sending data
insert into sdr_tbl_hdr (id, breakid, campid, retrievedate, type, vcr_box)
select tbl_hdr.id, tbl_hdr.tbl_jet_id, NULL, tbl_hdr.retrievedate,
vcr_dir.type, tbl_hdr.vcr_box
from tbl_hdr, vcr_dir, rpt_dtrange
where
rpt_dtrange.id = tbl_hdr.vcr_box
and
tbl_hdr.vcr_dir_id = vcr_dir.id
and tbl_hdr.contained=0
and rpt_dtrange.id = tbl_hdr.vcr_box
and tbl_hdr.retrievedate between rpt_dtrange.startdate and rpt_dtrange.enddate
and tbl_hdr.tbl_jet_id is not nu
InnoDB: Submit a detailed bug report to http://bugs.mysql.com
060523 15:30:20InnoDB: Assertion failure in thread 10738608 in file btr0pcur.c line 83
InnoDB: Failing assertion: cursor->pos_state == BTR_PCUR_IS_POSITIONED
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/mysql/en/Forcing_recovery.html
InnoDB: about forcing recovery.
mysqld got signal 11;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.
....
thd=0x9dfab70
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
Cannot determine thread, fp=0xa3b5ac, backtrace may not be correct.
Stack range sanity check OK, backtrace follows:
0x815ab80
0x4fe8b8
0x82a5114
0x82a5114
0x820af75
0x81acb9b
0x81a9879
0x81a9bd3
0x81b7df4
0x81b8d3c
0x81b93b5
0x8174fc4
0x817669d
0x8176e31
0x8177c04
0x8178290
0x4f83ae
0x441aee
New value of fp=(nil) failed sanity check, terminating stack trace!
Please read http://dev.mysql.com/doc/mysql/en/Using_stack_trace.html and follow instructions on how to resolve the stack trace. Resolved
stack trace is much more helpful in diagnosing the problem, so please do
resolve it
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x3d014528 is invalid pointer
thd->thread_id=5085
After restarting the Server and MySQL the database seems to have recovered and no other errors are shown so far....
-Srinivas
[9 Jun 2006 9:16]
Heikki Tuuri
Srinivas, does CHECK TABLE say that the tables are ok? Regards, Heikki
[9 Jun 2006 15:02]
Srinivas Bolisetty
Hi Heikki I tried check table - which recovered many of the tables, except for one. It keeps on crashing the MySQL with the same error over and over again. Tried with innodb recovery option 4 and 1. No use. It kept on failing over the corruption on primary index. Tried dropping the index, no use. Tried taking a mysqldump - select * into outfile - without using the index, still no use. Rebooting the system still showed up the same error. No matter what I tried it was of no use. Finally, the following procedure worked: copy /var/lib/mysql over to an external hard-disk. rm -fr /var/lib/mysql copy /var/lib/mysql from external hard-disk back onto the system. Ran mysqlcheck and all the tables are recovered - including the one that I was never able to in the previous attempt. Everything seems to be normal so far. But this definitely makes me wonder if indeed we had a disk problem. But performing diagnostics on the disk resulted in no warnings or errors. I am wondering if it would help, if we were to use raw disk for MySQL. We may be able to sacrifice a bit of performance, but will it help in not repeating such a situation. -Srinivas
[16 Jun 2006 14:27]
Heikki Tuuri
Srinivas, if copying the file to a different location fixed the problem, then it looks like a disk problem. Though I do not understand how a disk problem could cause the errors that were printed in the .err log! Regards, Heikki
[16 Jun 2006 16:13]
Srinivas Bolisetty
Yeah.. this is a mystery to me as well... After running the database for a couple of days, we had the same problem repeat again... This time I am working with James Day and Domas Mituzas at MySQL to see what is going on... They looked at the queries involving date based search criteria and said this bug (#13379) reported on 4.1 is probably different issue altogether... Though our verison is different 5.0.20, the errors in the err log are almost similar to those originally reported on this bug here... so there may be some interest on our findings from the research.. I will update them here... -Srinivas
[5 Jul 2006 16:14]
Srinivas Bolisetty
Just an update. As per the discussion I had with James and Domas we had run memtest and ltptools on our hardware. Also ran "lftest" to write to each every byte of the partition that holds MySQL data checking md5 of each written file against a master set. None of the tests failed on the hardware so far. -Srinivas
[3 Sep 2006 20:30]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/11320 ChangeSet@1.2538, 2006-09-03 22:30:16+02:00, tnurnberg@salvation.intern.azundris.com +3 -0 Bug#13379 Loss of DB connection with certain subselects Certain subselects featuring 'BETWEEN x AND y' clauses would trigger an error that would cause InnoDB to panic if x and y were equal integers/dates. This case now gets optimized to '= x'.
[6 Sep 2006 11:03]
Sergey Petrunya
Setting back to in progress, based on the outcome of the irc discussion about "The not yet known reason of missing ha_innobase::index_read() call"
[13 Sep 2006 12:20]
Tatiana Azundris Nuernberg
fix for Bug#21077 also addressed this
Description: During a select with a sub-select which uses an index containing a date field, with a between having the same date for start & end, the database dies with error ERROR 2013 (HY000) at line 1: Lost connection to MySQL server during query Repro script attached below. How to repeat: #!/bin/sh user=$1 passwd=$2 if [ -z $user ] || [ -z $passwd ] then echo "Usage: trac675.sh user passwd {[init|cleanup]}" echo "cleanup deletes database and log files" echo "init creates database, tables & inserts data" echo "Otherwise, run the test" exit fi if [ x$3 = xinit ] then # Create database, 2 tables, with date field, ID, data mysql -u$user -p$passwd -e "create database trac675" cat > trac675.sql <<EOF CREATE TABLE tab1 ( id INT, uid INT, state INT, PRIMARY KEY (id, uid)) ENGINE=InnoDB; CREATE TABLE tab2 ( id INT, uid INT, date DATETIME, PRIMARY KEY (id, uid, date)) ENGINE=InnoDB; INSERT INTO tab1 VALUES (1,2,1), (1,1,2), (2,3,1); INSERT INTO tab2 VALUES (1, 2, '2005-01-01'), (1, 1, '2005-01-01'), (2, 3, '2005-01-01'); EOF mysql -u$user -p$passwd trac675 < trac675.sql 2>&1 > trac675.log elif [ x$3 = xcleanup ] then rm trac675.sql trac675.log mysql -u$user -p$passwd -e "drop database trac675" else cat > trac675.sql <<EOF SELECT * FROM tab1 WHERE (id,uid) IN (SELECT tab2.id,tab2.uid FROM tab2,tab1 WHERE tab1.id=tab2.id AND tab2.id=1 AND tab1.uid = tab2.uid AND tab2.uid=2 AND tab1.state=1 AND tab2.date BETWEEN '2005-01-01 00:00:00' AND '2005-01-01 00:00:00'); EOF echo "SQL command:" > trac675.log echo >> trac675.log cat trac675.sql >> trac675.log echo >> trac675.log echo "Result:" >> trac675.log echo >> trac675.log mysql -u$user -p$passwd trac675 < trac675.sql 2>&1 >> trac675.log if [ $? -ne 0 ] then echo "TEST FAILED" echo >> trac675.log echo "TEST FAILED" >> trac675.log fi fi Suggested fix: Workaround: Replace "between date1 and date1" with "=date1", or add a second to date1 for the after.