[MDEV-11192] Error "Checsum failure while reading node partition in file" makes server crashes Created: 2016-10-31  Updated: 2016-11-30  Resolved: 2016-11-30

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.0.27
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Jan Hejl Assignee: Jan Lindström (Inactive)
Resolution: Not a Bug Votes: 0
Labels: tokudb
Environment:

Gentoo linux - 4.4.8-hardened-r1 with PAX enabled
Supermicro machine with:

  • two AMD Opteron(TM) Processor 6274, 64GB memory (approx. 40GB used regurarly)
  • 4x 512GB SSD drives (different vendors) -> Linux MDRAID RAID5 -> LVM for /var/lib/mysql
    emerge info and my.cnf attached

Attachments: File 20160711-mysqld.err     File 201611071723-mysql.err     File 201611110203-innodb-mysqld.err     File 20161118-mysqld.err     Text File core-gdb-201611071338.txt     Text File core-gdb-201611071723.txt     Text File core-gdb-full-201611071338.txt     Text File core-gdb-full-201611071338.txt     Text File core-gdb-full-201611071723.txt     File crash.log     File emerge.info     File my.cnf     File scanner.sql    

 Description   

After replacing SSD drives laying under the the RAID+LVM (256GB drives to larger 512GB drives) and extending the LVM logical volume, server started crashing with:

Checksum failure while reading node partition in file ... error on different TokuDB files (example crash.log attached) - most of the time it's main files, sometime index
Table structure attached. Crash can be reproduced easily by reading the whole table (or identify the failing part of the data range and read its data).

The only solution was to drop index/table - in case of table it hurt because it contained 10M-100M lines of data.
What helps was to split large tables into partitions, smaller ones are not crashing anymore, but the the ones containing 30M+ lines per partition still crashes from time to time.

My question is if it's related to storage layer or tokudb/mariadb?

 Comments   
Comment by Elena Stepanova [ 2016-11-03 ]

Can you build a debug binary, produce a coredump and get a stack trace?

Comment by Jan Hejl [ 2016-11-03 ]

Built with debug flag, core and strack-trace set.
Unfortunatelly test core dump was 42GB large.

I'll put a trace next time it happens.

Comment by Elena Stepanova [ 2016-11-03 ]

Can you run 

gdb --batch --eval-command="thread apply all bt" <binary> <coredump>
 
gdb --batch --eval-command="thread apply all full bt" <binary> <coredump>

(and redirect them to files)? Each will produce a text file of a reasonable size, which you would be able to attach either as is, or compressed.

Comment by Jan Hejl [ 2016-11-07 ]

Attached - 20160711-mysqld.err core-gdb-201611071338.txt core-gdb-full-201611071338.txt

Comment by Jan Hejl [ 2016-11-07 ]

Another one - 201611071723-mysql.err core-gdb-201611071723.txt core-gdb-full-201611071723.txt
Reuploaded core-gdb-full-201611071338.txt - second command should be:

gdb --batch --eval-command="thread apply all bt full" <binary> <coredump>

Right?

Comment by Jan Hejl [ 2016-11-09 ]

Anything more I can provide?
It's happening more often since I reported this issues, even after upgrading to 10.0.28.

Comment by Jan Hejl [ 2016-11-11 ]

I switched one of the databases to the InnoDB engine and it happened too, output is little bit different. mysqld.err 201611110203-innodb-mysqld.err attached, unfortunatelly core file was overwritten by another accident that happened to the TokuDB engine. Maybe this helps.

I forgot to mention that it runs under the Xen dom0 and on the EXT4 partition mounted to the /var/lib/mysql

fscheck is planned on this night.

Comment by Elena Stepanova [ 2016-11-12 ]

This last one is certainly different, it's not even a TokuDB crash, but InnoDB. As it looks from the partial log, there was a crash before, and InnoDB failed to recover afterwards due to alleged data corruption. It could be a genuine disk problem, or InnoDB bug, but given repeated TokuDB checksum errors, disk issues start looking more likely.

What did you do to fix the problem? I see that you were able to start it a few minutes later.

Maybe jplindst can take a look at this last InnoDB issue, he might have an insight on what can be the root cause of the problem.

From 201611110203-innodb-mysqld.err

 
2016-11-11 02:03:25.950413500 InnoDB: Database page corruption on disk or a failed
 
2016-11-11 02:03:25.950417500 InnoDB: file read of page 4924.
 
2016-11-11 02:03:25.950422500 InnoDB: You may have to recover from a backup.
 
2016-11-11 02:03:25.955066500 2016-11-11 02:03:25 66932de08700 InnoDB: Page dump in ascii and hex (16384 bytes):
 
2016-11-11 02:03:25.955087500  len 16384; hex 6527cd3c0000133 ... long string deleted ...
 
2016-11-11 02:03:26.058479500 InnoDB: End of page dump
 
