MySQL crash recovery when Semi-sync replication switched OFF

Bug #1606911 reported by zhugaojian
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
New
Undecided
Unassigned

Bug Description

mysql> \s
--------------
mysql Ver 14.14 Distrib 5.5.33, for Linux (x86_64) using readline 5.1

Connection id: 15234
Current database:
Current user: root@localhost
SSL: Not in use
Current pager: stdout
Using outfile: ''
Using delimiter: ;
Server version: 5.7.11-4-log Source distribution
Protocol version: 10
Connection: Localhost via UNIX socket
Server characterset: utf8
Db characterset: utf8
Client characterset: utf8
Conn. characterset: utf8
UNIX socket: /home/work/data/tmp/mysql3508.sock
Uptime: 2 hours 32 min 28 sec

OS:CentOS release 6.3

after doing 'set global rpl_semi_sync_slave_enabled=OFF',mysql restarted

error log:
2016-07-27T18:07:47.014281+08:00 2006600 [Note] Semi-sync replication switched OFF.
2016-07-27T18:07:47.014445+08:00 2006600 [Note] Semi-sync replication disabled on the master.
2016-07-27T18:07:47.014915+08:00 0 [Note] Stopping ack receiver thread
10:07:47 UTC - 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.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=1048576
read_buffer_size=8388608
max_used_connections=3641
max_threads=65544
thread_count=2067
connection_count=2049
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 1075128933 K bytes of memory
Thread pointer: 0x0
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...
2016-07-27T10:07:48.697947Z mysqld_safe Number of processes running now: 0
2016-07-27T10:07:48.699099Z mysqld_safe mysqld restarted
2016-07-27T10:07:48.713768Z 0 [Warning] option 'max_connections': unsigned value 102400 adjusted to 100000
2016-07-27T18:07:48.834401+08:00 0 [Warning] The syntax '--log_warnings/-W' is deprecated and will be removed in a future release. Please use '--log_error_verbosity' instead.
2016-07-27T18:07:48.834951+08:00 0 [Note] /home/work/app/percona-5.7.11/bin/mysqld (mysqld 5.7.11-4-log) starting as process 36777 ...
2016-07-27T18:07:48.840540+08:00 0 [Warning] InnoDB: Using innodb_support_xa is deprecated and the parameter may be removed in future releases. Only innodb_support_xa=ON is allowed.
2016-07-27T18:07:48.840586+08:00 0 [Note] InnoDB: PUNCH HOLE support available
2016-07-27T18:07:48.840597+08:00 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2016-07-27T18:07:48.840604+08:00 0 [Note] InnoDB: Uses event mutexes
2016-07-27T18:07:48.840612+08:00 0 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
2016-07-27T18:07:48.840619+08:00 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2016-07-27T18:07:48.840625+08:00 0 [Note] InnoDB: Using Linux native AIO
2016-07-27T18:07:48.867858+08:00 0 [Note] InnoDB: Number of pools: 1
2016-07-27T18:07:48.867919+08:00 0 [Note] InnoDB: Using CPU crc32 instructions
2016-07-27T18:07:49.133871+08:00 0 [Note] InnoDB: Initializing buffer pool, total size = 40G, instances = 1, chunk size = 128M
2016-07-27T18:07:51.194232+08:00 0 [Note] InnoDB: Completed initialization of buffer pool
2016-07-27T18:07:51.519141+08:00 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2016-07-27T18:07:51.532631+08:00 0 [Note] InnoDB: Recovering partial pages from the parallel doublewrite buffer at /home/work/data/mysql/data3508/xb_doublewrite
2016-07-27T18:07:51.537473+08:00 0 [Note] InnoDB: Opened 3 undo tablespaces
2016-07-27T18:07:51.537496+08:00 0 [Note] InnoDB: 3 undo tablespaces made active
2016-07-27T18:07:51.537634+08:00 0 [Note] InnoDB: Highest supported file format is Barracuda.
2016-07-27T18:07:51.756544+08:00 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 101809180271
2016-07-27T18:07:51.756597+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 101809233972
2016-07-27T18:07:51.977150+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 101809233972
2016-07-27T18:07:52.063007+08:00 0 [Note] InnoDB: Created parallel doublewrite buffer at /home/work/data/mysql/data3508/xb_doublewrite, size 3932160 bytes
2016-07-27T18:07:52.154898+08:00 0 [Note] InnoDB: Transaction 5019191 was in the XA prepared state.
2016-07-27T18:07:52.158005+08:00 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 0 row operations to undo
2016-07-27T18:07:52.158021+08:00 0 [Note] InnoDB: Trx id counter is 5019648
2016-07-27T18:07:52.177093+08:00 0 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 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
2016-07-27T18:07:54.348147+08:00 0 [Note] InnoDB: Apply batch completed
2016-07-27T18:07:54.348185+08:00 0 [Note] InnoDB: Last MySQL binlog file position 0 591545867, file name mysql-bin.000054
2016-07-27T18:07:55.455943+08:00 0 [Note] InnoDB: Starting in background the rollback of uncommitted transactions
2016-07-27T18:07:55.455981+08:00 0 [Note] InnoDB: Rollback of non-prepared transactions completed
2016-07-27T18:07:55.459812+08:00 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2016-07-27T18:07:55.459829+08:00 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2016-07-27T18:07:55.459874+08:00 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2016-07-27T18:07:55.470754+08:00 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2016-07-27T18:07:55.471564+08:00 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2016-07-27T18:07:55.471578+08:00 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2016-07-27T18:07:55.472781+08:00 0 [Note] InnoDB: Waiting for purge to start
2016-07-27T18:07:55.523200+08:00 0 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.7.11-4 started; log sequence number 101809233972
2016-07-27T18:07:55.523784+08:00 0 [Note] InnoDB: Loading buffer pool(s) from /home/work/data/mysql/data3508/ib_buffer_pool
2016-07-27T18:07:55.524405+08:00 0 [Note] Plugin 'FEDERATED' is disabled.
2016-07-27T18:07:55.526354+08:00 0 [Note] Semi-sync replication initialized for transactions.
2016-07-27T18:07:55.526374+08:00 0 [Note] Semi-sync replication enabled on the master.
2016-07-27T18:07:55.526461+08:00 0 [Note] Starting ack receiver thread
2016-07-27T18:07:55.526621+08:00 0 [Note] Recovering after a crash using /home/work/data/mysql/data3508/mysql-bin
2016-07-27T18:07:55.541641+08:00 0 [Note] InnoDB: Buffer pool(s) load completed at 160727 18:07:55
2016-07-27T18:08:00.091220+08:00 0 [Note] Starting crash recovery...
2016-07-27T18:08:00.091442+08:00 0 [Note] InnoDB: Starting recovery for XA transactions...
2016-07-27T18:08:00.091455+08:00 0 [Note] InnoDB: Transaction 5019191 in prepared state after recovery
2016-07-27T18:08:00.091463+08:00 0 [Note] InnoDB: Transaction contains changes to 1 rows
2016-07-27T18:08:00.091470+08:00 0 [Note] InnoDB: 1 transactions in prepared state after recovery
2016-07-27T18:08:00.091476+08:00 0 [Note] Found 1 prepared transaction(s) in InnoDB
2016-07-27T18:08:00.091841+08:00 0 [Note] Crash recovery finished.
2016-07-27T18:08:17.152183+08:00 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
2016-07-27T18:08:17.152214+08:00 0 [Note] Server hostname (bind-address): '10.108.41.33'; port: 3508
2016-07-27T18:08:17.152272+08:00 0 [Note] - '10.108.41.33' resolves to '10.108.41.33';
2016-07-27T18:08:17.152287+08:00 0 [Note] Server socket created on IP: '10.108.41.33'.
2016-07-27T18:08:17.152447+08:00 0 [Note] Server hostname (bind-address): '10.108.41.33'; port: 8228
2016-07-27T18:08:17.152471+08:00 0 [Note] - '10.108.41.33' resolves to '10.108.41.33';
2016-07-27T18:08:17.152480+08:00 0 [Note] Server socket created on IP: '10.108.41.33'.
2016-07-27T18:08:17.155470+08:00 0 [Warning] 'user' entry 'root@localhost' ignored in --skip-name-resolve mode.
2016-07-27T18:08:17.155503+08:00 0 [Warning] 'user' entry 'mysql.sys@localhost' ignored in --skip-name-resolve mode.
2016-07-27T18:08:17.172458+08:00 0 [Warning] 'db' entry 'sys mysql.sys@localhost' ignored in --skip-name-resolve mode.
2016-07-27T18:08:17.194164+08:00 0 [Warning] 'proxies_priv' entry '@ root@localhost' ignored in --skip-name-resolve mode.
2016-07-27T18:08:17.199175+08:00 0 [Warning] 'tables_priv' entry 'sys_config mysql.sys@localhost' ignored in --skip-name-resolve mode.
2016-07-27T18:08:17.207037+08:00 0 [Warning] Recovery from master pos 556046356 and file mysql-bin.000003 for channel ''. Previous relay log pos and relay log file had been set to 454, /hom
e/work/data/mysql/data3508/mysql-relay-bin.000006 respectively.
2016-07-27T18:08:17.217788+08:00 0 [Note] Event Scheduler: Loaded 0 events
2016-07-27T18:08:17.217981+08:00 0 [Note] /home/work/app/percona-5.7.11/bin/mysqld: ready for connections.
Version: '5.7.11-4-log' socket: '/home/work/data/tmp/mysql3508.sock' port: 3508 Source distribution

Revision history for this message
zhugaojian (zhugaojian) wrote :
Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-3496

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Bug attachments

Remote bug watches

Bug watches keep track of this bug in other bug trackers.