Qihoo360 / Atlas

A high-performance and stable proxy for MySQL, it is developed by Qihoo's DBA and infrastructure team
GNU General Public License v2.0
4.65k stars 1.15k forks source link

使用Atalas作为代理层mysql 导致mysql5.6奔溃 #174

Open lilien1010 opened 6 years ago

lilien1010 commented 6 years ago

mysql 版本:mysql Ver 14.14 Distrib 5.6.36, for Linux (x86_64) using EditLine wrapper

使用模式 Client -> Atlas -> Mysql

原来的使用方式是客户端直连Mysql,但是后面想做读写分离 就用了Atlas,但是发现通过Atalas 代理基本的读写业务之后,Mysql 会不定期奔溃(几乎每天都会奔溃一次),并且自动重启。

后面我们客户端改回去直连mysql的方式, 就没有出现奔溃的现象。

下面我贴出的是coredump记录,以及奔溃日志

关于COREDUMP 文件 如果有必要可以把coredump文件发出来。我们目前只得到下面的信息

通过对比源码发现是parser_state 从 thd 解析原始报文出来之后,数据报文里面的长度和sql语句对不上,解析出来的sql语句是 pdate HT_USER_PROPERTY set PROFILEVERSION = 1520829348 where USERID = 6059889; sql语句前面少了一个u

下面是奔溃Log

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=2097152
max_used_connections=197
max_threads=1000
thread_count=182
connection_count=181
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 4239845 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x281d0770
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 = 7f5184ccbea0 thread_stack 0x100000
/usr/local/mysql/bin/mysqld(my_print_stacktrace+0x2c)[0x9009dc]
/usr/local/mysql/bin/mysqld(handle_fatal_signal+0x357)[0x6729c7]
/lib64/libpthread.so.0(+0xf5e0)[0x7f578bbd65e0]
/usr/local/mysql/bin/mysqld(_Z16digest_add_tokenP16sql_digest_statejP7YYSTYPE+0x71)[0x6cb691]
/usr/local/mysql/bin/mysqld(_Z8MYSQLlexP7YYSTYPEP3THD+0x60)[0x6e98c0]
/usr/local/mysql/bin/mysqld(_Z10MYSQLparseP3THD+0x7f6)[0x79c126]
/usr/local/mysql/bin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x130)[0x6fc740]
/usr/local/mysql/bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1418)[0x6fe468]
/usr/local/mysql/bin/mysqld(_Z24do_handle_one_connectionP3THD+0x1fd)[0x6c568d]
/usr/local/mysql/bin/mysqld(handle_one_connection+0x39)[0x6c56d9]
/usr/local/mysql/bin/mysqld(pfs_spawn_thread+0x143)[0xb31923]
/lib64/libpthread.so.0(+0x7e25)[0x7f578bbcee25]
/lib64/libc.so.6(clone+0x6d)[0x7f578aca134d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f510442302f): is an invalid pointer
Connection ID (thread ID): 6554
Status: NOT_KILLED

