MySQL Bugs: #33199: Signal 11 when starting slave for the first time

Bug #33199	Signal 11 when starting slave for the first time
Submitted:	13 Dec 2007 6:26	Modified:	19 Dec 2007 15:05
Reporter:	Michael Bacarella	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S1 (Critical)
Version:	5.1.22-rc-community-log	OS:	Linux (CentOS release 4.4 (Final))
Assigned to:		CPU Architecture:	Any
Tags:	5.1.22, crash, innobase, innodb, rc, replication, segfault, Signal 11, SIGSEGV

Description:
071213 0:28:01 [Note] Slave I/O thread: connected to master 'repl@db-w.gpshopper.com:3306',replication started in log 'mysql-repl.000011' at position 75042759
071213 0:29:17 - 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=1048576000
read_buffer_size=4190208
max_used_connections=2
max_threads=151
threads_connected=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 11539210 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x1499340
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=0x4510b118, backtrace may not be correct.
Stack range sanity check OK, backtrace follows:
(nil)
New value of fp=0x1499340 failed sanity check, terminating stack trace!
Please read http://dev.mysql.com/doc/refman/5.1/en/resolve-stack-dump.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 (nil) is invalid pointer
thd->thread_id=3
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.
071213 00:29:17 mysqld_safe Number of processes running now: 0
071213 00:29:17 mysqld_safe mysqld restarted

Server continues to restart and crash in a tight loop at this point.

How to repeat:
Set up a MySQL 5.1.22 master on Linux CentOS 5 x86_64
master# rpm -qi MySQL-server-community-5.1.22-0.rhel4
Name : MySQL-server-community Relocations: (not relocatable)
Version : 5.1.22 Vendor: MySQL AB
Release : 0.rhel4 Build Date: Tue 25 Sep 2007 09:48:57 AM EDT
Install Date: Tue 04 Dec 2007 06:25:38 PM EST Build Host: rh-x86-64.mysql.com
Group : Applications/Databases Source RPM: MySQL-community-5.1.22-0.rhel4.src.rpm
Size : 46241615 License: GPL
Signature : DSA/SHA1, Fri 28 Sep 2007 12:23:34 PM EDT, Key ID 8c718d3b5072e1f5
Packager : MySQL Product Engineering Team <build@mysql.com>
URL : http://www.mysql.com/
Summary : @COMMENT@ for Red Hat Enterprise Linux 4

Populate it with both InnoDB, MyISAM, and Federated table types.

rsync the data to a 5.1.22 slave, running the same OS, arch, and mysqld.

slave# rpm -qi MySQL-server-community-5.1.22-0.rhel4
Name : MySQL-server-community Relocations: (not relocatable)
Version : 5.1.22 Vendor: MySQL AB
Release : 0.rhel4 Build Date: Tue 25 Sep 2007 09:48:57 AM EDT
Install Date: Wed 12 Dec 2007 08:24:56 PM EST Build Host: rh-x86-64.mysql.com
Group : Applications/Databases Source RPM: MySQL-community-5.1.22-0.rhel4.src.rpm
Size : 46241615 License: GPL
Signature : DSA/SHA1, Fri 28 Sep 2007 12:23:34 PM EDT, Key ID 8c718d3b5072e1f5
Packager : MySQL Product Engineering Team <build@mysql.com>
URL : http://www.mysql.com/
Summary : @COMMENT@ for Red Hat Enterprise Linux 4

Slave has no relay-bin or relay.info files at this point. We start mysql, we start slave, and the crash happens immediately after updates are resumed on the master (site comes back up).

Suggested fix:
Shouldn't segfault.

