| Bug #6841 | SELECT DISTINCT crashes with InnoDB and subquery | ||
|---|---|---|---|
| Submitted: | 26 Nov 2004 9:50 | Modified: | 3 Dec 2004 23:16 |
| Reporter: | Dimitri Redant | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server | Severity: | S1 (Critical) |
| Version: | 4.1.7 | OS: | Linux (Linux) |
| Assigned to: | Oleksandr Byelkin | CPU Architecture: | Any |
[26 Nov 2004 9:50]
Dimitri Redant
[26 Nov 2004 10:26]
MySQL Verification Team
Verified with 4.1.8-debug-log This is INSERT statement to add test data: insert into pay_desk values (NULL, '1999-01-01', 1,'test', 22, 33, 'comment'), (NULL, '1999-01-01', 1,'test', 22, 33, 'comment'), (NULL, '1999-01-01', 1,'test', 22, 33, 'comment'), (NULL, '1998-01-01', 1,'test', 22, 33, 'comment'), (NULL, '1998-01-01', 1,'test', 22, 33, 'comment'), (NULL, '2004-01-01', 1,'test', 22, 33, 'comment'), (NULL, '2004-01-01', 1,'test', 22, 33, 'comment');
[26 Nov 2004 11:13]
Heikki Tuuri
Victoria, please always in cases like this run mysqld inside gdb, and post the stack trace to the bug report. Regards, Heikki
[26 Nov 2004 13:26]
Heikki Tuuri
Sanja, looks like MySQL releases the table locks too early. InnoDB asserts because MySQL is reading a table that is not locked. Regards, Heikki heikki@hundin:~/mysql-4.1/sql> gdb mysqld GNU gdb 6.0 Copyright 2003 Free Software Foundation, Inc. GDB is free software, covered by the GNU General Public License, and you are welcome to change it and/or distribute copies of it under certain conditions. Type "show copying" to see the conditions. There is absolutely no warranty for GDB. Type "show warranty" for details. This GDB was configured as "i686-pc-linux-gnu"... (gdb) run Starting program: /home/heikki/mysql-4.1/sql/mysqld [New Thread 16384 (LWP 6993)] [New Thread 32769 (LWP 6995)] [New Thread 16386 (LWP 6996)] [New Thread 32771 (LWP 6997)] [New Thread 49156 (LWP 6998)] [New Thread 65541 (LWP 6999)] 041126 14:46:33 InnoDB: Database was not shut down normally! InnoDB: Starting crash recovery. InnoDB: Reading tablespace information from the .ibd files... InnoDB: Restoring possible half-written data pages from the doublewrite InnoDB: buffer... 041126 14:46:34 InnoDB: Starting log scan based on checkpoint at InnoDB: log sequence number 1 63587428. 041126 14:46:34 InnoDB: Starting an apply batch of log records to the database. .. InnoDB: Progress in percents: 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 4 7 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 InnoDB: Apply batch completed 041126 14:46:36 InnoDB: Starting an apply batch of log records to the database. .. InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 7 3 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 InnoDB: Apply batch completed 041126 14:46:37 InnoDB: Starting an apply batch of log records to the database. .. InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 7 3 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 InnoDB: Apply batch completed 041126 14:46:38 InnoDB: Starting an apply batch of log records to the database. .. InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 7 3 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 InnoDB: Apply batch completed 041126 14:46:40 InnoDB: Starting an apply batch of log records to the database. .. InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 7 3 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 InnoDB: Apply batch completed InnoDB: Doing recovery: scanned up to log sequence number 1 65159995 InnoDB: 5 transaction(s) which must be rolled back or cleaned up InnoDB: in total 95 row operations to undo InnoDB: Trx id counter is 0 1641472 041126 14:46:41 InnoDB: Starting an apply batch of log records to the database. .. InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 7 3 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 InnoDB: Apply batch completed InnoDB: Starting rollback of uncommitted transactions InnoDB: Rolling back trx with id 0 1641074, 5 rows to undo InnoDB: Rolling back of trx id 0 1641074 completed InnoDB: Rolling back trx with id 0 1641071, 6 rows to undo InnoDB: Rolling back of trx id 0 1641071 completed InnoDB: Rolling back trx with id 0 1641061, 3 rows to undo InnoDB: Rolling back of trx id 0 1641061 completed InnoDB: Rolling back trx with id 0 1641040, 23 rows to undo InnoDB: Rolling back of trx id 0 1641040 completed InnoDB: Rolling back trx with id 0 1640873, 58 rows to undo InnoDB: Rolling back of trx id 0 1640873 completed InnoDB: Rollback of uncommitted transactions completed InnoDB: Last MySQL binlog file position 0 4, file name ./binlog.000009 041126 14:46:43 InnoDB: Flushing modified pages from the buffer pool... [New Thread 81926 (LWP 7000)] [New Thread 98311 (LWP 7001)] [New Thread 114696 (LWP 7002)] 041126 14:46:43 InnoDB: Started; log sequence number 1 65159995 [New Thread 131081 (LWP 7003)] 041126 14:46:44 [Warning] mysql.user table is not updated to new password format ; Disabling new password usage until mysql_fix_privilege_tables is run /home/heikki/mysql-4.1/sql/mysqld: ready for connections. Version: '4.1.8-debug-log' socket: '/home/heikki/bugsocket' port: 3307 Source distribution [New Thread 147466 (LWP 7041)] InnoDB: Error: MySQL is trying to perform a SELECT InnoDB: but it has not locked any tables in ::external_lock()! TRANSACTION 0 1641479, not started, process no 7041, OS thread id 147466, thread declared inside InnoDB 500 MySQL thread id 1, query id 4 localhost heikki Sending data SELECT DISTINCT (SELECT sum(sum_used) FROM pay_desk WHERE sum_used > 0 AND year(date1) <= '2004') as somallontvangsten, (SELECT sum(sum_used) FROM pay_desk WHERE sum_used < 0 AND year(date1) <= '2004') as somalluitgaven FROM pay_desk 041126 14:48:52InnoDB: Assertion failure in thread 147466 in file row0sel.c line 2851 InnoDB: Failing assertion: 0 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. Program received signal SIGSEGV, Segmentation fault. [Switching to Thread 147466 (LWP 7041)] 0x0827b99c in row_search_for_mysql (buf=0x8620908 "ÿ", mode=1, prebuilt=0x4028c868, match_mode=0, direction=0) at row0sel.c:2851 2851 ut_a(0); Current language: auto; currently c (gdb) bt #0 0x0827b99c in row_search_for_mysql (buf=0x8620908 "ÿ", mode=1, prebuilt=0x4028c868, match_mode=0, direction=0) at row0sel.c:2851 #1 0x08201bca in ha_innobase::index_read(char*, char const*, unsigned, ha_rkey_ function) (this=0x8620598, buf=0x0, key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at ha_innodb.cc:3015 #2 0x082020a1 in ha_innobase::index_first(char*) (this=0x8620598, buf=0x0) at ha_innodb.cc:3254 #3 0x08202231 in ha_innobase::rnd_next(char*) (this=0x8620598, buf=0x8620908 "ÿ") at ha_innodb.cc:3346 #4 0x081f18c5 in rr_sequential (info=0x862fb3c) at records.cc:206 #5 0x081b1d3f in join_init_read_record (tab=0x862fb18) at sql_select.cc:6202 #6 0x081b0fea in sub_select (join=0x862df10, join_tab=0x862fb18, end_of_records=false) at sql_select.cc:5766 #7 0x081b0cae in do_select (join=0x862df10, fields=0x862fb18, table=0x0, procedure=0x0) at sql_select.cc:5674 #8 0x081a6513 in JOIN::exec() (this=0x862df10) at sql_select.cc:1463 #9 0x08139eea in subselect_single_select_engine::exec() (this=0x86074e0) at item_subselect.cc:1250 #10 0x081368e4 in Item_subselect::exec() (this=0x8607458) at item_subselect.cc:200 #11 0x081373b0 in Item_singlerow_subselect::val() (this=0x8607458) at item_subselect.cc:441 #12 0x080e820d in Item::send(Protocol*, String*) (this=0x8607458, protocol=0x861b43c, buffer=0x4c2dd06c) at item.cc:1992 #13 0x0815395b in select_send::send_data(List<Item>&) (this=0x8607f60, items=@0x0) at sql_class.cc:821 #14 0x081b21ab in end_send (join=0x8607f70, join_tab=0x862f858, end_of_records=false) at sql_select.cc:6366 #15 0x081b10a3 in sub_select (join=0x8607f70, join_tab=0x862f718, end_of_records=false) at sql_select.cc:5790 #16 0x081b0cae in do_select (join=0x8607f70, fields=0x862f718, table=0x0, procedure=0x0) at sql_select.cc:5674 #17 0x081a6513 in JOIN::exec() (this=0x8607f70) at sql_select.cc:1463 #18 0x081a6980 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=0x861ac68, rref_pointer_array=0x861ae78, tables=0x8607dd0, wild_num=0, fields=@0x0, conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=8669697, result=0x8607f60, unit=0x861acb0, select_lex=0x861ad90) at sql_select.cc:1584 #19 0x081a2c3f in handle_select(THD*, st_lex*, select_result*) (thd=0x861ac68, lex=0x861aca4, result=0x8607f60) at sql_select.cc:182 #20 0x08179bdb in mysql_execute_command(THD*) (thd=0x861ac68) at sql_parse.cc:2009 #21 0x0817f087 in mysql_parse(THD*, char*, unsigned) (thd=0x861ac68, inBuf=0x8606bb0 "SELECT DISTINCT (SELECT sum(sum_used) FROM pay_desk WHERE s um_used > 0 AND\nyear(date1) <= '2004') as somallontvangsten, (SELECT sum(sum_us ed) FROM pay_desk\nWHERE sum_used < 0 AND year(date1) <= '2004'"..., length=140618916) at sql_parse.cc:4074 #22 0x08178560 in dispatch_command(enum_server_command, THD*, char*, unsigned) (command=COM_QUERY, thd=0x861ac68, packet=0x8629a19 "", packet_length=234) at sql_parse.cc:1466 #23 0x08177e7f in do_command(THD*) (thd=0x861ac68) at sql_parse.cc:1280 #24 0x0817737b in handle_one_connection (arg=0x0) at sql_parse.cc:1024 #25 0x40062f60 in pthread_start_thread () from /lib/i686/libpthread.so.0 #26 0x400630fe in pthread_start_thread_event () from /lib/i686/libpthread.so.0 #27 0x401f5327 in clone () from /lib/i686/libc.so.6 (gdb) frame 0 #0 0x0827b99c in row_search_for_mysql (buf=0x8620908 "ÿ", mode=1, prebuilt=0x4028c868, match_mode=0, direction=0) at row0sel.c:2851 2851 ut_a(0); (gdb) list 2846 "InnoDB: Error: MySQL is trying to perform a SELECT\n" 2847 "InnoDB: but it has not locked any tables in ::external_lock()!\n", 2848 stderr); 2849 trx_print(stderr, trx); 2850 fputc('\n', stderr); 2851 ut_a(0); 2852 } 2853 2854 /* fprintf(stderr, "Match mode %lu\n search tuple ", (ulong) match_ mode); 2855 dtuple_print(search_tuple); (gdb) I put a breakpoint to ::external_lock(). The query first acquires 3 locks on the table, then releases all of them, but continues to query the table: ............................ [Switching to Thread 147466 (LWP 7108)] Breakpoint 1, ha_innobase::external_lock(THD*, int) (this=0x861c058, thd=0x861ac28, lock_type=0) at ha_innodb.cc:4946 4946 row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_prebuilt; Current language: auto; currently c++ (gdb) c Continuing. Breakpoint 1, ha_innobase::external_lock(THD*, int) (this=0x862aeb0, thd=0x861ac28, lock_type=0) at ha_innodb.cc:4946 4946 row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_prebuilt; (gdb) c Continuing. Breakpoint 1, ha_innobase::external_lock(THD*, int) (this=0x862c6f8, thd=0x861ac28, lock_type=0) at ha_innodb.cc:4946 4946 row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_prebuilt; (gdb) Continuing. Breakpoint 1, ha_innobase::external_lock(THD*, int) (this=0x861c058, thd=0x861ac28, lock_type=2) at ha_innodb.cc:4946 4946 row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_prebuilt; (gdb) Continuing. Breakpoint 1, ha_innobase::external_lock(THD*, int) (this=0x862aeb0, thd=0x861ac28, lock_type=2) at ha_innodb.cc:4946 4946 row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_prebuilt; (gdb) Continuing. Breakpoint 1, ha_innobase::external_lock(THD*, int) (this=0x862c6f8, thd=0x861ac28, lock_type=2) at ha_innodb.cc:4946 4946 row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_prebuilt; (gdb) Continuing. InnoDB: Error: MySQL is trying to perform a SELECT InnoDB: but it has not locked any tables in ::external_lock()! TRANSACTION 0 1641984, not started, process no 7108, OS thread id 147466, thread declared inside InnoDB 500 MySQL thread id 1, query id 1 localhost heikki Sending data SELECT DISTINCT (SELECT sum(sum_used) FROM pay_desk WHERE sum_used > 0 AND year( date1) <= '2004') as somallontvangsten, (SELECT sum(sum_used) FROM pay_desk WHER E sum_used < 0 AND year(date1) <= '2004') as somalluitgaven FROM pay_desk 041126 14:53:44InnoDB: Assertion failure in thread 147466 in file row0sel.c line 2851 InnoDB: Failing assertion: 0
[30 Nov 2004 19:43]
Oleksandr Byelkin
ChangeSet 1.2119 04/11/30 21:41:12 bell@sanja.is.com.ua +5 -0 now we create temporary join for all queries with subqueries to make correct cleunup of tables and avoid too early unlock (BUG#6841)
[3 Dec 2004 23:16]
Oleksandr Byelkin
Thank you for bugreport! Bug is fixed, patch is pushed in our source repository.
