Bug #1588564 “Server crashed and fails on each restart” : Bugs : Percona Server moved to https://jira.percona.com/projects/PS

Revision history for this message

monty solomon (monty+launchpad) wrote on 2016-06-02:

#1

Download full text (8.7 KiB)

InnoDB: Doing recovery: scanned up to log sequence number 1230221675932
InnoDB: Transaction 22213646579 was in the XA prepared state.
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 0 row operations to undo
InnoDB: Trx id counter is 22213646848
2016-06-02 22:02:34 20059 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 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 0 94361, file name bin.000357
InnoDB: Last MySQL binlog file position 0 1854245, file name bin.005516
2016-06-02 22:02:36 20059 [Note] InnoDB: 128 rollback segment(s) are active.
InnoDB: Starting in background the rollback of uncommitted transactions
2016-06-02 22:02:36 7f3fc8c86700 InnoDB: Rollback of non-prepared transactions completed
2016-06-02 22:02:36 20059 [Note] InnoDB: Waiting for purge to start
2016-06-02 22:02:36 20059 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.25-73.1 started; log sequence number 1230221675932
2016-06-02 22:02:36 7f3fdd568700 InnoDB: Loading buffer pool(s) from /opt/mysql/dbdata1/reference-p0//ib_buffer_pool
2016-06-02 22:02:36 20059 [Note] Recovering after a crash using /opt/mysql/dblogs1/reference-p0/bin/bin
2016-06-02 22:02:36 20059 [Note] Starting crash recovery...
2016-06-02 22:02:36 7f46251657e0 InnoDB: Starting recovery for XA transactions...
2016-06-02 22:02:36 7f46251657e0 InnoDB: Transaction 22213646579 in prepared state after recovery
2016-06-02 22:02:36 7f46251657e0 InnoDB: Transaction contains changes to 1 rows
2016-06-02 22:02:36 7f46251657e0 InnoDB: 1 transactions in prepared state after recovery
2016-06-02 22:02:36 20059 [Note] Found 1 prepared transaction(s) in InnoDB
2016-06-02 22:02:36 20059 [Note] Crash recovery finished.
2016-06-02 22:02:36 20059 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: b6f2d323-290d-11e6-9e8f-0ac4bf0ab353.
2016-06-02 22:02:36 20059 [Note] RSA private key file not found: /opt/mysql/dbdata1/reference-p0//private_key.pem. Some authentication plugins will not work.
2016-06-02 22:02:36 20059 [Note] RSA public key file not found: /opt/mysql/dbdata1/reference-p0//public_key.pem. Some authentication plugins will not work.
2016-06-02 22:02:36 20059 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
2016-06-02 22:02:36 20059 [Note] - '0.0.0.0' resolves to '0.0.0.0';
2016-06-02 22:02:36 20059 [Note] Server socket created on IP: '0.0.0.0'.
2016-06-02 22:02:36 20059 [ERROR] /usr/sbin/mysqld: Table './mysql/user' is marked as crashed and should be repaired
2016-06-02 22:02:36 20059 [Warning] Checking table: './mysql/user'
2016-06-02 22:02:36 20059 [ERROR] 1 client is using or hasn't closed the table properly
2016-06-02 22:02:36 20059 [ERROR] /usr/sbin/mysqld: Table './mysql/db' is marked as crashed and should be ...