Repairing MyISAM tables takes a very long time. :(

Here's a gdb stack backtrace:

slave# gdb mysqld
GNU gdb Red Hat Linux (6.3.0.0-1.132.EL4rh)
Copyright 2004 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 "x86_64-redhat-linux-gnu"...(no debugging symbols found)
Using host libthread_db library "/lib64/tls/libthread_db.so.1".

(gdb) run --user=mysql
Starting program: /usr/sbin/mysqld --user=mysql
(no debugging symbols found)
[Thread debugging using libthread_db enabled]
[New Thread 182894093568 (LWP 23001)]
(no debugging symbols found)
(no debugging symbols found)
(no debugging symbols found)
(no debugging symbols found)
(no debugging symbols found)
(no debugging symbols found)
[New Thread 1084229984 (LWP 23004)]
(no debugging symbols found)

Program received signal SIG33, Real-time event 33.
[Switching to Thread 1084229984 (LWP 23004)]
0x0000003200bc6874 in clone () from /lib64/tls/libc.so.6
(gdb) cont
Continuing.
(no debugging symbols found)

Program received signal SIG33, Real-time event 33.
0x000000320090b350 in _dl_debug_state () from /lib64/ld-linux-x86-64.so.2
(gdb) cont
Continuing.
[Thread 1084229984 (zombie) exited]
[New Thread 1084229984 (LWP 23005)]
[New Thread 1094719840 (LWP 23006)]
[New Thread 1105209696 (LWP 23007)]
[New Thread 1115699552 (LWP 23008)]
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
071213  7:56:47  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: In a MySQL replication slave the last master binlog file
InnoDB: position 0 896113724, file name mysql-repl.004982
InnoDB: Last MySQL binlog file position 0 74994725, file name ./mysql-repl.000011
[New Thread 1126189408 (LWP 22990)]
[Thread 1126189408 (LWP 22990) exited]
[New Thread 1136679264 (LWP 22991)]
[New Thread 1147169120 (LWP 22992)]
[New Thread 1157658976 (LWP 22993)]
071213  7:56:47  InnoDB: Started; log sequence number 15 2034101867
071213  7:56:47 [Note] Recovering after a crash using mysql-repl
071213  7:56:47 [Note] Starting crash recovery...
071213  7:56:47 [Note] Crash recovery finished.
[New Thread 1157925216 (LWP 22994)]
071213  7:56:47 [Warning] 'user' entry '@db.slifter.com' ignored in --skip-name-resolve mode.
071213  7:56:47 [Warning] 'user' entry 'shoplifter@db.slifter.com' ignored in --skip-name-resolve mode.
[New Thread 1158191456 (LWP 22995)]
(no debugging symbols found)
(no debugging symbols found)
[New Thread 1158457696 (LWP 22996)]
071213  7:56:47 [ERROR] Incorrect definition of table mysql.event: expected column 'name' at position 1 to have type char(64), found type varchar(64).
071213  7:56:47 [ERROR] Incorrect definition of table mysql.event: expected column 'character_set_client' at position 18 to have type char(32), found type varchar(32).
071213  7:56:47 [ERROR] Incorrect definition of table mysql.event: expected column 'collation_connection' at position 19 to have type char(32), found type varchar(32).
071213  7:56:47 [ERROR] Incorrect definition of table mysql.event: expected column 'db_collation' at position 20 to have type char(32), found type varchar(32).
071213  7:56:47 [ERROR] Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler.
071213  7:56:47 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.1.22-rc-community-log'  socket: '/vol/mysql/mysql.sock'  port: 3306  MySQL Community Edition (GPL)
071213  7:56:47 [Note] Slave SQL thread initialized, starting replication in log 'mysql-repl.000012' at position 20467, relay log '/vol/mysql/meridius-relay-bin.000003' position: 20613

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 1158457696 (LWP 22996)]
0x000000000078b4aa in dict_scan_to ()
(gdb) bt
#0  0x000000000078b4aa in dict_scan_to ()
#1  0x000000000078bf0a in dict_str_starts_with_keyword ()
#2  0x00000000007ee4b5 in row_search_for_mysql ()
#3  0x00000000007693a9 in ha_innobase::index_read ()
#4  0x0000000000769cf2 in ha_innobase::rnd_pos ()
#5  0x000000000069ec20 in Rows_log_event::find_row ()
#6  0x000000000069f351 in Update_rows_log_event::do_exec_row ()
#7  0x000000000069bee4 in Rows_log_event::do_apply_event ()
#8  0x00000000006f5d31 in handle_slave_sql ()
#9  0x000000320140610a in start_thread () from /lib64/tls/libpthread.so.0
#10 0x0000003200bc68b3 in clone () from /lib64/tls/libc.so.6
#11 0x0000000000000000 in ?? ()
(gdb)

master# cat /etc/redhat-release
CentOS release 5 (Final)
master# uname -a
Linux master 2.6.18-8.el5 #1 SMP Thu Mar 15 19:46:53 EDT 2007 x86_64 x86_64 x86_64 GNU/Linux

slave# cat /etc/redhat-release
CentOS release 4.4 (Final)
slave# uname -a
Linux slave 2.6.9-42.ELsmp #1 SMP Tue Aug 15 10:35:26 BST 2006 x86_64 x86_64 x86_64 GNU/Linux

Many thanks for writing a bug report.

