Troubleshooting Corruption in InnoDB

Published by Ryan on

(apologies for the raw dump, keeping this for myself for posterity)

Error:

(intermittently) Warning: mysqli_connect(): (HY000/2002): No such file or directory in {} on line #

Suspicions:

– MySQL hitting a resource or connection limit
– MySQL has a configuration error
– Corrupt hardware/disk/partition/blocks
– MySQL has corrupt data

Checks:

`htop` : check to see if cpu/memory limits are not strained
`df -h` : check available capacity on primary disk
`sudo service mysql restart` : restart mysql service to see if issue persists
`sudo tail -f /var/log/mysql/error.log` :

InnoDB: Page may be an index page where index id is 167
2019-03-27T20:30:25.250383Z 0 [ERROR] [FATAL] InnoDB: Apparent corruption of an index page [page id: space=72, page number=4] to be written to data file. We intentionally crash the server to prevent corrupt data from ending up in data files.
2019-03-27 20:30:25 0x7f4d2b1f2700 InnoDB: Assertion failure in thread 139969412671232 in file ut0ut.cc line 942
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.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
20:30:25 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.

key_buffer_size=16777216
read_buffer_size=131072
max_used_connections=0
max_threads=151
thread_count=0
connection_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 76388 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 0x30000
/usr/sbin/mysqld(my_print_stacktrace+0x3b)[0xebeb7b]
/usr/sbin/mysqld(handle_fatal_signal+0x48b)[0x790f8b]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x12890)[0x7f4d4a997890]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xc7)[0x7f4d49c93e97]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x141)[0x7f4d49c95801]
/usr/sbin/mysqld[0x767714]
/usr/sbin/mysqld(_ZN2ib5fatalD1Ev+0x66)[0x1095c06]
/usr/sbin/mysqld(_Z31buf_dblwr_flush_buffered_writesv+0x8e3)[0x10dc773]
/usr/sbin/mysqld(_Z22buf_dblwr_add_to_batchP10buf_page_t+0x671)[0x10dcf21]
/usr/sbin/mysqld(_Z14buf_flush_pageP10buf_pool_tP10buf_page_t11buf_flush_tb+0x521)[0x10e93f1]
/usr/sbin/mysqld[0x10ea397]
/usr/sbin/mysqld(_Z18buf_flush_do_batchP10buf_pool_t11buf_flush_tmmPm+0x3dc)[0x10ead6c]
/usr/sbin/mysqld(_Z15buf_flush_listsmmPm+0xa2)[0x10ec282]
/usr/sbin/mysqld(buf_flush_page_cleaner_coordinator+0xfc3)[0x10ef4b3]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76db)[0x7f4d4a98c6db]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7f4d49d7688f]
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
2019-03-27T20:30:25.870673Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use –explicit_defaults_for_timestamp server option (see documentation for more details).
2019-03-27T20:30:25.872378Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.25-0ubuntu0.18.04.2) starting as process 7003 …
2019-03-27T20:30:25.876366Z 0 [Note] InnoDB: PUNCH HOLE support available
2019-03-27T20:30:25.876446Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-03-27T20:30:25.876509Z 0 [Note] InnoDB: Uses event mutexes
2019-03-27T20:30:25.876578Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2019-03-27T20:30:25.876632Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2019-03-27T20:30:25.876685Z 0 [Note] InnoDB: Using Linux native AIO
2019-03-27T20:30:25.876981Z 0 [Note] InnoDB: Number of pools: 1
2019-03-27T20:30:25.877145Z 0 [Note] InnoDB: Using CPU crc32 instructions
2019-03-27T20:30:25.880192Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2019-03-27T20:30:25.888173Z 0 [Note] InnoDB: Completed initialization of buffer pool
2019-03-27T20:30:25.890257Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2019-03-27T20:30:25.901966Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2019-03-27T20:30:25.903390Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 104108512
2019-03-27T20:30:25.913199Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 105011282
2019-03-27T20:30:25.913660Z 0 [Note] InnoDB: Database was not shutdown normally!
2019-03-27T20:30:25.913720Z 0 [Note] InnoDB: Starting crash recovery.
2019-03-27T20:30:25.925688Z 0 [Note] InnoDB: Starting an apply batch of log records to the database…
InnoDB: Progress in percent: 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
2019-03-27T20:30:25.933302Z 0 [Note] InnoDB: Apply batch completed
2019-03-27T20:30:26.037851Z 0 [Note] InnoDB: Removed temporary tablespace data file: “ibtmp1”
2019-03-27T20:30:26.038012Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2019-03-27T20:30:26.038136Z 0 [Note] InnoDB: Setting file ‘./ibtmp1’ size to 12 MB. Physically writing the file full; Please wait …
2019-03-27T20:30:26.086968Z 0 [Note] InnoDB: File ‘./ibtmp1’ size is now 12 MB.
2019-03-27T20:30:26.087710Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2019-03-27T20:30:26.087781Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2019-03-27T20:30:26.088063Z 0 [Note] InnoDB: Waiting for purge to start
2019-03-27T20:30:26.138300Z 0 [Note] InnoDB: 5.7.25 started; log sequence number 105011282
2019-03-27T20:30:26.138697Z 0 [Note] Plugin ‘FEDERATED’ is disabled.
2019-03-27T20:30:26.143303Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
2019-03-27T20:30:26.143401Z 0 [Note] Server hostname (bind-address): ‘*’; port: 3306
2019-03-27T20:30:26.143482Z 0 [Note] IPv6 is available.
2019-03-27T20:30:26.143548Z 0 [Note] – ‘::’ resolves to ‘::’;
2019-03-27T20:30:26.143622Z 0 [Note] Server socket created on IP: ‘::’.
2019-03-27T20:30:26.146112Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2019-03-27T20:30:26.146981Z 0 [Note] InnoDB: Buffer pool(s) load completed at 190327 20:30:26
2019-03-27T20:30:26.151598Z 0 [Note] Event Scheduler: Loaded 0 events
2019-03-27T20:30:26.151793Z 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: ‘5.7.25-0ubuntu0.18.04.2’ socket: ‘/var/run/mysqld/mysqld.sock’ port: 3306 (Ubuntu)
2019-03-27T20:30:27.891447Z 0 [ERROR] InnoDB: Record 13732 is above rec heap top 2018
2019-03-27T20:30:27.891649Z 0 [Note] InnoDB: Page dump in ascii and hex (16384 bytes):

Um whoops.

Most innodb data errors, we can fix.

`mysqlcheck -p{{password}} –all-databases` :
mysqlcheck: Got error: 2013: Lost connection to MySQL server during query when executing ‘CHECK TABLE … ‘

`mysqlcheck -p{{password}} –all-databases` :
royals.user_orders
Warning : InnoDB: The B-tree of index user_2 is corrupted.
Warning : InnoDB: The B-tree of index order is corrupted.
error : Corrupt

Performed steps:

Export table data,
Delete table
Recreate table and import data

No more logs blowing up!


Leave a Reply

Your email address will not be published. Required fields are marked *