InnoDB: Doing recovery: scanned up to log sequence number 1230221675932
InnoDB: Transaction 22213646579 was in the XA prepared state.
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 0 row operations to undo
InnoDB: Trx id counter is 22213646848
2016-06-02 22:02:34 20059 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 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 0 94361, file name bin.000357
InnoDB: Last MySQL binlog file position 0 1854245, file name bin.005516
2016-06-02 22:02:36 20059 [Note] InnoDB: 128 rollback segment(s) are active.
InnoDB: Starting in background the rollback of uncommitted transactions
2016-06-02 22:02:36 7f3fc8c86700  InnoDB: Rollback of non-prepared transactions completed
2016-06-02 22:02:36 20059 [Note] InnoDB: Waiting for purge to start
2016-06-02 22:02:36 20059 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.25-73.1 started; log sequence number 1230221675932
2016-06-02 22:02:36 7f3fdd568700 InnoDB: Loading buffer pool(s) from /opt/mysql/dbdata1/reference-p0//ib_buffer_pool
2016-06-02 22:02:36 20059 [Note] Recovering after a crash using /opt/mysql/dblogs1/reference-p0/bin/bin
2016-06-02 22:02:36 20059 [Note] Starting crash recovery...
2016-06-02 22:02:36 7f46251657e0  InnoDB: Starting recovery for XA transactions...
2016-06-02 22:02:36 7f46251657e0  InnoDB: Transaction 22213646579 in prepared state after recovery
2016-06-02 22:02:36 7f46251657e0  InnoDB: Transaction contains changes to 1 rows
2016-06-02 22:02:36 7f46251657e0  InnoDB: 1 transactions in prepared state after recovery
2016-06-02 22:02:36 20059 [Note] Found 1 prepared transaction(s) in InnoDB
2016-06-02 22:02:36 20059 [Note] Crash recovery finished.
2016-06-02 22:02:36 20059 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: b6f2d323-290d-11e6-9e8f-0ac4bf0ab353.
2016-06-02 22:02:36 20059 [Note] RSA private key file not found: /opt/mysql/dbdata1/reference-p0//private_key.pem. Some authentication plugins will not work.
2016-06-02 22:02:36 20059 [Note] RSA public key file not found: /opt/mysql/dbdata1/reference-p0//public_key.pem. Some authentication plugins will not work.
2016-06-02 22:02:36 20059 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
2016-06-02 22:02:36 20059 [Note]   - '0.0.0.0' resolves to '0.0.0.0';
2016-06-02 22:02:36 20059 [Note] Server socket created on IP: '0.0.0.0'.
2016-06-02 22:02:36 20059 [ERROR] /usr/sbin/mysqld: Table './mysql/user' is marked as crashed and should be repaired
2016-06-02 22:02:36 20059 [Warning] Checking table:   './mysql/user'
2016-06-02 22:02:36 20059 [ERROR] 1 client is using or hasn't closed the table properly
2016-06-02 22:02:36 20059 [ERROR] /usr/sbin/mysqld: Table './mysql/db' is marked as crashed and should be repaired
2016-06-02 22:02:36 20059 [Warning] Checking table:   './mysql/db'
2016-06-02 22:02:36 20059 [ERROR] 1 client is using or hasn't closed the table properly
2016-06-02 22:02:36 20059 [ERROR] /usr/sbin/mysqld: Table './mysql/time_zone_name' is marked as crashed and should be repaired
2016-06-02 22:02:36 20059 [Warning] Checking table:   './mysql/time_zone_name'
2016-06-02 22:02:36 20059 [ERROR] 1 client is using or hasn't closed the table properly
2016-06-02 22:02:36 20059 [ERROR] /usr/sbin/mysqld: Table './mysql/time_zone' is marked as crashed and should be repaired
2016-06-02 22:02:36 20059 [Warning] Checking table:   './mysql/time_zone'
2016-06-02 22:02:36 20059 [ERROR] 1 client is using or hasn't closed the table properly
2016-06-02 22:02:36 20059 [Note] Event Scheduler: Loaded 0 events
2016-06-02 22:02:36 20059 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.25-73.1-log'  socket: '/opt/mysql/dbprod/reference-p0.sock'  port: 3306  Percona Server (GPL), Release 73.1, Revision 07b797f
2016-06-02 22:02:37 20059 [ERROR] /usr/sbin/mysqld: Table './heartbeat/heartbeat' is marked as crashed and should be repaired
2016-06-02 22:02:37 20059 [Warning] Checking table:   './heartbeat/heartbeat'
2016-06-02 22:02:46 20059 [Note] Start binlog_dump to master_thread_id(281) slave_server(1416274460), pos(, 4)
2016-06-02 22:02:46 20059 [Note] Start binlog_dump to master_thread_id(282) slave_server(36114240), pos(, 4)
2016-06-02 22:02:46 20059 [Note] Start binlog_dump to master_thread_id(284) slave_server(786552237), pos(, 4)
2016-06-02 22:02:46 20059 [Note] Start binlog_dump to master_thread_id(287) slave_server(1519166138), pos(, 4)
2016-06-02 22:02:46 20059 [Note] Start binlog_dump to master_thread_id(283) slave_server(180369484), pos(, 4)
2016-06-02 22:02:46 20059 [Note] Start binlog_dump to master_thread_id(285) slave_server(1934835896), pos(, 4)
2016-06-02 22:02:46 20059 [Note] Start binlog_dump to master_thread_id(286) slave_server(69722903), pos(, 4)
2016-06-02 22:02:46 20059 [Note] Start binlog_dump to master_thread_id(288) slave_server(2540989931), pos(, 4)
2016-06-02 22:02:46 20059 [Note] Start binlog_dump to master_thread_id(289) slave_server(2474101931), pos(, 4)
2016-06-02 22:05:11 20059 [Note] While initializing dump thread for slave with UUID <a5275eba-cf68-11e5-9600-12f8a960e07d>, found a zombie dump thread with the same UUID. Master is killing the zombie dump thread(284).
2016-06-02 22:05:11 20059 [Warning] Aborted connection 284 to db: 'unconnected' user: 'SUSR_Repl' host: '172.16.47.157' (Got an error writing communication packets)
2016-06-02 22:05:11 20059 [Note] Start binlog_dump to master_thread_id(1838) slave_server(786552237), pos(, 4)
2016-06-02 22:05:47 20059 [Note] Start binlog_dump to master_thread_id(2208) slave_server(3376456826), pos(, 4)
2016-06-02 22:06:25 20059 [Note] While initializing dump thread for slave with UUID <f56d61ae-1185-11e6-8520-0af0d65f27ab>, found a zombie dump thread with the same UUID. Master is killing the zombie dump thread(282).
2016-06-02 22:06:25 20059 [Note] Start binlog_dump to master_thread_id(2606) slave_server(36114240), pos(, 4)
2016-06-02 22:06:42 20059 [Note] Start binlog_dump to master_thread_id(2769) slave_server(69722903), pos(, 4)
2016-06-02 22:10:52 7f3fded6b700  InnoDB: Assertion failure in thread 139912298280704 in file fsp0fsp.cc line 1509
InnoDB: Failing assertion: frag_n_used > 0
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
22:10:52 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=67108864
read_buffer_size=1048576
max_used_connections=304
max_threads=1802
thread_count=292
connection_count=292
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2396986 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

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...
stack_bottom = 0 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0x8cea7c]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x655fa1]
/lib64/libpthread.so.0[0x34c8e0f7e0]
/lib64/libc.so.6(gsignal+0x35)[0x34c8a32625]
/lib64/libc.so.6(abort+0x175)[0x34c8a33e05]
/usr/sbin/mysqld[0xa6db01]
/usr/sbin/mysqld[0xa750be]
/usr/sbin/mysqld[0x9bd847]
/usr/sbin/mysqld[0x9bee88]
/usr/sbin/mysqld[0x9b00cb]
/lib64/libpthread.so.0[0x34c8e07aa1]
/lib64/libc.so.6(clone+0x6d)[0x34c8ae893d]
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.
160602 22:10:53 mysqld_safe Number of processes running now: 0
160602 22:10:53 mysqld_safe mysqld restarted

Revision history for this message

monty solomon (monty+launchpad) wrote on 2016-06-02:

#2

Then it repeatedly fails with that assertion and restarts.

mysql Ver 14.14 Distrib 5.6.25-73.1, for Linux (x86_64) using 6.0
Server version: 5.6.25-73.1-log Percona Server (GPL), Release 73.1, Revision 07b797f

CentOS release 6.7 (Final)
Linux fragrant-band 3.18.26-83.el6.x86_64 #1 SMP Mon Jan 25 18:39:22 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

Revision history for this message

monty solomon (monty+launchpad) wrote on 2016-10-17:

#3

The bug status is still Undecided. Has this bug been triaged?

Revision history for this message

monty solomon (monty+launchpad) wrote on 2016-12-13:

#4

The bug status is still New/Undecided. Has this bug been triaged?

Revision history for this message

Shahriyar Rzayev (rzayev-sehriyar) wrote on 2018-01-25:

#5

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

Percona Server moved to https://jira.percona.com/projects/PS

Server crashed and fails on each restart

Bug Description

Other bug subscribers

Remote bug watches