Please, can you add your my.cnf for the master and the slave.
What did you do exactly on the slave and master to startup the system?
(I mean something like "change master to" and start/stop slave)
Do you copy the master data dir to the slave data dir?

Hi Susanne,

master# cat /etc/my.cnf
[mysqlcheck]
socket=/vol/mysql/mysql.sock

[libmysql]
socket=/vol/mysql/mysql.sock

[mysqld]
skip-name-resolve
server-id=3
log-bin=mysql-repl
datadir=/vol/mysql/
socket=/vol/mysql/mysql.sock
innodb_additional_mem_pool_size=2M      # innodb metadata
innodb_buffer_pool_size=500M            # 512MB buffer-cache
innodb_flush_log_at_trx_commit=0        # don't fsync() on every COMMIT
innodb_autoextend_increment=32          # grow table in 32MB steps
old_passwords=1
transaction-isolation=READ-COMMITTED
relay-log=/vol/mysql/josephus-relay-bin

set-variable=max_allowed_packet=32M     # bigger for bigger imports
set-variable=key_buffer_size=1000M       # shared by all threads
set-variable=sort_buffer_size=64M       # thread-local
set-variable=read_buffer_size=4M        # thread-local
set-variable=net_buffer_length=32768    # thread-local
set-variable=read_rnd_buffer_size=1M    # enhances GROUP BY/ORDER BY reads?
set-variable=table-cache=256
set-variable=tmp_table_size=192M
set-variable=net_write_timeout=1200
set-variable=slave_skip_errors=1062,1061,1060,1216

[mysql.server]
user=mysql
basedir=/usr

[mysqld_safe]
err-log=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

slave# cat /etc/my.cnf
# cat /etc/my.cnf

[mysqlcheck]
socket=/vol/mysql/mysql.sock

[libmysql]
socket=/vol/mysql/mysql.sock

[mysqld]
skip-name-resolve
server-id=14
log-bin=mysql-repl
datadir=/vol/mysql/
socket=/vol/mysql/mysql.sock
innodb_additional_mem_pool_size=2M      # innodb metadata
innodb_buffer_pool_size=500M            # 512MB buffer-cache
innodb_flush_log_at_trx_commit=0        # don't fsync() on every COMMIT
innodb_autoextend_increment=32          # grow table in 32MB steps
old_passwords=1
transaction-isolation=READ-COMMITTED
relay-log=/vol/mysql/meridius-relay-bin

set-variable=max_allowed_packet=32M     # bigger for bigger imports
set-variable=key_buffer_size=1000M       # shared by all threads
set-variable=sort_buffer_size=64M       # thread-local
set-variable=read_buffer_size=4M        # thread-local
set-variable=net_buffer_length=32768    # thread-local
set-variable=read_rnd_buffer_size=1M    # enhances GROUP BY/ORDER BY reads?
set-variable=table-cache=256
set-variable=tmp_table_size=192M
set-variable=net_write_timeout=1200
set-variable=slave_skip_errors=1062,1061,1060,1216

[mysql.server]
user=mysql
basedir=/usr

[mysqld_safe]
err-log=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

> What did you do exactly on the slave and master to startup the system?
> (I mean something like "change master to" and start/stop slave)
> Do you copy the master data dir to the slave data dir?

We...

1. Took all traffic away from the master (took down site).

2. Did a SHOW MASTER STATUS and recorded the bin-log and position.

3. Shut down the master mysqld and the slave mysqld.

4. Copied the master data dir to the slave data dir using rsync.  Approximately this:  slave# rsync -a -v --delete master:/var/lib/mysql /var/lib/mysql

5. Deleted the *.info and *.index files on the slave side so that it would start fresh.

6. Started the master mysqld.

7. Started the slave mysqld.

8. Ran CHANGE MASTER TO ... on the slave and directed it to the master at the previously recorded bin-log and position.

9. Ran slave start.

10. Brought the site back up so that the master mysqld would receive traffic again.  Slave crashed immediately once this happened, within seconds.

Any restart of the slave mysqld results in the gdb stack backtrace in my previous comment.

Regarding the my.cnf file above, please note that on the filesystem /vol/mysql is a symlink to /var/lib/mysql.

I noted replication keeps failing in the same spot on relay-bin.000003 position 20614.  Here's a look at this position on the slave.

slave# mysqlbinlog --start-position 20612 /vol/mysql/meridius-relay-bin.000003 --stop-position 20614
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
ERROR: Error in Log_event::read_log_event(): 'read error', data_len: 23808, event_type: 71
Could not read entry at offset 20612:Error in log format or read error
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