The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
Writing a core file
2018-03-12 12:36:29 12176 [Note] Plugin 'FEDERATED' is disabled.
2018-03-12 12:36:29 12176 [Note] InnoDB: Using atomics to ref count buffer pool pages
2018-03-12 12:36:29 12176 [Note] InnoDB: The InnoDB memory heap is disabled
2018-03-12 12:36:29 12176 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-03-12 12:36:29 12176 [Note] InnoDB: Memory barrier is not used
2018-03-12 12:36:29 12176 [Note] InnoDB: Compressed tables use zlib 1.2.3
2018-03-12 12:36:29 12176 [Note] InnoDB: Using CPU crc32 instructions
2018-03-12 12:36:29 12176 [Note] InnoDB: Initializing buffer pool, size = 22.0G
2018-03-12 12:36:30 12176 [Note] InnoDB: Completed initialization of buffer pool
2018-03-12 12:36:31 12176 [Note] InnoDB: Highest supported file format is Barracuda.
2018-03-12 12:36:31 12176 [Note] InnoDB: Log scan progressed past the checkpoint lsn 3412483943928
2018-03-12 12:36:31 12176 [Note] InnoDB: Database was not shutdown normally!
2018-03-12 12:36:31 12176 [Note] InnoDB: Starting crash recovery.
2018-03-12 12:36:31 12176 [Note] InnoDB: Reading tablespace information from the .ibd files...
2018-03-12 12:36:32 12176 [Note] InnoDB: Restoring possible half-written data pages 
2018-03-12 12:36:32 12176 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 3412489186304
InnoDB: Doing recovery: scanned up to log sequence number 3412492675710
2018-03-12 12:36:32 12176 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 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: Last MySQL binlog file position 0 728658151, file name mysql-bin.000279
2018-03-12 12:36:37 12176 [Note] InnoDB: 128 rollback segment(s) are active.
2018-03-12 12:36:37 12176 [Note] InnoDB: Waiting for purge to start
2018-03-12 12:36:37 12176 [Note] InnoDB: 5.6.36 started; log sequence number 3412492675710
2018-03-12 12:36:37 12176 [Note] Recovering after a crash using mysql-bin
2018-03-12 12:36:40 12176 [Note] Starting crash recovery...
2018-03-12 12:36:40 12176 [Note] Crash recovery finished.
2018-03-12 12:36:42 12176 [Note] Server hostname (bind-address): '*'; port: 3306
2018-03-12 12:36:42 12176 [Note] IPv6 is available.
2018-03-12 12:36:42 12176 [Note]   - '::' resolves to '::';
2018-03-12 12:36:42 12176 [Note] Server socket created on IP: '::'.
2018-03-12 12:36:42 12176 [Warning] 'user' entry 'root@ht6' ignored in --skip-name-resolve mode.
2018-03-12 12:36:42 12176 [Warning] 'user' entry '@ht6' ignored in --skip-name-resolve mode.
2018-03-12 12:36:42 12176 [Warning] 'proxies_priv' entry '@ root@HT6' ignored in --skip-name-resolve mode.
2018-03-12 12:36:42 12176 [Note] Event Scheduler: Loaded 3 events
2018-03-12 12:36:42 12176 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.6.36-log'  socket: '/htdata/mysql/mysql.sock'  port: 3306  Source distribution
2018-03-12 12:36:42 12176 [Note] Event Scheduler: scheduler thread started with id 1

COREDUMP 文件

(gdb) bt
#0  0x00007f578bbd39b1 in pthread_kill () from /lib64/libpthread.so.0
#1  0x000000000067298d in handle_fatal_signal (sig=11) at /usr/local/src/mysql-5.6.36/sql/signal_handler.cc:230
#2  <signal handler called>
#3  read_token (tok=<synthetic pointer>, index=4294967294, digest_storage=0x281d20c8) at /usr/local/src/mysql-5.6.36/sql/sql_digest.cc:70
#4  digest_add_token (state=0x281d20c0, token=token@entry=0, yylval=0x7f5184cca920) at /usr/local/src/mysql-5.6.36/sql/sql_digest.cc:603
#5  0x00000000006e98c0 in add_digest_token (yylval=<optimized out>, token=<optimized out>, this=<optimized out>) at /usr/local/src/mysql-5.6.36/sql/sql_lex.cc:391
#6  MYSQLlex (yylval=yylval@entry=0x7f5184cca920, thd=thd@entry=0x281d0770) at /usr/local/src/mysql-5.6.36/sql/sql_lex.cc:980
#7  0x000000000079c126 in MYSQLparse (YYTHD=YYTHD@entry=0x281d0770) at /export/home2/pb2/build/sb_2-22757651-1489819423.63/dist_GPL/sql/sql_yacc.cc:18502
#8  0x00000000006fc740 in parse_sql (creation_ctx=0x0, parser_state=0x7f5184ccb740, thd=0x281d0770) at /usr/local/src/mysql-5.6.36/sql/sql_parse.cc:8408
#9  mysql_parse (thd=thd@entry=0x281d0770, rawbuf=rawbuf@entry=0x7f510442302f "", length=length@entry=4017, parser_state=parser_state@entry=0x7f5184ccb740)
    at /usr/local/src/mysql-5.6.36/sql/sql_parse.cc:6340
