今天遇到一个案例:监控报警 mysql 服务器突然crash,登陆数据库服务器发现mysqld_safe 进程存在,但是无法登陆数据库。
root@rac1 # my
Entry Port ==== 3306
ERROR 2003 (HY000): Can't connect to MySQL server on '127.0.0.1' (111)
root@masterdb1a.cms.xyi.aliyun.com # ps -ef | grep mysqld
root 15511 12134 0 14:06 pts/1 00:00:00 /bin/sh /usr/bin/mysqld_safe --defaults-file=/etc/my330**f --skip-slave-start=1
mysql 19846 15511 69 14:10 pts/1 00:00:05 /usr/sbin/mysqld --defaults-file=/etc/my330**f --basedir=/ --datadir=/home/mysql/data3306/mysql --user=mysql --skip-slave-start=1 --log-error=/home/mysql/data3306/mysql/master-error.log --open-files-limit=8192 --pid-file=/home/mysql/data3306/mysql/rac1.pid --socket=/tmp/mysql3306.sock --port=3306
master-error.log中的报警日志如下，mysqld在不停的crash,restart,但是slave 重启之后,数据库立刻就crash。
130313 13:46:59 InnoDB Plugin 1.0.9 started; log sequence number 1854409642790
130313 13:46:59 [Note] Recovering after a crash using /home/mysql/data3306/mysql/mysql-bin
130313 13:46:59 [Note] Starting crash recovery...
130313 13:46:59 [Note] Crash recovery finished.
130313 13:46:59 [Note] Event Scheduler: Loaded 0 events
130313 13:46:59 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.1.48-aliyun-log' socket: '/tmp/mysql3306.sock' port: 3306 MySQL Community Server (GPL)
130313 13:46:59 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.003860' at position 498385473, relay log '/home/mysql/data3306/mysql/slave-relay.011248' position: 498385618
130313 13:46:59 [Note] Slave I/O thread: connected to master 'replicator@172.18.150.10:3306',replication started in log 'mysql-bin.003860' at position 521361565
130313 13:47:00 - 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=314572800
read_buffer_size=1048576
max_used_connections=1
max_threads=4000
threads_connected=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 8540418 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
==========================================================================
上述内容实际上可以忽略 计算公式的值也不过850M,而数据库服务器总共47g,不会不满足分配对应的内存。由于数据库一启动slave 进程就crash,所以检查相关的binlog 内容 mysql-bin.003860 position 498385473 开始的内容是什么的？
root@rac1 # mysqlbinlog --no-defaults -v -v -v --start-position=498385473 mysql-bin.003860 > /home/admin/003860.sql
root@rac1 #
root@rac1 #
root@rac1 #
root@rac1 # cd /home/admin/
root@rac1 # more 003860.sql
# at 498385473
#130313 13:43:25 server id 1503306010 end_log_pos 498385553 Query thread_id=81671382 exec_time=0
....忽略一些注释信息
BEGIN
/*!*/;
# at 498385553
# at 498385657
# at 498385728
# at 498385794
# at 498386162
#130313 13:43:25 server id 1503306010 end_log_pos 498385657 Table_map: `c`.`node` mapped to number 0
#130313 13:43:25 server id 1503306010 end_log_pos 498385728 Table_map: `c`.`entry` mapped to number 0
#130313 13:43:25 server id 1503306010 end_log_pos 498385794 Table_map: `c`.`xxx_entry_rel` mapped to number 307680
#130313 13:43:25 server id 1503306010 end_log_pos 498386162 Update_rows: table id 0
#130313 13:43:25 server id 1503306010 end_log_pos 498386732 Update_rows: table id 0 flags: STMT_END_F
问题就出在红色的标记的位置,两个不同的表却被标记为 同一个0,sql thread 要用 number值来应用主库传过来的日志，重做sql，如果number值一样,就会出现张冠李戴的情况,sql应用报错。怀疑遇到bug。
thd: 0x2ab43a577000
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...
stack_bottom = 0x582130c8 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x21)[0x89a177]
/usr/sbin/mysqld(handle_segfault+0x35c)[0x5c75c8]
/lib64/libpthread.so.0[0x313700e7c0]
/lib64/libc.so.6(memset+0xade)[0x313647b44e]
/usr/sbin/mysqld(_ZN12Field_string6unpackEPhPKhjb+0x99)[0x5985a9]
/usr/sbin/mysqld(_Z10unpack_rowPK14Relay_log_infoP8st_tablejPKhPK9st_bitmapPS5_Pmbb+0x158)[0x6a2350]
/usr/sbin/mysqld(_ZN14Rows_log_event8find_rowEPK14Relay_log_info+0x39c)[0x68ef6c]
/usr/sbin/mysqld(_ZN21Update_rows_log_event11do_exec_rowEPK14Relay_log_info+0x13)[0x697267]
/usr/sbin/mysqld(_ZN14Rows_log_event14do_apply_eventEPK14Relay_log_info+0x7a4)[0x69592e]
/usr/sbin/mysqld(_Z26apply_event_and_update_posP9Log_eventP3THDP14Relay_log_info+0xfd)[0x709b2d]
/usr/sbin/mysqld(handle_slave_sql+0x96a)[0x70f09a]
/lib64/libpthread.so.0[0x31370064a7]
/lib64/libc.so.6(clone+0x6d)[0x31364d3c2d]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
上面的信息是说一些update相关的事情(有待进一步确认具体意义),解析的binlog中事务都是在对entry表多update操作，且字段@7明显有问题 多达数千字节。和前端开发确定@7字段应该有限制。
### UPDATE c.entry
### WHERE
### @1=24715 /* INT meta=0 nullable=1 is_null=0 */
### @2=NULL /* INT meta=0 nullable=1 is_null=1 */
### @3=838939137 /* INT meta=0 nullable=1 is_null=0 */
### @4=1497432085 /* INT meta=0 nullable=1 is_null=0 */
### @5=808530481 /* INT meta=0 nullable=1 is_null=0 */
### @6=842086449 /* INT meta=0 nullable=1 is_null=0 */
### @7=NULL /* INT meta=765 nullable=1 is_null=1 */
...
### SET
### @1=-1593835520 (2701131776) /* INT meta=0 nullable=1 is_null=0 */
### @2=72062304000948757 /* LONGINT meta=0 nullable=1 is_null=0 */
### @3=3277057 /* INT meta=0 nullable=1 is_null=0 */
### @4=30000 /* INT meta=0 nullable=1 is_null=0 */
### @5=-903638655 (3391328641) /* INT meta=0 nullable=1 is_null=0 */
### @6=4684 /* INT meta=0 nullable=1 is_null=0 */
### @7='\x00\x00a\x1912\x00\x00\x1100:16:3e:0e:13:77 ........省略N多 ....'
最终的解决方法是跳过出问题的binlog位置，重新启动slave 进程。问题解决！
接下来
1 同步 entry表，使之和主库一致。
2 要求开发限制@7 字段的长度而非无限制。