MySQL crash during rotation of logs
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
Percona Server moved to https://jira.percona.com/projects/PS |
Incomplete
|
Undecided
|
Unassigned |
Bug Description
Hi Team,
Customer had a slave server crash encountered yesterday and would like to gather clues and information from what had caused here.
From the error log;
mysqld: /mnt/workspace/
18:00:01 UTC - mysqld got signal 6 ;
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.
Please help us make Percona Server better by reporting any
bugs at http://
key_buffer_
read_buffer_
max_used_
max_threads=1602
thread_count=225
connection_
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_
Hope that's ok; if not, decrease some variables in the equation.
Thread pointer: 0x2b70adbe0
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 = 7e9f96086f00 thread_stack 0x40000
/opt/percona/
/opt/percona/
/lib/x86_
/lib/x86_
/lib/x86_
/lib/x86_
/lib/x86_
/opt/percona/
/opt/percona/
/opt/percona/
/opt/percona/
/opt/percona/
/opt/percona/
/opt/percona/
/opt/percona/
/opt/percona/
/opt/percona/
/opt/percona/
/lib/x86_
/lib/x86_
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0): is an invalid pointer
Connection ID (thread ID): 1749910
Status: NOT_KILLED
You may download the Percona Server operations manual by visiting
http://
in the manual which will help you identify the cause of the crash.
170624 14:00:18 mysqld_safe mysqld restarted
170624 14:00:18 [Note] Plugin 'FEDERATED' is disabled.
170624 14:00:18 InnoDB: The InnoDB memory heap is disabled
170624 14:00:18 InnoDB: Mutexes and rw_locks use GCC atomic builtins
170624 14:00:18 InnoDB: Compressed tables use zlib 1.2.3
170624 14:00:18 InnoDB: Using Linux native AIO
170624 14:00:18 InnoDB: Initializing buffer pool, size = 410.0G
170624 14:03:32 InnoDB: Completed initialization of buffer pool
170624 14:03:32 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 16677824581769
170624 14:03:39 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: Doing recovery: scanned up to log sequence number 16677829824512
InnoDB: Doing recovery: scanned up to log sequence number 16677833682455
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 5281 row operations to undo
InnoDB: Trx id counter is 31D9938A00
170624 14:03:41 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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: In a MySQL replication slave the last master binlog file
InnoDB: position 625957624, file name mysql-bin.038544
InnoDB: and relay log file
InnoDB: position 625874562, file name /data/mysql/
InnoDB: Last MySQL binlog file position 0 623115901, file name /data/mysql/
InnoDB: Starting in background the rollback of uncommitted transactions
170624 14:04:14 InnoDB: Rolling back trx with id 31D9938764, 5281 rows to undo
InnoDB: Progress in percents: 1170624 14:04:14 InnoDB: Restoring buffer pool pages from ib_lru_dump
170624 14:04:14 InnoDB: Waiting for the background threads to start
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 100
InnoDB: Rolling back of trx id 31D9938764 completed
170624 14:04:14 InnoDB: Rollback of non-prepared transactions completed
170624 14:04:15 Percona XtraDB (http://
170624 14:04:15 [Note] Recovering after a crash using /data/mysql/
170624 14:04:15 [Note] Starting crash recovery...
170624 14:04:15 [Note] Crash recovery finished.
170624 14:04:15 [Warning] 'user' entry 'root@DB01' ignored in --skip-name-resolve mode.
170624 14:04:15 [Warning] 'user' entry '@DB01' ignored in --skip-name-resolve mode.
170624 14:04:15 [Warning] 'proxies_priv' entry '@ root@DB01' ignored in --skip-name-resolve mode.
170624 14:04:15 [Note] Event Scheduler: Loaded 0 events
170624 14:04:15 [Note] /opt/percona/
Version: '5.5.31-
and resolve_stack_dump shows as follows:
root@DB01:
0x7571f2 Log_event:
0x52715a Log_event:
0x74986a MYSQL_BIN_
0x74a8b2 MYSQL_BIN_
0x51a8c3 rotate_
0x653968 reload_
0x5879d9 dispatch_
0x588814 do_command(THD*) + 260
0x6271b5 do_handle_
0x6272d4 handle_
Upon checking the code, it looks to have occurred under this file:
http://
and during the period it crashed, I took a one-minute range to check for any DML queries that were replicated that time:
# mysqlbinlog --base64-
1 ### INSERT INTO `a`.`market_
1 ### INSERT INTO `s`.`abp_
1 ### UPDATE `percona`
3 ### INSERT INTO `a`.`selection_
3 ### INSERT INTO `y`.`user_session`
3 ### INSERT INTO `s`.`abp_
3 ### INSERT INTO `s`.`ag_
3 ### UPDATE `a`.`odds`
3 ### UPDATE `y`.`job_
4 ### UPDATE `y`.`announcement`
5 ### UPDATE `y`.`user`
7250 ### UPDATE `y`.`journal_
Memory before MySQL crash:
10:15:01 AM kbmemfree kbmemused %memused kbbuffers kbcached kbcommit %commit kbactive kbinact kbdirty
....
01:15:01 PM 1650500 526724636 99.69 306012 62871316 467705948 75.98 409845436 112454584 5736
01:25:01 PM 2058772 526316364 99.61 306012 62457104 467853676 76.01 409554528 112338372 5076
01:35:01 PM 1406864 526968272 99.73 306032 63104516 467860576 76.01 410075372 112466924 9556
01:45:01 PM 2048864 526326272 99.61 306212 62450576 467916124 76.02 409576072 112318012 10340
01:55:01 PM 1396248 526978888 99.74 306180 63102160 468068180 76.04 410222560 112330928 5312
02:05:01 PM 8499244 519875892 98.39 279684 50687740 468179884 76.06 479133812 36311128 12204]
MySQL version: # mysqld --version
mysqld Ver 5.5.31-rel30.3-log for Linux on x86_64 (Percona Server with XtraDB (GPL), Release rel30.3, Revision 520)
and disk is of
root@DB01:
NAME RM SIZE RO FSTYPE MOUNTPOINT MODEL
sdc 0 2.8T 0 PERC H700
└─sdc1 0 2.8T 0 xfs /data
OS info:
# lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 16.04.2 LTS
Release: 16.04
Codename: xenial
# uname -a
Linux DB01 4.4.0-79-generic #100-Ubuntu SMP Wed May 17 19:58:14 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
Any information regarding the cause of this bug and if this has been fixed from higher version of 5.5 is helpful to this case.
Thank you.
Thank you for the report.
Version 5.5.31 is old and many bugs were fixed since. Please consider to upgrade and inform us if crash still happens.
Please also check if you don't run LOAD DATA INFILE prior crash: stack trace look similar, although not completely same as https:/ /bugs.mysql. com/bug. php?id= 60929