#10 0x00000000006fe468 in dispatch_command (command=<optimized out>, thd=0x281d0770, packet=<optimized out>, packet_length=<optimized out>) at /usr/local/src/mysql-5.6.36/sql/sql_parse.cc:1451
#11 0x00000000006ffca4 in do_command (thd=<optimized out>) at /usr/local/src/mysql-5.6.36/sql/sql_parse.cc:1039
#12 0x00000000006c568d in do_handle_one_connection (thd_arg=thd_arg@entry=0x28260da0) at /usr/local/src/mysql-5.6.36/sql/sql_connect.cc:982
#13 0x00000000006c56d9 in handle_one_connection (arg=arg@entry=0x28260da0) at /usr/local/src/mysql-5.6.36/sql/sql_connect.cc:899
#14 0x0000000000b31923 in pfs_spawn_thread (arg=0x275c2c30) at /usr/local/src/mysql-5.6.36/storage/perfschema/pfs.cc:1860
#15 0x00007f578bbcee25 in start_thread () from /lib64/libpthread.so.0
#16 0x00007f578aca134d in clone () from /lib64/libc.so.6
(gdb) bt full
 parser_state = {m_input = {m_compute_digest = false}, m_lip = {m_thd = 0x281d0770, yylineno = 1, yytoklen = 0, yylval = 0x7f5184cca920, lookahead_token = -1, lookahead_yylval = 0x0, 
            m_ptr = 0x7f5104423030 "", m_tok_start = 0x7f510442302f "", m_tok_end = 0x7f510442302f "", m_end_of_query = 0x7f5104423fe0 "", m_tok_start_prev = 0x0, m_buf = 0x7f510442302f "", 
            m_buf_length = 4017, m_echo = true, 
m_echo_saved = false, m_cpp_buf = 0x7f5104408a90 "", 
            m_cpp_ptr = 0x7f5104408a91 "pdate HT_USER_PROPERTY set PROFILEVERSION = 1520829348 where USERID = 6059889;", m_cpp_tok_start = 0x7f5104408a90 "", m_cpp_tok_start_prev = 0x0, 
            m_cpp_tok_end = 0x7f5104408a90 "", m_body_utf8 = 0x0, m_body_utf8_ptr = 0x0, m_cpp_utf8_processed_ptr = 0x0, next_state = MY_LEX_START, found_semicolon = 0x0, tok_bitmap = 127 '\177', 
            ignore_space = false, stmt_prepare_mode = false, multi_statements = true, in_comment = NO_COMMENT, in_comment_saved = NO_COMMENT, m_cpp_text_start = 0x7f5104408ad7 "6059889;", 
            m_cpp_text_end = 0x7f5104408ade ";", m_underscore_cs = 0x0, m_digest = 0x281d20c0}, m_yacc = {yacc_yyss = 0x0, yacc_yyvs = 0x0, m_set_signal_info = {m_item = {0x0 <repeats 12 times>}}, 
            m_lock_type = TL_READ_DEFAULT, m_mdl_type = MDL_SHARED_READ, m_ha_rkey_mode = HA_READ_KEY_EXACT}, m_digest_psi = 0x281d2108}
        net = 0x281d0980
        error = false
lilien1010 commented 6 years ago

Atlas版本 Atlas-sharding_1.0.1-el6.x86_64.rpm

mysql-proxy 0.8.2 chassis: mysql-proxy 0.8.2 glib2: 2.32.4 libevent: 2.0.20-stable

longxibendi commented 6 years ago

试试mysql5.6.26 看看有没有这个问题

introspection3 commented 6 years ago

oh no! I think you should repair this error. dear 360