2016-11-11 02:03:26.058496500 2016-11-11 02:03:26 66932de08700 InnoDB: uncompressed page, stored checksum in field1 1697107260, calculated checksums for field1: crc32 4124020344, innodb 2977065308, none 3735928559, stored checksum in field2 2196862977, calculated checksums for field2: crc32 4124020344, innodb 2196862977, none 3735928559, page LSN 12 2458776873, low 4 bytes of LSN at page end 2458776873, page number (if stored to page already) 4924, space id (if created with >= MySQL-4.1.1 and stored already) 863
 
2016-11-11 02:03:26.060628500 InnoDB: Page may be an index page where index id is 5017
 
2016-11-11 02:03:26.060645500 InnoDB: (index "PRIMARY" of table "centrum+sk2015"."scanner" /* Partition "p1479343025" */)
 
2016-11-11 02:03:26.061152500 InnoDB: Database page corruption on disk or a failed
 
2016-11-11 02:03:26.061155500 InnoDB: file read of page 4924.
 
2016-11-11 02:03:26.061157500 InnoDB: You may have to recover from a backup.
 
2016-11-11 02:03:26.061159500 InnoDB: It is also possible that your operating
 
2016-11-11 02:03:26.061162500 InnoDB: system has corrupted its own file cache
 
2016-11-11 02:03:26.061164500 InnoDB: and rebooting your computer removes the
 
2016-11-11 02:03:26.061166500 InnoDB: error.
 
2016-11-11 02:03:26.061168500 InnoDB: If the corrupt page is an index page
 
2016-11-11 02:03:26.061175500 InnoDB: you can also try to fix the corruption
 
2016-11-11 02:03:26.061177500 InnoDB: by dumping, dropping, and reimporting
 
2016-11-11 02:03:26.061179500 InnoDB: the corrupt table. You can use CHECK
 
2016-11-11 02:03:26.061181500 InnoDB: TABLE to scan your table for corruption.
 
2016-11-11 02:03:26.061183500 InnoDB: See also http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
 
2016-11-11 02:03:26.061186500 InnoDB: about forcing recovery.
 
2016-11-11 02:03:26.061207500 2016-11-11 02:03:26 66932de08700  InnoDB: Assertion failure in thread 112782315915008 in file buf0lru.cc line 2326
 
2016-11-11 02:03:26.061210500 InnoDB: Failing assertion: bpage->buf_fix_count == 0
 
2016-11-11 02:03:26.061212500 InnoDB: We intentionally generate a memory trap.
 
2016-11-11 02:03:26.061215500 InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
 
2016-11-11 02:03:26.061217500 InnoDB: If you get repeated assertion failures or crashes, even
 
2016-11-11 02:03:26.061219500 InnoDB: immediately after the mysqld startup, there may be
 
2016-11-11 02:03:26.061226500 InnoDB: corruption in the InnoDB tablespace. Please refer to
 
2016-11-11 02:03:26.061228500 InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
 
2016-11-11 02:03:26.061231500 InnoDB: about forcing recovery.
 
2016-11-11 02:03:26.061247500 161111  2:03:26 [ERROR] mysqld got signal 6 ;
 
2016-11-11 02:03:26.061250500 This could be because you hit a bug. It is also possible that this binary
 
2016-11-11 02:03:26.061252500 or one of the libraries it was linked against is corrupt, improperly built,
 
2016-11-11 02:03:26.061254500 or misconfigured. This error can also be caused by malfunctioning hardware.
 
2016-11-11 02:03:26.061257500 
2016-11-11 02:03:26.061258500 To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
2016-11-11 02:03:26.061261500 
2016-11-11 02:03:26.061267500 We will try our best to scrape up some info that will hopefully help
 
2016-11-11 02:03:26.061269500 diagnose the problem, but since we have already crashed, 
2016-11-11 02:03:26.061272500 something is definitely wrong and this may fail.
 
2016-11-11 02:03:26.061274500 
2016-11-11 02:03:26.061276500 Server version: 10.0.28-MariaDB
 
2016-11-11 02:03:26.061278500 key_buffer_size=67108864
 
2016-11-11 02:03:26.061294500 read_buffer_size=262144
 
2016-11-11 02:03:26.061296500 max_used_connections=675
 
2016-11-11 02:03:26.061298500 max_threads=802
 
2016-11-11 02:03:26.061300500 thread_count=405
 
2016-11-11 02:03:26.061302500 It is possible that mysqld could use up to 
2016-11-11 02:03:26.061304500 key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 697348 K  bytes of memory
 
2016-11-11 02:03:26.061307500 Hope that's ok; if not, decrease some variables in the equation.
 
2016-11-11 02:03:26.061309500 
2016-11-11 02:03:26.061311500 Thread pointer: 0x0x0
 