Here's the corresponding mysql-repl log on the master is mysql-repl.000012 at position 20467:

master# mysqlbinlog --start-position 20466 --stop-position 20468                    mysql-repl.000012
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
ERROR: Error in Log_event::read_log_event(): 'Sanity check failed', data_len: 23                   808, event_type: 71
Could not read entry at offset 20466:Error in log format or read error
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

Please disregard the previous post (delete it if possible).
I was misusing the mysqlbinlog tool.

Maybe this will be more useful.

master# mysqlbinlog -H --start-position 20467 mysql-repl.000012 | less
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 20467
# at 20560
#71213 0:29:17 server id 3  end_log_pos 20560
#     4ff3 2d c3 60 47 13 03 00 00  00 5d 00 00 00 50 50 00 |...G.........PP.|
#     5003 00 00 00 20 00 00 00 00  00 00 00 0d 67 70 73 68 |............gpsh|
#     5013 6f 70 70 65 72 5f 31 5f  31 00 11 4d 6f 62 69 6c |opper.1.1..Mobil|
#     5023 65 55 73 65 72 50 72 6f  66 69 6c 65 00 10 08 0f |eUserProfile....|
#     5033 03 03 03 0c 0c 01 08 08  03 0f  |..........|
#       Table_map: `gpshopper_1_1`.`MobileUserProfile` mapped to number 32
#71213 0:29:17 server id 3  end_log_pos 20760
#     5050 2d c3 60 47 18 03 00 00  00 c8 00 00 00 18 51 00 |...G..........Q.|
#     5060 00 10 00 20 00 00 00 00  00 01 00 10 ff ff ff ff |................|
#     5070 00 00 44 00 00 00 00 00  00 00 06 31 30 30 30 31 |..D........10001|
#     5080 00 64 00 00 00 00 00 00  00 00 00 00 00 88 49 20 |.d............I.|
#     5090 0e 41 12 00 00 c5 8b fe  30 41 12 00 00 00 01 00 |.A......0A......|
#     50a0 00 00 00 00 00 00 45 00  00 00 00 00 00 00 fb 02 |......E.........|
#     50b0 00 00 00 00 00 00 00 00  02 36 39 08 31 32 33 34 |.........69.1234|
#     50c0 35 36 37 38 00 00 44 00  00 00 00 00 00 00 06 31 |5678..D........1|
#     50d0 30 30 30 31 00 64 00 00  00 00 00 00 00 00 00 00 |0001.d..........|
#     50e0 00 88 49 20 0e 41 12 00  00 a5 70 85 31 41 12 00 |..I..A....p.1A..|
#     50f0 00 00 01 00 00 00 00 00  00 00 45 00 00 00 00 00 |..........E.....|
#     5100 00 00 fc 02 00  |.....|
#       Update_rows: table id 32 flags: STMT_END_F

BINLOG '
LcNgRxMDAAAAXQAAAFBQAAAAACAAAAAAAAAADWdwc2hvcHBlcl8xXzEAEU1vYmlsZVVzZXJQcm9m
aWxlABAIDwMDAwwMAQgIAw8PDw8PDB4ALAEsAf0CPAAYAPr4
LcNgRxgDAAAAyAAAABhRAAAQACAAAAAAAAEAEP////8AAEQAAAAAAAAABjEwMDAxAGQAAAAAAAAA
AAAAAIhJIA5BEgAAxYv+MEESAAAAAQAAAAAAAABFAAAAAAAAAPsCAAAAAAAAAAACNjkIMTIzNDU2
NzgAAEQAAAAAAAAABjEwMDAxAGQAAAAAAAAAAAAAAIhJIA5BEgAApXCFMUESAAAAAQAAAAAAAABF
AAAAAAAAAPwCAAAAAAAAAAACNjkIMTIzNDU2Nzg=
'/*!*/;
# at 20760

and this from the slave's relay log:

