【MySQL】mysqldgotsignal11案例一則

北在南方發表於2016-04-13
MySqlGo
  今天遇到一個案例:監控報警 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=`x00x00ax1912x00x00x1100:16:3e:0e:13:77 ……..省略N多 ….`
最終的解決方法是跳過出問題的binlog位置，重新啟動slave 程式。問題解決！
接下來
1 同步 entry表，使之和主庫一致。 
2 要求開發限制@7 欄位的長度而非無限制。


相關文章