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:
None 
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
Description:
InnoDB repeatedly crashes the server after catching an assertion:

InnoDB: Error: MySQL is trying to perform a consistent read                                                
InnoDB: but the read view is not assigned!                                                                 
TRANSACTION D6775CAC, ACTIVE 0 sec, process no 19367, OS thread id 1084614976 starting index read          
mysql tables in use 11, locked 11                                                                          
MySQL thread id 260769, query id 4842046485 foo.bar.com xxx.yy.zz.42 stats Sending data
... <query removed> ...
090528  1:10:19  InnoDB: Assertion failure in thread 1084614976 in file row/row0sel.c line 3750            
InnoDB: Failing assertion: 0                                                                               
InnoDB: We intentionally generate a memory trap.                 

This happens sporadically and for different SELECT queries.

How to repeat:
n/a
[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".