MySQL crash during rotation of logs

[Paul Namuag]

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/percona-server-5.5-binaries/label_exp/centos5-64/Percona-Server-5.5.31-rel30.3/mysys/my_new.cc:52: int __cxa_pure_virtual(): Assertion `! "Aborted: pure virtual method called."' failed.
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://bugs.percona.com/

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=599
max_threads=1602
thread_count=225
connection_count=225
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 3513793 K bytes of memory
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/server/bin/mysqld(my_print_stacktrace+0x35)[0x7e3645]
/opt/percona/server/bin/mysqld(handle_fatal_signal+0x3f4)[0x69ea74]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7f0b0bf78390]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x38)[0x7f0b0aa99428]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7f0b0aa9b02a]
/lib/x86_64-linux-gnu/libc.so.6(+0x2dbd7)[0x7f0b0aa91bd7]
/lib/x86_64-linux-gnu/libc.so.6(+0x2dc82)[0x7f0b0aa91c82]
/opt/percona/server/bin/mysqld[0x7ebb53]
/opt/percona/server/bin/mysqld(_ZN9Log_event12write_headerEP11st_io_cachem+0x72)[0x7571f2]
/opt/percona/server/bin/mysqld(_ZN9Log_event5writeEP11st_io_cache+0x2a)[0x52715a]
/opt/percona/server/bin/mysqld(_ZN13MYSQL_BIN_LOG4openEPKc13enum_log_typeS1_10cache_typebmbb+0x27a)[0x74986a]
/opt/percona/server/bin/mysqld(_ZN13MYSQL_BIN_LOG13new_file_implEb+0x562)[0x74a8b2]
/opt/percona/server/bin/mysqld(_Z16rotate_relay_logP11Master_info+0x43)[0x51a8c3]
/opt/percona/server/bin/mysqld(_Z20reload_acl_and_cacheP3THDmP10TABLE_LISTPi+0x1e8)[0x653968]
/opt/percona/server/bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0xa79)[0x5879d9]
/opt/percona/server/bin/mysqld(_Z10do_commandP3THD+0x104)[0x588814]
/opt/percona/server/bin/mysqld(_Z24do_handle_one_connectionP3THD+0x105)[0x6271b5]
/opt/percona/server/bin/mysqld(handle_one_connection+0x54)[0x6272d4]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7f0b0bf6e6ba]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f0b0ab6a82d]

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://www.percona.com/software/percona-server/. You may find information
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/relay-bin/mysql-relay.000766
InnoDB: Last MySQL binlog file position 0 623115901, file name /data/mysql/log-bin/mysql-bin.000252
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://www.percona.com) 5.5.31-rel30.3 started; log sequence number 16677833682455
170624 14:04:15 [Note] Recovering after a crash using /data/mysql/log-bin/mysql-bin
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/server/bin/mysqld: ready for connections.
Version: '5.5.31-rel30.3-log' socket: '/data/mysql/data/mysql.sock' port: 3306 Percona Server with XtraDB (GPL), Release rel30.3, Revision 520

and resolve_stack_dump shows as follows:

root@DB01:/home/percona# resolve_stack_dump -s /tmp/mysqld.symbols -n /tmp/mysqld.stack | c++filt
0x7571f2 Log_event::write_header(st_io_cache*, unsigned long) + 114
0x52715a Log_event::write(st_io_cache*) + 42
0x74986a MYSQL_BIN_LOG::open(char const*, enum_log_type, char const*, cache_type, bool, unsigned long, bool, bool) + 634
0x74a8b2 MYSQL_BIN_LOG::new_file_impl(bool) + 1378
0x51a8c3 rotate_relay_log(Master_info*) + 67
0x653968 reload_acl_and_cache(THD*, unsigned long, TABLE_LIST*, int*) + 488
0x5879d9 dispatch_command(enum_server_command, THD*, char*, unsigned int) + 2681
0x588814 do_command(THD*) + 260
0x6271b5 do_handle_one_connection(THD*) + 261
0x6272d4 handle_one_connection + 84

Upon checking the code, it looks to have occurred under this file:
http://bazaar.launchpad.net/~percona-core/percona-server/5.5/view/head:/sql/log_event.cc at line 955

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-output=decode-rows -vvv mysql-bin.038544 --start-position=625957624 | head -900000 | sed -n '/\#170624 14\:00\:/,/\#170624 14\:01\:/p'|awk 'BEGIN{IGNORECASE = 1}/insert / || /update / || /delete / || /alter /;' | sort| uniq -c|sort -n|tail -30
      1 ### INSERT INTO `a`.`market_accumulator`
      1 ### INSERT INTO `s`.`abp_market_accumulator_id`
      1 ### UPDATE `percona`.`heartbeat`
      3 ### INSERT INTO `a`.`selection_accumulator`
      3 ### INSERT INTO `y`.`user_session`
      3 ### INSERT INTO `s`.`abp_selection_accumulator_id`
      3 ### INSERT INTO `s`.`ag_user_session_id`
      3 ### UPDATE `a`.`odds`
      3 ### UPDATE `y`.`job_transaction`
      4 ### UPDATE `y`.`announcement`
      5 ### UPDATE `y`.`user`
   7250 ### UPDATE `y`.`journal_staging`

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:/data/mysql/log-bin# lsblk -o "NAME,RM,SIZE,RO,FSTYPE,MOUNTPOINT,MODEL" /dev/sdc
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.

[Sveta Smirnova (svetasmirnova)]

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

[Shahriyar Rzayev (rzayev-sehriyar)]

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