2016-11-11 02:03:26.061317500 Attempting backtrace. You can use the following information to find out
 
2016-11-11 02:03:26.061319500 where mysqld died. If you see no messages after this, something went
 
2016-11-11 02:03:26.061322500 terribly wrong...
 
2016-11-11 02:03:26.068836500 stack_bottom = 0x0 thread_stack 0x48000
 
2016-11-11 02:04:02.135225500 /usr/sbin/mysqld(my_print_stacktrace+0x49)[0xbf2f52adc59]
 
2016-11-11 02:04:02.135466500 /usr/sbin/mysqld(handle_fatal_signal+0x2b3)[0xbf2f4e03833]
 
2016-11-11 02:04:02.135525500 /lib64/libpthread.so.0(+0x114e0)[0x6693f22b24e0]
 
2016-11-11 02:04:02.135609500 /lib64/libc.so.6(gsignal+0x3b)[0x6693f0fb4edb]
 
2016-11-11 02:04:02.135685500 /lib64/libc.so.6(abort+0x180)[0x6693f0fb6430]
 
2016-11-11 02:04:02.135909500 /usr/sbin/mysqld(+0x8f343b)[0xbf2f51a343b]
 
2016-11-11 02:04:02.136132500 /usr/sbin/mysqld(+0x8f4857)[0xbf2f51a4857]
 
2016-11-11 02:04:02.136353500 /usr/sbin/mysqld(+0x8e2ff1)[0xbf2f5192ff1]
 
2016-11-11 02:04:02.136574500 /usr/sbin/mysqld(+0x92e930)[0xbf2f51de930]
 
2016-11-11 02:04:02.136795500 /usr/sbin/mysqld(+0x87e96a)[0xbf2f512e96a]
 
2016-11-11 02:04:02.136846500 /lib64/libpthread.so.0(+0x75f4)[0x6693f22a85f4]
 
2016-11-11 02:04:02.136927500 /lib64/libc.so.6(clone+0x6d)[0x6693f107487d]
 
2016-11-11 02:04:02.136930500 The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
 
2016-11-11 02:04:02.136933500 information that should help you find out what is causing the crash.
 
2016-11-11 02:04:02.136950500 Writing a core file
 
2016-11-11 02:11:13.351322500 161111  2:11:13 [Note] /usr/sbin/mysqld (mysqld 10.0.28-MariaDB) starting as process 20707 ...
 
2016-11-11 02:11:13.792093500 161111  2:11:13 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
2016-11-11 02:11:13.792098500 161111  2:11:13 [Note] InnoDB: The InnoDB memory heap is disabled
 
2016-11-11 02:11:13.792100500 161111  2:11:13 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2016-11-11 02:11:13.792146500 161111  2:11:13 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
 
2016-11-11 02:11:13.792149500 161111  2:11:13 [Note] InnoDB: Compressed tables use zlib 1.2.8
 
2016-11-11 02:11:13.792151500 161111  2:11:13 [Note] InnoDB: Using Linux native AIO
 
2016-11-11 02:11:13.794989500 161111  2:11:13 [Note] InnoDB: Using CPU crc32 instructions
 
2016-11-11 02:11:13.798846500 161111  2:11:13 [Note] InnoDB: Initializing buffer pool, size = 256.0M
 
2016-11-11 02:11:13.833649500 161111  2:11:13 [Note] InnoDB: Completed initialization of buffer pool
 
2016-11-11 02:11:18.515585500 161111  2:11:18 [Note] InnoDB: Highest supported file format is Barracuda.
 
2016-11-11 02:11:18.520189500 161111  2:11:18 [Note] InnoDB: The log sequence numbers 597081819 and 597081819 in ibdata files do not match the log sequence number 56230177548 in the ib_logfiles!
 
2016-11-11 02:11:18.520193500 161111  2:11:18 [Note] InnoDB: Database was not shutdown normally!
 
2016-11-11 02:11:18.520221500 161111  2:11:18 [Note] InnoDB: Starting crash recovery.
 
2016-11-11 02:11:18.520224500 161111  2:11:18 [Note] InnoDB: Reading tablespace information from the .ibd files...
 
2016-11-11 02:11:19.106315500 161111  2:11:19 [Note] InnoDB: Restoring possible half-written data pages 
2016-11-11 02:11:19.106320500 161111  2:11:19 [Note] InnoDB: from the doublewrite buffer...
 
2016-11-11 02:11:19.221836500 InnoDB: Last MySQL binlog file position 0 27575495, file name ./mysqld-bin.015042
 
2016-11-11 02:11:19.326581500 161111  2:11:19 [Note] InnoDB: 128 rollback segment(s) are active.
 
2016-11-11 02:11:19.328845500 161111  2:11:19 [Note] InnoDB: Waiting for purge to start
 
