MySQL Bugs: #19421: MySQL server crashed when deleting from a table

Bug #19421	MySQL server crashed when deleting from a table
Submitted:	28 Apr 2006 10:13	Modified:	30 May 2006 1:38
Reporter:	McEase Tu	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: Partitions	Severity:	S2 (Serious)
Version:	5.1.9/5.1BK	OS:	GNU/Linux 2.6.8-3-686-smp
Assigned to:		CPU Architecture:	Any

Description:
It seems like Bug #5837. But the difference is that the server crashed when deleting from only one table.

I have two tables and have a program (multiple threads) processing the data through JDBC. Before the processing finished, I termilated the client. After that, I want to clean the data of one table through "mysql" client. Unfortunately, I got the following error every time I want to delete the data:

mysql> delete from test.tab2;
ERROR 2013 (HY000): Lost connection to MySQL server during query
mysql> 
Number of processes running now: 0
060428 17:46:13  mysqld restarted

Following are the error messages in error log:
060428 17:46:12InnoDB: Assertion failure in thread 2543668144 in file row0mysql.c line 1367
InnoDB: Failing assertion: node->pcur->rel_pos == BTR_PCUR_ON
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.

key_buffer_size=134217728
read_buffer_size=2093056
max_used_connections=1
max_connections=500
threads_connected=1
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 2177068 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd=0x9b24b70
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=0x979d35ec, backtrace may not be correct.
Stack range sanity check OK, backtrace follows:
0x8182a1d
0xffffe420
0x4
0x82bff2d
0x8242471
0x81fdd18
0x819a674
0x81a2743
0x8197d61
0x81978bd
0x8196c32
0x40036b63
0x4024018a
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 0x9b44838 = delete from test.tab2
thd->thread_id=1
The manual page at http://www.mysql.com/doc/en/Crashing.html contains
information that should help you find out what is causing the crash.

How to repeat:
My box has three cpu (Intel(R) Xeon(TM) CPU 2.80GHz), 2 disks, 3G memory, with "Linux 2.6.8-3-686-smp #1 SMP i686 GNU/Linux" installed.

I use InnoDB engine and some key parameters are as following:

innodb_data_file_path = ibdata1:512M:autoextend
innodb_autoextend_increment=32M
innodb_thread_concurrency=4

# You can set .._buffer_pool_size up to 50 - 80 %
# of RAM but beware of setting memory usage too high
innodb_buffer_pool_size = 1G
innodb_additional_mem_pool_size = 20M
innodb_log_files_in_group=2
# Set .._log_file_size to 25 % of buffer pool size
innodb_log_file_size = 256M
innodb_log_buffer_size = 8M
innodb_flush_log_at_trx_commit = 1
innodb_lock_wait_timeout = 50

Using following Java program to repeat this bug:

----------------- Java program start ----------------
import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.PreparedStatement;
import java.sql.ResultSet;
import java.sql.SQLException;
import java.sql.Timestamp;

public class CrashMySQL {
	private String host = "127.0.0.1";
	private String user = "root";
	private String pwd = "";
	
	public CrashMySQL () {
		try {
			Class.forName("com.mysql.jdbc.Driver");
		}
		catch (ClassNotFoundException e) {
			e.printStackTrace();
		}
	}
	
	public void  prepareData () {
		Connection conn;
		PreparedStatement pstmt;
		System.out.println("Preparing data...");
		try {
			conn = DriverManager.getConnection("jdbc:mysql://" + host + "/test", user, pwd);
			pstmt = conn.prepareStatement("drop table if exists test.tab1");
			pstmt.execute();
			pstmt.close();
			pstmt = conn.prepareStatement("create table test.tab1(str varchar(32), i int, primary key (str)) engine = innodb");
			pstmt.execute();
			pstmt.close();
			pstmt = conn.prepareStatement("drop table if exists test.tab2");
			pstmt.execute();
			pstmt.close();
			pstmt = conn.prepareStatement("create table test.tab2(str varchar(32), i int, t datetime, index(str)) engine = innodb" + 
					" partition by range(UNIX_TIMESTAMP(t)) subpartition by key(str) subpartitions 5" +
					" (partition p0 values less than (UNIX_TIMESTAMP('2006-05-05 12:00:00'))," + 
					"  partition p1 values less than (UNIX_TIMESTAMP('2006-05-12 12:00:00'))," +
					"  partition p2 values less than (UNIX_TIMESTAMP('2006-05-19 12:00:00'))," + 
					"  partition p3 values less than (UNIX_TIMESTAMP('2006-05-26 12:00:00')))");
			pstmt.execute();
			pstmt.close();
			pstmt = conn.prepareStatement("insert into test.tab1 values (?, ?)");
			for (int i = 0; i < 100000; i ++) {
				pstmt.setString(1, "str " + i);
				pstmt.setInt(2, i);
				pstmt.execute();
				if (i % 1000 == 0) {
					System.out.println(i + " rows inserted into test.tab1");
				}
			}
			pstmt.close();
			conn.close();
		}
		catch (SQLException sqle) {
			sqle.printStackTrace();
		}
	}
	
