Not the answer you need?
Register and ask your own question!

Database crashes when binary logging not possible

RedithionRedithion EntrantCurrent User Role Beginner
Hi everyone,
We have been experiencing this issue at least once a day for the last 5 days:
2017-04-18T00:11:49.499793Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 11624ms. The settings might not be optimal. (flushed=200, during the time.)
2017-04-18T00:11:49.649596Z 14 [ERROR] /usr/sbin/mysqld: Binary logging not possible. Message: An error occurred during flush stage of the commit. 'binlog_error_action' is set to 'ABORT_SERVER'. Hence aborting the server.
00:11:49 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.
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=8388608
read_buffer_size=131072
max_used_connections=189
max_threads=215
thread_count=101
connection_count=101
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 93386 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7f04ff816000
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 = 7f0da45dce00 thread_stack 0x30000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0xec707c]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x79d941]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10330)[0x7f0dadae3330]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7f0dacf24c37]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7f0dacf28028]
/usr/sbin/mysqld[0x761bc0]
/usr/sbin/mysqld(_ZN13MYSQL_BIN_LOG33handle_binlog_flush_or_sync_errorEP3THDb+0x19b)[0xe5d1ab]
/usr/sbin/mysqld(_ZN13MYSQL_BIN_LOG14ordered_commitEP3THDbb+0x131)[0xe65691]
/usr/sbin/mysqld(_ZN13MYSQL_BIN_LOG6commitEP3THDb+0xcb3)[0xe676e3]
/usr/sbin/mysqld(_Z15ha_commit_transP3THDbb+0x131)[0x7fd571]
/usr/sbin/mysqld(_Z12trans_commitP3THD+0x39)[0xd51cd9]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THDb+0xc92)[0xca4f12]
/usr/sbin/mysqld(_Z11mysql_parseP3THDP12Parser_state+0x5c5)[0xcaba75]
/usr/sbin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0x92f)[0xcac42f]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x1b7)[0xcaddc7]
/usr/sbin/mysqld(handle_connection+0x2a0)[0xd6f8c0]
/usr/sbin/mysqld(pfs_spawn_thread+0x1b4)[0x1246fc4]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8184)[0x7f0dadadb184]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f0dacfe837d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f04ff828030): COMMIT
Connection ID (thread ID): 14
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.
2017-04-18T00:11:51.272796Z mysqld_safe Number of processes running now: 0
2017-04-18T00:11:51.274351Z mysqld_safe mysqld restarted
2017-04-18T00:11:51.296136Z 0 [Warning] Changed limits: max_open_files: 1024 (requested 5000)
2017-04-18T00:11:51.296265Z 0 [Warning] Changed limits: max_connections: 214 (requested 300)
2017-04-18T00:11:51.296278Z 0 [Warning] Changed limits: table_open_cache: 400 (requested 2000)
2017-04-18T00:11:51.443192Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2017-04-18T00:11:51.444043Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.14-7-log) starting as process 8607 ...
2017-04-18T00:11:51.454822Z 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.
2017-04-18T00:11:51.454848Z 0 [Warning] InnoDB: Using innodb_file_format is deprecated and the parameter may be removed in future releases. See http://dev.mysql.com/doc/refman/5.7/en/innodb-file-format.html
2017-04-18T00:11:51.454912Z 0 [Note] InnoDB: PUNCH HOLE support available
2017-04-18T00:11:51.454921Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-04-18T00:11:51.454925Z 0 [Note] InnoDB: Uses event mutexes
2017-04-18T00:11:51.454929Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2017-04-18T00:11:51.454933Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.8
2017-04-18T00:11:51.454937Z 0 [Note] InnoDB: Using Linux native AIO
2017-04-18T00:11:51.455688Z 0 [Note] InnoDB: Number of pools: 1
2017-04-18T00:11:51.455770Z 0 [Note] InnoDB: Using CPU crc32 instructions
2017-04-18T00:11:51.456478Z 0 [Note] InnoDB: Initializing buffer pool, total size = 32G, instances = 8, chunk size = 128M
2017-04-18T00:11:52.181194Z 0 [Note] InnoDB: Completed initialization of buffer pool
2017-04-18T00:11:52.312596Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2017-04-18T00:11:52.324805Z 0 [Note] InnoDB: Recovering partial pages from the parallel doublewrite buffer at /var/lib/mysql/xb_doublewrite
2017-04-18T00:11:52.405692Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2017-04-18T00:11:52.542600Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 303947279741
2017-04-18T00:11:52.613070Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 303952522240
2017-04-18T00:11:52.681503Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 303957765120
2017-04-18T00:11:52.841734Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 303948327936
2017-04-18T00:11:52.919589Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 303953570816
2017-04-18T00:11:53.005760Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 303958813696
2017-04-18T00:11:53.082855Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 303964056576
2017-04-18T00:11:53.086403Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 303964205271
2017-04-18T00:11:53.086696Z 0 [Note] InnoDB: Database was not shutdown normally!
2017-04-18T00:11:53.086701Z 0 [Note] InnoDB: Starting crash recovery.
2017-04-18T00:11:53.338831Z 0 [Note] InnoDB: Created parallel doublewrite buffer at /var/lib/mysql/xb_doublewrite, size 31457280 bytes
2017-04-18T00:11:53.427281Z 0 [Note] InnoDB: Transaction 432564072 was in the XA prepared state.
2017-04-18T00:11:53.428568Z 0 [Note] InnoDB: Transaction 432564072 was in the XA prepared state.
2017-04-18T00:11:53.428713Z 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 0 row operations to undo
2017-04-18T00:11:53.428726Z 0 [Note] InnoDB: Trx id counter is 432564480
2017-04-18T00:11:53.428740Z 0 [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

I have no idea why this happens or how to solve it. Any help will be appreciated.

Comments

  • RedithionRedithion Entrant Current User Role Beginner
    Second part of the log:
    2017-04-18T00:11:56.021088Z 0 [Note] InnoDB: Apply batch completed
    2017-04-18T00:11:56.021123Z 0 [Note] InnoDB: Last MySQL binlog file position 0 10427836, file name mysql-bin.003364
    2017-04-18T00:11:56.033238Z 0 [Note] InnoDB: Starting in background the rollback of uncommitted transactions
    2017-04-18T00:11:56.033285Z 0 [Note] InnoDB: Rollback of non-prepared transactions completed
    2017-04-18T00:11:56.036654Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
    2017-04-18T00:11:56.036671Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
    2017-04-18T00:11:56.036710Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
    2017-04-18T00:11:56.128396Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
    2017-04-18T00:11:56.130448Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
    2017-04-18T00:11:56.130468Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
    2017-04-18T00:11:56.132208Z 0 [Note] InnoDB: Waiting for purge to start
    2017-04-18T00:11:56.182406Z 0 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.7.14-7 started; log sequence number 303964205271
    2017-04-18T00:11:56.182859Z 0 [Note] Plugin 'FEDERATED' is disabled.
    2017-04-18T00:11:56.183094Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
    2017-04-18T00:11:56.185823Z 0 [Note] InnoDB: Buffer pool(s) load completed at 170417 20:11:56
    2017-04-18T00:11:56.196894Z 0 [Note] Recovering after a crash using /var/log/mysql/mysql-bin
    2017-04-18T00:11:56.255840Z 0 [Note] Starting crash recovery...
    2017-04-18T00:11:56.256301Z 0 [Note] InnoDB: Starting recovery for XA transactions...
    2017-04-18T00:11:56.256433Z 0 [Note] InnoDB: Transaction 432564072 in prepared state after recovery
    2017-04-18T00:11:56.256457Z 0 [Note] InnoDB: Transaction contains changes to 2 rows
    2017-04-18T00:11:56.256468Z 0 [Note] InnoDB: 1 transactions in prepared state after recovery
    2017-04-18T00:11:56.256477Z 0 [Note] Found 1 prepared transaction(s) in InnoDB
    2017-04-18T00:11:56.256557Z 0 [Note] Crash recovery finished.
    2017-04-18T00:11:56.327980Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them.
    2017-04-18T00:11:56.328044Z 0 [Note] Skipping generation of SSL certificates as certificate files are present in data directory.
    2017-04-18T00:11:56.344903Z 0 [Warning] CA certificate ca.pem is self signed.
    2017-04-18T00:11:56.344971Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory.
    2017-04-18T00:11:56.345121Z 0 [Note] Server hostname (bind-address): '*'; port: 3306
    2017-04-18T00:11:56.345163Z 0 [Note] IPv6 is available.
    2017-04-18T00:11:56.345183Z 0 [Note]   - '::' resolves to '::';
    2017-04-18T00:11:56.345211Z 0 [Note] Server socket created on IP: '::'.
    2017-04-18T00:11:56.372062Z 0 [Note] Event Scheduler: Loaded 0 events
    2017-04-18T00:11:56.372211Z 0 [Note] /usr/sbin/mysqld: ready for connections.
    Version: '5.7.14-7-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  Percona Server (GPL), Release '7', Revision '083e298'
    
Sign In or Register to comment.

MySQL, InnoDB, MariaDB and MongoDB are trademarks of their respective owners.
Copyright ©2005 - 2020 Percona LLC. All rights reserved.