slave# mysqlbinlog -H --start-position 20613 meridius-relay-bin.000003
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 20613
# at 20706
#71213 0:29:17 server id 3  end_log_pos 20560
#     5085 2d c3 60 47 13 03 00 00  00 5d 00 00 00 50 50 00 |...G.........PP.|
#     5095 00 00 00 20 00 00 00 00  00 00 00 0d 67 70 73 68 |............gpsh|
#     50a5 6f 70 70 65 72 5f 31 5f  31 00 11 4d 6f 62 69 6c |opper.1.1..Mobil|
#     50b5 65 55 73 65 72 50 72 6f  66 69 6c 65 00 10 08 0f |eUserProfile....|
#     50c5 03 03 03 0c 0c 01 08 08  03 0f  |..........|
#       Table_map: `gpshopper_1_1`.`MobileUserProfile` mapped to number 32
#71213 0:29:17 server id 3  end_log_pos 20760
#     50e2 2d c3 60 47 18 03 00 00  00 c8 00 00 00 18 51 00 |...G..........Q.|
#     50f2 00 10 00 20 00 00 00 00  00 01 00 10 ff ff ff ff |................|
#     5102 00 00 44 00 00 00 00 00  00 00 06 31 30 30 30 31 |..D........10001|
#     5112 00 64 00 00 00 00 00 00  00 00 00 00 00 88 49 20 |.d............I.|
#     5122 0e 41 12 00 00 c5 8b fe  30 41 12 00 00 00 01 00 |.A......0A......|
#     5132 00 00 00 00 00 00 45 00  00 00 00 00 00 00 fb 02 |......E.........|
#     5142 00 00 00 00 00 00 00 00  02 36 39 08 31 32 33 34 |.........69.1234|
#     5152 35 36 37 38 00 00 44 00  00 00 00 00 00 00 06 31 |5678..D........1|
#     5162 30 30 30 31 00 64 00 00  00 00 00 00 00 00 00 00 |0001.d..........|
#     5172 00 88 49 20 0e 41 12 00  00 a5 70 85 31 41 12 00 |..I..A....p.1A..|
#     5182 00 00 01 00 00 00 00 00  00 00 45 00 00 00 00 00 |..........E.....|
#     5192 00 00 fc 02 00  |.....|
#       Update_rows: table id 32 flags: STMT_END_F

BINLOG '
LcNgRxMDAAAAXQAAAFBQAAAAACAAAAAAAAAADWdwc2hvcHBlcl8xXzEAEU1vYmlsZVVzZXJQcm9m
aWxlABAIDwMDAwwMAQgIAw8PDw8PDB4ALAEsAf0CPAAYAPr4
LcNgRxgDAAAAyAAAABhRAAAQACAAAAAAAAEAEP////8AAEQAAAAAAAAABjEwMDAxAGQAAAAAAAAA
AAAAAIhJIA5BEgAAxYv+MEESAAAAAQAAAAAAAABFAAAAAAAAAPsCAAAAAAAAAAACNjkIMTIzNDU2
NzgAAEQAAAAAAAAABjEwMDAxAGQAAAAAAAAAAAAAAIhJIA5BEgAApXCFMUESAAAAAQAAAAAAAABF
AAAAAAAAAPwCAAAAAAAAAAACNjkIMTIzNDU2Nzg=
'/*!*/;
# at 20906
#71213 0:29:17 server id 3  end_log_pos 20787
#     51aa 2d c3 60 47 10 03 00 00   |...G....|
#       Xid = 371
COMMIT/*!*/;
# at 20933
#71213 0:29:17 server id 3  end_log_pos 20957
#     51c5 2d c3 60 47 02 03 00 00  00 aa 00 00 00 dd 51 00 |...G..........Q.|
#     51d5 00 10 00 17 00 00 00 00  00 00 00 07 00 00 1a 00 |................|
#     51e5 00 00 40 00 00 01 00 00  00 00 00 00 00 00 06 03 |................|
#     51f5 73 74 64 04 08 00 08 00  08 00 73 65 73 73 69 6f |std.......sessio|
#     5205 6e 00 44 45 4c 45 54 45  20 46 52 4f 4d 20 74 6f |n.DELETE.FROM.to|
#     5215 6d 63 61 74 20 57 48 45  52 45 20 69 64 20 3d 20 |mcat.WHERE.id...|
#     5225 27 30 45 39 45 32 30 34  32 38 39 39 36 36 46 41 |.0E9E204289966FA|
#     5235 36 36 30 30 43 41 38 31  34 33 34 36 39 43 39 39 |6600CA8143469C99|
#     5245 35 27 20 20 41 4e 44 20  61 70 70 20 3d 20 27 2f |5...AND.app.....|
#     5255 43 61 74 61 6c 69 6e  |Catalin|
#       Query   thread_id=23    exec_time=0     error_code=0
use session/*!*/;
SET TIMESTAMP=1197523757/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1/*!*/;
SET @@session.sql_mode=0/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
DELETE FROM tomcat WHERE id = '0E9E204289966FA6600CA8143469C995'  AND app = '/Catalina/localhost/mobile'/*!*/;
# at 21103