	public void crashIt () {
		for (int i = 0; i < 100; i++) {
			final int t = i;
			new Thread () {
				Connection conn = null;
				PreparedStatement pstmt = null;
				public void run () {
					System.out.println("Thread " + t + " started");
					try {
						conn = DriverManager.getConnection("jdbc:mysql://" + host + "/test", user, pwd);
						conn.setAutoCommit(false);
						pstmt = conn.prepareStatement("select * from test.tab1 where str = ? for update");
						for (int j = 0; j < 1000; j++) {
							pstmt.setString(1, "str " + (t * 1000 + j));
							ResultSet rs = pstmt.executeQuery();
							rs.close();
						}
						pstmt.close();
						pstmt = conn.prepareStatement("update test.tab1 set i = ? where str = ?");
						for (int j = 0; j < 1000; j++) {
							pstmt.setInt(1, t * 1000 + j + 1);
							pstmt.setString(2, "str " + (t * 1000 + j));
							pstmt.execute();
						}
						pstmt.close();
						pstmt = conn.prepareStatement("insert into test.tab2 values (?, ?, ?)");
						for (int j = 0; j < 1000; j++) {
							pstmt.setString(1, "str " + (t * 1000 + j));
							pstmt.setInt(2, t * 1000 + j);
							pstmt.setTimestamp(3, new Timestamp(System.currentTimeMillis()));
							pstmt.execute();
						}
						pstmt.close();
						conn.commit();
						conn.close();
					}
					catch (SQLException sqle) {
						try {
							if (conn != null)
								conn.rollback();
							if (pstmt != null)
								pstmt.close();
						} catch (SQLException e) {}
						sqle.printStackTrace();
					}
					System.out.println("Thread " + t + " ended");
				}
			}.start();
		}
	}
	
	public static void main(String [] args) {
		CrashMySQL crash = new CrashMySQL();
		crash.prepareData();
		crash.crashIt();
	}

}

----------------- Java program end   ----------------

This program will create two tables in test database, one of them is partitioned.
First, it will insert 100,000 records into test.tab1.
Second, it will create 100 thread to process data in test.tab1 and test.tab2. The processing is in a transaction.
After those threads start, wait until some of them end. 
Then press "Ctrl-C" to terminate this program immediately. 
NOTICE, DO NOT wait until all of the threads end.
Next, using mysql client delete test.tab2:
delete from test.tab2

Now, you should have got that error!

The java program that will lead to the server crash

Attachment: CrashMySQL.java (text/java), 3.76 KiB.

Thank you for the bug report. I did your test case on Suse Linux 10
and Windows XO and I was unable to repeat with the current source
server:

miguel@hegel:~/testbug> java CrashMySQL
Preparing data...
0 rows inserted into test.tab1
1000 rows inserted into test.tab1
2000 rows inserted into test.tab1
3000 rows inserted into test.tab1
4000 rows inserted into test.tab1
<cut>

Thread 54 started
Thread 55 started
Thread 56 started
^Cmiguel@hegel:~/testbug> 
miguel@hegel:~/dbs/5.1> bin/mysql -uroot test
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1 to server version: 5.1.10-beta-debug

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> delete from test.tab2;
Query OK, 0 rows affected (0.01 sec)

mysql> show create table tab2\G
*************************** 1. row ***************************
       Table: tab2
