Bug #45303 | server crash due to assertion error during consistent read | ||
---|---|---|---|
Submitted: | 3 Jun 2009 12:48 | Modified: | 9 Jan 2010 13:42 |
Reporter: | Axel Schwenke | Email Updates: | |
Status: | No Feedback | Impact on me: | |
Category: | MySQL Server: InnoDB storage engine | Severity: | S1 (Critical) |
Version: | 5.1.33,5.1.40 | OS: | Linux (RHEL5/x86_64) |
Assigned to: | Assigned Account | CPU Architecture: | Any |
[3 Jun 2009 12:48]
Axel Schwenke
[3 Jun 2009 13:14]
Axel Schwenke
This happens in both internal InnoDB engine and the plugin. In 5.1.33 the error log show messages like so: InnoDB: Error: MySQL is trying to perform a consistent read InnoDB: but the read view is not assigned! TRANSACTION 0 3203691975, ACTIVE 0 sec, process no 9624, OS thread id 1169475904 starting index read, thread declared inside InnoDB 37 mysql tables in use 7, locked 7 MySQL thread id 849159, query id 12738263491 foo.bar.com xxx.yy.zz.42 stats Sending data <query removed> 090430 16:09:12 InnoDB: Assertion failure in thread 1169475904 in file row/row0sel.c line 3647 InnoDB: Failing assertion: 0 InnoDB: We intentionally generate a memory trap.
[11 Jun 2009 17:24]
saravanan krishnarajan
I tried to replicate from mysql 5.0.67 to 5.1.34 got the same problem with same error and server crashed. I tried the same with 5.1.35 also crashed the server. len 224; hex f095fe09000000009ada4757ab2a000080f1b04bab2a0000736f757263657320696e207468656972030000000000000002000000000000000000000000000000030000000000000001000000000000000000000000000000646f2c2065766572206265206469737375616465643f20566f6c756e74617269010000000000000083445107000000000000000000000000717569736820746865697220776569676874656420696e666c75656e63653f2060e111770000000004000000000000006022f509000000007320746f206d616b00000000000000006e20646563697369; asc GW * K * sources in their do, ever be dissuaded? Voluntari DQ quish their weighted influence? ` w `" s to mak n decisi; TRANSACTION 6943, ACTIVE 0 sec, process no 1457, OS thread id 1167513920 unlock_row mysql tables in use 2, locked 2 6 lock struct(s), heap size 3024, 3 row lock(s) MySQL thread id 4, query id 26262 Sending data <query removed> 090611 16:49:49 InnoDB: Assertion failure in thread 1167513920 in file btr/btr0pcur.c line 232 ---------------- /lib64/libpthread.so.0 [0x2af863624367] /lib64/libc.so.6(clone+0x6d) [0x2af864906f7d] Trying to get some variables. Some pointers may be invalid and cause the dump to abort... thd->query at 0xa0d8c3c = <query removed> thd->thread_id=4 thd->killed=NOT_KILLED
[7 Jul 2009 17:20]
Matthew Conway
I'm having the same problem - I'm using xtradb 1.0.3-5 (percona) - this has mysql 5.1.34 with innodb plugin 1.0.3: 090707 5:21:21 InnoDB: ERROR: the age of the last checkpoint is 9433665, InnoDB: which exceeds the log group capacity 9433498. InnoDB: If you are using big BLOB or TEXT rows, you must set the InnoDB: combined size of log files at least 10 times bigger than the InnoDB: largest such row. InnoDB: Error: MySQL is trying to perform a consistent read InnoDB: but the read view is not assigned! TRANSACTION 798894E, ACTIVE 0 sec, process no 29595, OS thread id 46921664674128 starting index read mysql tables in use 4, locked 1 MySQL thread id 9972, query id 14766408 app06 10.252.58.229 sml preparing SELECT count(*) AS count_all FROM `comments` WHERE (moderated = 1 and picture_id not in (select id from pictures where user_id = 354266)) AND (`comments`.user_id = 354266) 090707 5:55:18 InnoDB: Assertion failure in thread 46921664674128 in file row/row0sel.c line 3750 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/refman/5.1/en/forcing-recovery.html InnoDB: about forcing recovery. 090707 5:55:18 - mysqld got signal 6 ; 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. key_buffer_size=16777216 read_buffer_size=131072 max_used_connections=98 max_threads=600 threads_connected=92 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 5014491 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. thd: 0x2aacd00fef30 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... InnoDB: Error: MySQL is trying to perform a consistent read InnoDB: but the read view is not assigned! TRANSACTION 798894F, ACTIVE 0 sec, process no 29595, OS thread id 46921663457616 starting index read mysql tables in use 4, locked 1 MySQL thread id 9979, query id 14768318 app04 10.251.199.145 sml preparing SELECT count(*) AS count_all FROM `comments` WHERE (moderated = 1 and picture_id not in (select id from pictures where user_id = 354266)) AND (`comments`.user_id = 354266) 090707 5:55:18 InnoDB: Assertion failure in thread 46921663457616 in file row/row0sel.c line 3750 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/refman/5.1/en/forcing-recovery.html InnoDB: about forcing recovery. 090707 05:55:21 mysqld_safe Number of processes running now: 0 090707 05:55:21 mysqld_safe mysqld restarted 090707 5:55:21 [Warning] The syntax '--log_slow_queries' is deprecated and will be removed in MySQL 7.0. Please use '--slow_query_log'/'--slow_query_log_file' instead. 090707 5:55:21 [Warning] The syntax '--log_slow_queries' is deprecated and will be removed in MySQL 7.0. Please use '--slow_query_log'/'--slow_query_log_file' instead. InnoDB: The InnoDB memory heap is disabled InnoDB: Mutexes and rw_locks use GCC atomic builtins. 090707 5:55:22 InnoDB: highest supported file format is Barracuda. InnoDB: Log scan progressed past the checkpoint lsn 26185974997 090707 5:55:24 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... InnoDB: Doing recovery: scanned up to log sequence number 26191217664 InnoDB: Doing recovery: scanned up to log sequence number 26192700644 InnoDB: Transaction 7988947 was in the XA prepared state. InnoDB: 2 transaction(s) which must be rolled back or cleaned up InnoDB: in total 13297 row operations to undo InnoDB: Trx id counter is 7988B00 090707 5:55:25 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 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 InnoDB: In a MySQL replication slave the last master binlog file InnoDB: position 0 8609710, file name mysql-bin.001710 InnoDB: and relay log file InnoDB: position 0 8609855, file name /mnt/mysql/log/mysql-relay-bin.1943250 InnoDB: Last MySQL binlog file position 0 29744757, file name /mnt/mysql/log/mysql-bin.000075 InnoDB: Starting in background the rollback of uncommitted transactions 090707 5:56:15 InnoDB: Rolling back trx with id 7976A60, 13297 rows to undo InnoDB: Progress in percents: 1090707 5:56:15 InnoDB Plugin 1.0.3-5a started; log sequence number 26192700644 090707 5:56:15 [Note] Recovering after a crash using /mnt/mysql/log/mysql-bin 090707 5:56:15 [Note] Starting crash recovery... 090707 5:56:15 InnoDB: Starting recovery for XA transactions... 090707 5:56:15 InnoDB: Transaction 7988947 in prepared state after recovery 090707 5:56:15 InnoDB: Transaction contains changes to 1 rows 090707 5:56:15 InnoDB: 1 transactions in prepared state after recovery 090707 5:56:15 [Note] Found 1 prepared transaction(s) in InnoDB 090707 5:56:15 [Note] Crash recovery finished. 2 3090707 5:56:15 [Note] Event Scheduler: Loaded 0 events 090707 5:56:15 [Note] /usr/sbin/mysqld: ready for connections. Version: '5.1.34-xtradb5-log' socket: '/var/run/mysqld/mysqld.sock' port: 3306 (Ubuntu) 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 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 100 InnoDB: Rolling back of trx id 7976A60 completed 090707 5:56:24 InnoDB: Rollback of non-prepared transactions completed
[15 Jul 2009 6:56]
MySQL Verification Team
take a look at bug #46175 also ...
[5 Aug 2009 6:58]
Marko Mäkelä
The comment [11 Jun 19:24] looks like Bug #39320 aka Bug #45302.
[5 Aug 2009 7:21]
Marko Mäkelä
Can you enable core dumps and examine a core dump in gdb? I would like to see the stack trace and a complete dump of *trx and *prebuilt at the time of the assertion failure. Is there anything common between the queries? This looks like a duplicate of Bug #46175. My working hypothesis is that this is sometimes triggered by subquery execution. Could ha_innobase::external_lock() or ha_innobase::store_lock() close the read_view prematurely? Or could it be the case that trx->read_view is assigned to a curview->read_view while trx->global_read_view==NULL, and read_cursor_view_close_for_mysql() will leave trx->read_view and trx->global_read_view as NULL? This could cause problems with the following code snippets where we are not checking trx->global_read_view: if (!trx->read_view) { trx->read_view = read_view_open_now(trx, trx->global_read_view_heap); trx->global_read_view = trx->read_view; } On the other hand, this code was already in MySQL 5.0, and the bugs have been reported in 5.1. That would suggest a bug in ha_innodb.cc or the way how it is being invoked by the MySQL layer.
[5 Sep 2009 23:00]
Bugs System
No feedback was provided for this bug for over a month, so it is being suspended automatically. If you are able to provide the information that was originally requested, please do so and change the status of the bug back to "Open".
[3 Dec 2009 12:00]
MySQL Verification Team
Hi! The following testcase crashes 5.1.40, but gives a deadlock on 5.1.41. Therefore, this bug is a duplicate of some other bug fixed in 5.1.41! Open 2 sessions to mysql: session 1: drop table if exists t1,t2; create table t1(a tinyint not null,b tinyint,c tinyint,primary key(b))engine=innodb; create table t2(d tinyint not null)engine=innodb; start transaction; insert ignore into t1(a,b,c) values (abs(-60),abs(-101),abs(-109)); insert ignore into t2 values (abs(-53)); session 2: start transaction; insert ignore into t1(a,b,c) values (abs(68),abs(120),abs(-40)); session 1: select d from t2 where d not in (select a from t1); #this will hang for lock_wait_timeout session 2: insert ignore into t2 values (abs(92)); select d from t2 where d not in (select a from t1); #died Version: '5.1.40-enterprise-gpl-advanced-log' socket: '' port: 3306 MySQL Enterprise Server - Advance InnoDB: Error: MySQL is trying to perform a consistent read InnoDB: but the read view is not assigned! TRANSACTION 0 369932, ACTIVE 0 sec, OS thread id 11836 fetching rows, thread declared inside InnoDB 498 mysql tables in use 2, locked 1 MySQL thread id 1, query id 11 127.0.0.1 root Sending data select d from t2 where d not in (select a from t1) 091203 13:56:55 InnoDB: Assertion failure in thread 11836 in file .\row\row0sel.c line 3642 InnoDB: Failing assertion: 0 InnoDB: We intentionally generate a memory trap. 00000001402245F1 mysqld.exe!row_search_for_mysql()[row0sel.c:3642] 000000014020DCB4 mysqld.exe!ha_innobase::general_fetch()[ha_innodb.cc:4772] 000000014011C6AA mysqld.exe!rr_sequential()[records.cc:381] 000000014015AF3D mysqld.exe!sub_select()[sql_select.cc:11137] 000000014016EFA5 mysqld.exe!do_select()[sql_select.cc:10888] 000000014017023C mysqld.exe!JOIN::exec()[sql_select.cc:2206] 000000014017056A mysqld.exe!mysql_select()[sql_select.cc:2396] 0000000140170966 mysqld.exe!handle_select()[sql_select.cc:268] 0000000140068FC8 mysqld.exe!execute_sqlcom_select()[sql_parse.cc:5044] 000000014006A367 mysqld.exe!mysql_execute_command()[sql_parse.cc:2238] 000000014006E966 mysqld.exe!mysql_parse()[sql_parse.cc:5967] 000000014006F4FA mysqld.exe!dispatch_command()[sql_parse.cc:1226] 0000000140070167 mysqld.exe!do_command()[sql_parse.cc:865] 00000001400968B7 mysqld.exe!handle_one_connection()[sql_connect.cc:1127] 00000001403169D5 mysqld.exe!pthread_start()[my_winthread.c:85] 00000001402E0B07 mysqld.exe!_callthreadstart()[thread.c:295] 00000001402E0BD5 mysqld.exe!_threadstart()[thread.c:275] 0000000077D6B6CA kernel32.dll!BaseThreadStart() Trying to get some variables. Some pointers may be invalid and cause the dump to abort... thd->query at 0000000014E50C80=select d from t2 where d not in (select a from t1)
[9 Dec 2009 13:42]
Marko Mäkelä
Axel, I suspect that this is a duplicate of Bug #39022 and Bug #46175. Can you please find out if the crashing queries contain a (select) clause? It seems that the MySQL query executor is ignoring the fact that InnoDB aborted the transaction during subselect execution due to deadlock or lock wait timeout or some other reason. MySQL would carry on with the query execution, but InnoDB is getting upset because MySQL is attempting to use a stale transaction handle.
[10 Jan 2010 0:00]
Bugs System
No feedback was provided for this bug for over a month, so it is being suspended automatically. If you are able to provide the information that was originally requested, please do so and change the status of the bug back to "Open".