Please, check if you have enough memory ...
Also I see another thing:

071213  7:56:47 [ERROR] Incorrect definition of table mysql.event: expected column 'name'
at position 1 to have type char(64), found type varchar(64).
...

mysql> show create table event\G
*************************** 1. row ***************************
       Table: event
Create Table: CREATE TABLE `event` (
  `db` char(64) CHARACTER SET utf8 COLLATE utf8_bin NOT NULL DEFAULT '',
  `name` char(64) NOT NULL DEFAULT '',
...

I have no idea, where you get the wrong datatypes, but maybe this is the reason for your crashes.

Regarding the memory issue, we have 8GB of RAM and 102GB of swap space.

Also, we do not use the events table at all.

I will file a separate bug report regarding the events table issue.  We have repeatedly run mysql_upgrade against it but we keep getting the same issue on startup.  It happens on multiple machines, master included.

mysql.event is a table, that the mysql server needs. Without it, it won't run.
So it would be interesting, why there are the wrong datatypes.
I think, this is very relevant for your problem.

The mysql startup log says it has disabled events handlers because the format of mysql.events is unfamiliar.  Those tables do not appear corrupted because:

mysql> use mysql
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
mysql> CHECK TABLE event;
+-------------+-------+----------+----------+
| Table       | Op    | Msg_type | Msg_text |
+-------------+-------+----------+----------+
| mysql.event | check | status   | OK       |
+-------------+-------+----------+----------+
1 row in set (0.04 sec)

If the unfamiliar format of the events table IS causing a problem, (and I do not believe this is so), then this is still a bug because mysqld says:

071213 13:22:19 [ERROR] Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler.

Nevertheless, we went through the stack dump above and tracked it down to a dereferenced null pointer in the innobase handler.  It seems row0sel.c has been significantly changed between mysql 5.0 and 5.1 and it does not check if trx->mysql_query_str is a valid pointer before comparing it.

Please consider including this fix in 5.1 and 6.0.  Replication runs fine now that we've done this.

diff -ur mysql-5.1old/storage/innobase/row/row0sel.c mysql-5.1/storage/innobase/row/row0sel.c
--- mysql-5.1old/storage/innobase/row/row0sel.c	2007-12-13 16:06:49.000000000 -0500
+++ mysql-5.1/storage/innobase/row/row0sel.c	2007-12-13 15:56:37.000000000 -0500
@@ -3562,7 +3562,7 @@
 
 		/* Scan the MySQL query string; check if SELECT is the first
 		word there */
-		if (dict_str_starts_with_keyword(
+		if (*trx->mysql_query_str && dict_str_starts_with_keyword(
 			    trx->mysql_thd, *trx->mysql_query_str, "SELECT")) {
 			/* It is a plain locking SELECT and the isolation
 			level is low: do not lock gaps */

The question is, why is there a NULL pointer, and why is here a big mix between MyISAM and InnoDB?

What exactly did you do?

I understand first: You upgrade MySQL 5.1.xx (older version) to 5.1.22, MyISAM to MyISAM.

No it looks like you upgraded MySQL 5.0 to 5.1 and MyISAM to InnoDB. Is this right?

Sorry, typo, I wanted to write "now" instead of "no".
Now it looks like you upgraded MySQL 5.0 to 5.1 and MyISAM to InnoDB. Is this right?

Yes, we mix MyISAM and InnoDB.

Before upgrade:
    MySQL 4.0.
    MyISAM tables
    InnoDB tables
    Replication

After upgrade:
    MySQL 5.1.22
    MyISAM tables
    InnoDB tables
    Replication

The tables which were MyISAM remained MyISAM.
The tables which were InnoDB remained InnoDB.

Hi Michael,

I'll hope this will be my last question. What did you do for upgrading from 4.0 to 5.1?
Do you do it like recommended? First upgrade to 4.1 then to 5.0 and then to 5.1?
http://dev.mysql.com/doc/refman/5.1/en/upgrade.html

Did you use dump, restore, mysql_upgrade and stuff like this?

We did not.  I guess we missed those instructions.

I was under the impression the mysql_upgrade would perform the necessary work to make everything safe for 5.1.

I'll close this bug now.
Please  try first to make the upgrade like it is described in our documentation.

If you still will get the same curious results after this, please feel free to open it again or to open.

Many thanks for choosing MySQL.