Create Table: CREATE TABLE `tab2` (
  `str` varchar(32) DEFAULT NULL,
  `i` int(11) DEFAULT NULL,
  `t` datetime DEFAULT NULL,
  KEY `str` (`str`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1 PARTITION BY RANGE (UNIX_TIMESTAMP(t)) SUBPARTITION BY KEY (str) SUBPARTITIONS 5 (PARTITION p0 VALUES LESS THAN (1146844800) , PARTITION p1 VALUES LESS THAN (1147449600) , PARTITION p2 VALUES LESS THAN (1148054400) , PARTITION p3 VALUES LESS THAN (1148659200) )
1 row in set (0.01 sec)

mysql> select count(*) from tab1;
+----------+
| count(*) |
+----------+
|   100000 | 
+----------+
1 row in set (0.34 sec)

mysql>

Hi Miguel,

Did you termilate the program when all of the threads are still running? At that point it seems hard to cause the server crash.
I termilate the program when some of (not all of) the threads end:

Preparing data...
0 rows inserted into test.tab1
1000 rows inserted into test.tab1
2000 rows inserted into test.tab1
....
Thread 23 started
....
Thread 96 started
Thread 97 started
Thread 99 started
Thread 98 started
Thread 3 ended
Thread 25 ended
^C    <------- Press Ctrl-C when some of the threads end (DONOT wait until all of them end)

I also repeated this problem (not sure it's a bug) under windows non-installation version of MySQL 5.1.7.

I will be on vacation in next week. But I will still try to keep up with this bug's status.

Thanks!

Hi McEase,

Sorry I didn't understand well the the Ctrl+C step. I am going to
test again.

Thanks for the feedback.

Thank you for the bug report.

c:\mysql\bin>mysqld-nt --standalone --console
060429 22:49:38  InnoDB: Started; log sequence number 0 23549986
060429 22:49:39 [Note] mysqld-nt: ready for connections.
Version: '5.1.10-beta'  socket: ''  port: 3306  Source distribution
060429 23:32:14InnoDB: Assertion failure in thread 3824 in file .\row\row0mysql.c line 1369
InnoDB: Failing assertion: node->pcur->rel_pos == BTR_PCUR_ON
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.
InnoDB: Thread 1304 stopped in file .\mem\mem0pool.c line 340
InnoDB: Thread 164 stopped in file .\os\os0sync.c line 309
InnoDB: Thread 2812 stopped in file .\os\os0sync.c line 309
InnoDB: Thread 584 stopped in file .\os\os0sync.c line 309
InnoDB: Thread 3880 stopped in file .\os\os0file.c line 2719
InnoDB: Thread 2732 stopped in file .\os\os0sync.c line 309
InnoDB: Thread 3276 stopped in file .\os\os0sync.c line 309
InnoDB: Thread 1388 stopped in file .\os\os0sync.c line 309
InnoDB: Thread 972 stopped in file .\os\os0sync.c line 309
InnoDB: Thread 3284 stopped in file .\os\os0sync.c line 309
InnoDB: Thread 3888 stopped in file .\os\os0sync.c line 309
InnoDB: Thread 2924 stopped in file .\fil\fil0fil.c line 4262
InnoDB: Thread 3236 stopped in file .\sync\sync0arr.c line 130
InnoDB: Thread 2308 stopped in file .\os\os0sync.c line 487
InnoDB: Thread 2308 stopped in file .\os\os0sync.c line 492
InnoDB: Thread 2924 stopped in file .\log\log0log.c line 1483
InnoDB: Thread 3428 stopped in file .\mem\mem0mem.c line 317
InnoDB: Thread 3236 stopped in file .\sync\sync0arr.c line 131
InnoDB: Thread 2812 stopped in file .\os\os0sync.c line 487
InnoDB: Thread 972 stopped in file .\os\os0sync.c line 487
InnoDB: Thread 3284 stopped in file .\os\os0sync.c line 487
InnoDB: Thread 3888 stopped in file .\os\os0sync.c line 487
InnoDB: Thread 3880 stopped in file .\os\os0sync.c line 304
InnoDB: Thread 3276 stopped in file .\os\os0sync.c line 487
InnoDB: Thread 1304 stopped in file .\mem\mem0pool.c line 394
InnoDB: Thread 164 stopped in file .\os\os0sync.c line 487
InnoDB: Thread 1388 stopped in file .\os\os0sync.c line 487
InnoDB: Thread 2732 stopped in file .\os\os0sync.c line 487
InnoDB: Thread 584 stopped in file .\os\os0sync.c line 487
mysql> delete from test.tab2;
ERROR 2013 (HY000): Lost connection to MySQL server during query
mysql>

CALL STACK ON WINDOWS:
 	mysqld-nt.exe!_row_update_for_mysql()  + 0x14c	C
 	mysqld-nt.exe!_os_fast_mutex_unlock()  + 0xb	C
>	mysqld-nt.exe!ha_partition::delete_row(const unsigned char * buf=0x00000004)  Line 2732 + 0x18	C++
 	mysqld-nt.exe!handler::ha_delete_row(const unsigned char * buf=0x04413f10)  Line 3331 + 0xf	C++
 	mysqld-nt.exe!mysql_delete(THD * thd=0x00f1e480, st_table_list * table_list=0x00000001, Item * conds=0x00000001,
          st_sql_list * order=0x00000001, unsigned long limit=0, unsigned __int64 options=0, int reset_auto_increment=0)
          Line 242 + 0xc	C++
 	mysqld-nt.exe!mysql_execute_command(THD * thd=0x00f1e480)  Line 3424 + 0x27	C++
 	mysqld-nt.exe!mysql_parse(THD * thd=0x02d8f270, char * inBuf=0x00e7cf88, unsigned int length=21)  Line 5879	C++
 	mysqld-nt.exe!dispatch_command(enum_server_command command=COM_QUERY, THD * thd=0x02d8f270, 
        char * packet=0x02d92fb9, unsigned int packet_length=22)  Line 1755	C++
 	mysqld-nt.exe!do_command(THD * thd=0x02d8f270)  Line 1539 + 0xd	C++
 	mysqld-nt.exe!handle_one_connection(void * arg=0x02d8f270)  Line 1181 + 0xa	C++
 	mysqld-nt.exe!_pthread_start()  + 0x3b	C
 	mswsock.dll!71a15ccc() 	
 	mysqld-nt.exe!_threadstart(void * ptd=0x00e74e20)  Line 196 + 0x6	C
 	kernel32.dll!7c80b50b() 	
 	mswsock.dll!71a15ccc() 	
 	kernel32.dll!7c8399f3() 

ON LINUX:

060501  1:30:41InnoDB: Assertion failure in thread 1116761008 in file row0mysql.c line 1369
InnoDB: Failing assertion: node->pcur->rel_pos == BTR_PCUR_ON
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.
InnoDB: Thread 1093684144 stopped in file srv0srv.c line 624
[Thread 1120881584 (zombie) exited]
[Thread 1121483696 (zombie) exited]
[Thread 1121082288 (zombie) exited]
InnoDB: Thread 1120480176 stopped in file ../include/sync0sync.ic line 112
InnoDB: Thread 1120279472 stopped in file ../include/sync0sync.ic line 112
InnoDB: Thread 1120078768 stopped in file ../include/sync0sync.ic line 112
InnoDB: Thread 1118686128 stopped in file ../include/sync0sync.ic line 112
InnoDB: Thread 1118084016 stopped in file ../include/sync0sync.ic line 112
InnoDB: Thread 1117682608 stopped in file ../include/sync0sync.ic line 112

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 1116761008 (LWP 2864)]
0x0842f87c in row_update_for_mysql (
    mysql_rec=0x92ad640 "ø\tstr 11004", ' ' <repeats 23 times>, "ü*", prebuilt=0x950d2b8)
    at row0mysql.c:1369
1369            ut_a(node->pcur->rel_pos == BTR_PCUR_ON);
Current language:  auto; currently c
(gdb) bt full
#0  0x0842f87c in row_update_for_mysql (
    mysql_rec=0x92ad640 "ø\tstr 11004", ' ' <repeats 23 times>, "ü*", prebuilt=0x950d2b8)
    at row0mysql.c:1369
        savept = {least_undo_no = {high = 1116754680, low = 138197822}}
        err = 155967192
        thr = (que_thr_t *) 0x94bded8
<CUT>

Miguel,

can you still repeat this with the latest 5.1.xx?

This might be duplicate of http://bugs.mysql.com/bug.php?id=17992

If you can repeat, please post full stack trace in gdb.

Regards,

Heikki

I was unable to repeat with current source server:

Thread 59 ended
miguel@hegel:~/testbug> 

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 2 to server version: 5.1.12-beta-debug

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> delete from test.tab2;
Query OK, 0 rows affected (0.05 sec)

mysql>

Miguel,

thank you! Bug http://bugs.mysql.com/bug.php?id=17992 can easily explain this bug report, since the trx id field in the record has been garbage, and InnoDB has not known that the record has been inserted by an uncommitted transaction and we should wait for a lock on the record.

Regards,

Heikki