2016-11-11 02:11:19.379351500 161111  2:11:19 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.32-79.0 started; log sequence number 56230177548
 
2016-11-11 02:11:19.741493500 Fri Nov 11 02:11:19 2016 PerconaFT recovery starting in env /var/lib/mysql/
 
2016-11-11 02:11:19.939558500 Fri Nov 11 02:11:19 2016 PerconaFT recovery scanning backward from 61683595193
 
2016-11-11 02:11:20.128459500 Fri Nov 11 02:11:20 2016 PerconaFT recovery bw_begin_checkpoint at 61683582965 timestamp 1478826089859864 (bw_newer)
 
2016-11-11 02:11:20.141073500 Fri Nov 11 02:11:20 2016 PerconaFT recovery bw_end_checkpoint at 61683582010 timestamp 1478826087008497 xid 61683553026 (bw_newer)
 
2016-11-11 02:11:20.738518500 Fri Nov 11 02:11:20 2016 PerconaFT recovery bw_begin_checkpoint at 61683553026 timestamp 1478826016180110 (bw_between)
 
2016-11-11 02:11:20.738522500 Fri Nov 11 02:11:20 2016 PerconaFT recovery turning around at begin checkpoint 61683553026 time 70828387
 
2016-11-11 02:11:20.738562500 Fri Nov 11 02:11:20 2016 PerconaFT recovery starts scanning forward to 61683595193 from 61683553026 left 42167 (fw_between)
 
2016-11-11 02:11:35.769589500 Fri Nov 11 02:11:35 2016 PerconaFT recovery scanning forward to 61683595193 at 61683567026 left 28167 (fw_between)
 
2016-11-11 02:11:51.431803500 Fri Nov 11 02:11:51 2016 PerconaFT recovery scanning forward to 61683595193 at 61683582026 left 13167 (fw_newer)
 
2016-11-11 02:11:52.863123500 Fri Nov 11 02:11:52 2016 PerconaFT recovery closing 11975 dictionaries
 
2016-11-11 02:15:11.460163500 Fri Nov 11 02:15:11 2016 PerconaFT recovery making a checkpoint
 
2016-11-11 02:15:11.549076500 Fri Nov 11 02:15:11 2016 PerconaFT recovery done
 
2016-11-11 02:15:11.596737500 161111  2:15:11 [Note] Recovering after a crash using mysqld-bin
 
2016-11-11 02:15:11.669685500 161111  2:15:11 [Note] Starting crash recovery...
 
2016-11-11 02:15:11.669827500 161111  2:15:11 [Note] Crash recovery finished.
 
2016-11-11 02:15:11.792412500 161111  2:15:11 [Note] Server socket created on IP: '::'.
 
2016-11-11 02:15:11.844309500 161111  2:15:11 [Note] /usr/sbin/mysqld: ready for connections.
 
2016-11-11 02:15:11.844313500 Version: '10.0.28-MariaDB'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  Source distribution

Comment by Jan Hejl [ 2016-11-15 ]

Nothing. MySQL recovered itself without intervention.
Few days later MySQL wasn't able to recover from InnoDB error, the only was to set innodb_force_recovery = 1 and dump the DB contents.

Because there's another instance of mariadb i use has the datadir on the XFS filesystem, i switched this instance to XFS too - dumped from EXT4 and restored to XFS. So far so good.
EXT4 e2fsck shows clean filesystem, if there'll something wrong this should confirm the hard drives issue.

Comment by Jan Hejl [ 2016-11-18 ]

Unfotunatelly it happend even on the XFS filesystem + clean LVM volume. 20161118-mysqld.err attached. This is time options:

stack-trace
disable-gdb

were commented.

Is there something else I can do? Or is there someone able to tell it's a problem of the hard drives?

Comment by Elena Stepanova [ 2016-11-18 ]

jplindst,

Could you please take a look at the last comments (InnoDB-related)? Do you think it's likely to be a hardware problem?

I find it additionally confusing that one time recovery failed and another time it succeeded without any intervention.

Comment by Jan Lindström (Inactive) [ 2016-11-30 ]

Hi, yes most likely hardware problem both TokuDB and InnoDB complain corrupted database pages. I do not know enough about TokuDB to comment on those logs but InnoDB error is clearly about the fact that page that we read is corrupted.

R: Jan

Comment by Jan Hejl [ 2016-11-30 ]

Thanks for the comment.

I can confirm that in past few days I'm struggling with "FLUSH CACHE EXT" error on of the RAID drives. Interesting is the fact that the drive was replaced with new one, even newer model of the drive and the error happened again.
After updating machine's BIOS TokuDB stopped crashing but the drive stopped working again. When i turned the machine off took the drive out and put it back again, it was operating normally for some time. Thus it's clearly some HW error.

Thanks for all the help provided. I think this ticket might be closed.

Generated at Thu Feb 08 07:48:01 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.