|
Strangely, the page dumps do not look like uncompressed, unencrypted InnoDB pages. It does not seem to me that encryption or compression would be enabled, because there are several English plain text strings in each page dump. But there is no valid-looking page header or trailer either. In .ibd files, the only pages that contain user data are index pages, and these pages should always contain the 'infimum' and 'supremum' pseudo-records. Those records are missing too.
Also, innochecksum would crash when I tried to feed it the 16384-byte page dump that I extracted from the hex dump after this error log message:
2017-04-03 3:08:21 140102489065216 [ERROR] InnoDB: Space 40022 file piwik/piwik_archive_blob_2015_07 read of page 16614.
|
The message that I got was as follows, using innochecksum from the Debian mariadb-server-core-10.1 package, version 10.1.22-3:
innochecksum /dev/shm/page.bin
|
InnoDB offline file checksum utility.
|
innochecksum: /build/mariadb-10.1-Qh_1fj/mariadb-10.1-10.1.22/storage/innobase/include/fsp0fsp.ic:80: ulint fsp_flags_get_zip_size(ulint): Assertion `zip_size <= UNIV_ZIP_SIZE_MAX' failed.
|
To analyze further, I would need to know the InnoDB parameters (is encryption or page compression enabled?) and the table schema (SHOW CREATE TABLE).
Can you try running innochecksum on all InnoDB data files? While doing so, beware of MDEV-11939 (the first page of ibdata1 and possible other files in innodb_data_file_path are incorrectly being claimed as corrupted).
|
|
Hi Marko,
thank you for taking time to look into the Problem. Here the requested Information:
1) no encryption/compression enabled (see attached Variables Output) ( show_variables.txt )
2) Table Schema attached ( create_table.txt )
3) Whole Config attached ( mariadb_config.zip )
4) innochecksum of piwik_archive_blob_2015_07:
[root@piwikdb piwik]# innochecksum piwik_archive_blob_2015_07.ibd
|
InnoDB offline file checksum utility.
|
Table is uncompressed
|
Page size is 16384
|
0 bad checksum
|
17463 FIL_PAGE_INDEX
|
0 FIL_PAGE_UNDO_LOG
|
1 FIL_PAGE_INODE
|
0 FIL_PAGE_IBUF_FREE_LIST
|
2723 FIL_PAGE_TYPE_ALLOCATED
|
2 FIL_PAGE_IBUF_BITMAP
|
0 FIL_PAGE_TYPE_SYS
|
0 FIL_PAGE_TYPE_TRX_SYS
|
1 FIL_PAGE_TYPE_FSP_HDR
|
1 FIL_PAGE_TYPE_XDES
|
2081 FIL_PAGE_TYPE_BLOB
|
0 FIL_PAGE_TYPE_ZBLOB
|
0 FIL_PAGE_PAGE_COMPRESSED
|
0 FIL_PAGE_PAGE_COMPRESSED_ENCRYPTED
|
0 other
|
0 max index_id
|
undo type: 0 insert, 0 update, 0 other
|
undo state: 0 active, 0 cached, 0 to_free, 0 to_purge, 0 prepared, 0 other
|
index_id #pages #leaf_pages #recs_per_page #bytes_per_page
|
101191 14867 14829 72 14821
|
101192 2596 2587 408 16012
|
|
index_id page_data_bytes_histgram(empty,...,oversized)
|
101191 0 2 0 0 1 9 60 138 343 2080 12234 0
|
101192 0 1 0 0 0 2 1 0 0 1 2591 0
|
Also no high pressure on the Server:
Any further information I can provide to help finding the Problem?
|
|
Also no high pressure on the Server:
|
|
Hallo Andreas,
Theoretically, the corrupted pages could contain BLOB data as well. It is difficult to tell, because the page header looks corrupted. Can you check the error log and verify if the text strings of the page dump could have been inserted into the table?
In some parts of the page dump that I am examining, the data looks like it could match the PRIMARY KEY of the table. For example:
000035a0: b711 bdbc 013e 718c e705 a485 1800 0006 .....>q.........
|
000035b0: bdf6 5265 736f 6c75 7469 6f6e 5f63 6f6e ..Resolution_con
|
000035c0: 6669 6775 7261 7469 6f6e 0000 0000 3455 figuration....4U
|
000035d0: 8200 0009 781f b000 0002 2c8f bf03 8fbf ....x.....,.....
|
At offset 0x35ae it looks like we could have the clustered index tuple
(idarchive,name,DB_TRX_ID,DB_ROLL_PTR,idsite,…)=(0x6bdf6, 'Resolution_configuration', 0x3455, (fresh insert), 0x22c8fbf, …)
Alas, the record header does not look correct (the next-record offset 0x1800 does not make sense). So, maybe this is a secondary index record page instead?
The tuple would then be
(period,ts_archived,idarchive,name,(child page number)), but the bytes ending at 0x35ae do not seem to match what I would expect.
Do the following statements crash the server?
SELECT COUNT(*) FROM piwik.piwik_archive_blob_2015_07;
|
CHECK TABLE piwik.piwik_archive_blob_2015_07;
|
The first one should only access the clustered index leaf pages (probably no BLOB pages at all), and CHECK TABLE should access all pages.
|
|
Hi Marko,
the Table contains BLOB Data in value Field - see Screenshot ( and with "show blob" active: )
I'm not quite sure why there should be any insert at all - as it's archived Data from 2015?
Both Queries work as expected - no crash, no problem:
SELECT COUNT(*) FROM piwik.piwik_archive_blob_2015_07;
|
CHECK TABLE piwik.piwik_archive_blob_2015_07;
|
|
|
Hi Andreas,
Thanks for the update. Sorry, I have been busy with other tasks.
I wonder why InnoDB crashed in the first place. Everything looks just normal now.
Can you try the following (as I am not 100% sure if CHECK TABLE would fetch the BLOBs):
SELECT * FROM piwik.piwik_archive_blob_2015_07;
|
(or execute mysqldump to do the same)
If it is not crashing now, then it is really strange why it originally crashed. The error message should only be displayed when reading a page from a file to the buffer pool fails.
Can you check any error logs of the storage subsystem, just in case? On my system, the command would be smartctl. Can you test the memory too, using memtest86, memtester or similar? Is the server equipped with ECC RAM?
I would not rule out hardware, firmware or kernel problems. While the SSD storage medium is likely more reliable than HDD, the failure modes are different, and firmware bugs can have more devastating effects (the extreme case being the loss of all data). Another possible problem could be a kernel bug, or a DMA controller bug or faulty memory or caches.
I am not claiming that InnoDB is bug-free. But I do not think that it is likely that some ‘rogue’ writer corrupted the page so soon after it was read from the file to the buffer pool. And the page dump looked so weird, so badly corrupted.
I wonder if you could extract one of the corrupted pages from the file:
dd if=piwik/piwik_archive_blob_2015_07.ibd bs=16384 skip=16614 count=1 of=page16614.bin
|
and the same for other pages if possible.
Even if the above-mentioned SELECT * succeeds, it is possible that the file contains corrupted pages with vaild checksum, but the pages happen to be currently unused. In that case, the erroneous page read would have been triggered by some read-ahead logic. But InnoDB should not have written such corrupted pages (with valid checksum) in the first place. If the page checksums are valid and the page is corrupted, a possible explanation is that something corrupted the page while it was in the InnoDB buffer pool.
|
|
Hello Marko,
I did the SELECT as requested - and it did not produce any crash.
I also checked all the logs / statistics of our storage subsystem / servers - no indication of any problem. Servers are equipped with ECC RAM. (HP Blade Servers)
As I checked everything today I noticed that again (another) Table crashed and is inaccessible! :-/
Would it help if you have access to the crashed IBD File (+Log with Crash Info)? I sent you an E-Mail with a Download Link to it.
thx
Andreas
|
|
ok ... lot's of corrupted Tables again it seems ... on 04.04. mysqlcheck did not show any Errors anymore ... now 7 crashed Tables again:
piwik.piwik_archive_blob_2012_12
Warning : InnoDB: Index "PRIMARY" is marked as corrupted
error : Corrupt
piwik.piwik_archive_blob_2013_01
Warning : InnoDB: Index "PRIMARY" is marked as corrupted
error : Corrupt
piwik.piwik_archive_blob_2013_06
Warning : InnoDB: Index "PRIMARY" is marked as corrupted
error : Corrupt
piwik.piwik_archive_blob_2015_04
Warning : InnoDB: Index "PRIMARY" is marked as corrupted
error : Corrupt
piwik.piwik_archive_blob_2016_05
Warning : InnoDB: Index "PRIMARY" is marked as corrupted
error : Corrupt
piwik.piwik_archive_blob_2016_06
Warning : InnoDB: Index "PRIMARY" is marked as corrupted
error : Corrupt
piwik.piwik_archive_blob_2016_11
Warning : InnoDB: Index "PRIMARY" is marked as corrupted
error : Corrupt
|
|
Futureweb, thanks, I got the email.
Unfortunately I am currently very busy with other tasks, and I should start my summer vacation soon. So, realistically speaking it might be that I cannot return to this before August or even later. It would help if you could somehow narrow it down further.
The nasty thing about corruption is that it can be hidden until you access the affected pages. What could cause the corruption? Some bug in the mysqld server process that causes a "rogue" write to the InnoDB buffer pool? (Page checksums are only computed right before writing a page back from the buffer pool to the data file, or when loading a page from the data file to the buffer pool.)
Could it be unreliable RAM or caches on the server? (sudo apt install memtester, and let multiple instances of it run for an extended time)
An unreliable connection to the storage subsystem? (sudo apt install smartmontools; sudo smartctl -A)
Or could the data be spontaneously corrupted on the storage media while it was apparently not accessed for a long time? (I have witnessed that on a laptop hard drive; some files in my photo collection were corrupted, noticed when running "rsync -ncavil files/ /backup/files/")
A kernel bug?
Are the data files being written to by any other program than the mysqld server? Did you ever restore backups? If so, how were these backups made and restored? Maybe this process is faulty?
Sorry for the flood of questions and suggestions, but I cannot look at the data right now, so I am trying to give you ideas how to narrow it down. The nature of the corruption in the data dump might provide some useful clues to me when I will be able to look at it, but I would not count on that.
|
|
Hi @Marko Mäkelä,
I repaired all broken Tables again. (Got Backups of all 7 corrupted IBDs if it helps diagnosing the problem)
As you wrote (if I understood correct) if pages are unused those corruptions could be undetected for a longer time - how can I be sure that the current status of all of my Tables is OK?
What I did now is a "mysqlcheck --optimize" - which triggers a recreate/analyze of the Tables - would this reveal corrupt pages/checksums/problems?
mysqlcheck --optimize and afterwards --check did not show any problems for now except those 3 Errors which appeared right now in the Logs as I again did a mysqlcheck:
2017-06-23 9:43:52 140133463947008 [ERROR] InnoDB: Space id and page n:o stored in the page read in are 62138:26621, should be 62173:18301!
2017-06-23 9:43:52 140133463947008 [ERROR] InnoDB: Space id and page n:o stored in the page read in are 62138:26622, should be 62173:18302!
2017-06-23 9:43:52 140133463947008 [ERROR] InnoDB: Space id and page n:o stored in the page read in are 62138:26623, should be 62173:18303!
As for your Questions to narrow down the problem:
- let memtest86+ run overnight - no problems so far (ECC RAM)
- storage subsystem is "Virtuozzo Storage" (https://virtuozzo.com/products/virtuozzo-storage/) - Software defined SAN running on Enterprise Server SSDs connected through dedicated 10GBit Network. All Data Blocks are stored on 3 different Storage Nodes. If the Problems is here we got a decent problem! :-/ ... but Logs didn't show any suspect activities within storage subsystem - and dozens of other Systems (Webserver, DB Servers, Mail Servers, ...) don't show problems - so I guess/hope the Problem isn't burried here ...
- as for possible Kernel Bug - no idea? :-/ ... using CentOS Linux release 7.3.1611 (Core) - as it's really wide spread - i hope not?
- I create Backups with "innobackupex version 2.3.8 Linux (x86_64) (revision id: 9328211)" - but no restore needed yet (except repairing the corrupted Tables which I did with older Backups when the Tables still were OK)
- Only MariaDB is accessing the Data Files - it's a dedicated DB Server
- Updated to 10.1.24-MariaDB yesterday
I guess those Answers won't really help to narrow down the Problem in a specific direction ... sorry! :-/
Any other ideas on how to narrow down the Problem?
Thank you for your time and relaxing holidays! 
Andreas
|
|
That's crazy - 3 days no problem - and today again some DB corruptions:
...
|
2017-06-23 9:43:52 140133463947008 [ERROR] InnoDB: Space id and page n:o stored in the page read in are 62138:26621, should be 62173:18301!
|
...
|
2017-06-24 3:32:04 140133463947008 [ERROR] InnoDB: Space id and page n:o stored in the page read in are 62138:26621, should be 62173:18301!
|
...
|
2017-06-25 3:34:17 140133463947008 [ERROR] InnoDB: Space id and page n:o stored in the page read in are 62465:18039, should be 62490:4983!
|
...
|
2017-06-26 3:32:08 140133463947008 [ERROR] InnoDB: Space id and page n:o stored in the page read in are 1358817207:3293897363, should be 62801:13951!
|
2017-06-26 3:32:08 140133463947008 [Note] InnoDB: Log sequence number at the start 2841626724 and the end 2277888994 do not match.
|
2017-06-26 3:32:08 140133463947008 [ERROR] InnoDB: Database page corruption on disk or a failed file read of tablespace piwik/piwik_archive_blob_2016_03 page [page id: space=62801, page number=13951]. You may have to recover from a backup.
|
2017-06-26 03:32:08 7f735d56f700 InnoDB: Page dump in ascii and hex (16384 bytes):
|
len 16384; hex e4d4c698c454e29399cb79a5fc8ff2d4563ebcdaa95fc8641c091ca8d3fe5723f53c50fde7b7ebfbbb89987838e9124e241a7efdf13c6d813c7900c8b5bf18050b8122000005295a56697369746f72496e7465726573745f6461797353696e63654c61737456697369740000462645bddc00002664137a0$
|
InnoDB: End of page dump
|
2017-06-26 03:32:09 7f735d56f700 InnoDB: uncompressed page, stored checksum in field1 3839149720, calculated checksums for field1: crc32 1464224319, innodb 1101069064, none 3735928559, stored checksum in field2 1288165860, calculated checksums for field2:$
|
InnoDB: page type 7177 meaning PAGE TYPE CORRUPTED
|
2017-06-26 3:32:09 140133463947008 [Note] InnoDB: It is also possible that your operating system has corrupted its own file cache and rebooting your computer removes the error. If the corrupt page is an index page. You can also try to fix the corruption $
|
2017-06-26 3:32:09 140133463947008 [ERROR] InnoDB: Read operation failed for tablespace ./piwik/piwik_archive_blob_2016_03.ibd offset 13951 with error Page read from tablespace is corrupted.
|
2017-06-26 3:32:10 140132249761536 [ERROR] InnoDB: Space id and page n:o stored in the page read in are 1952801652:410759468, should be 62802:2516!
|
2017-06-26 3:32:10 140132249761536 [Note] InnoDB: Log sequence number at the start 527 and the end 876162867 do not match.
|
2017-06-26 3:32:10 140132249761536 [ERROR] InnoDB: Database page corruption on disk or a failed file read of tablespace piwik/piwik_archive_blob_2016_04 page [page id: space=62802, page number=2516]. You may have to recover from a backup.
|
2017-06-26 03:32:10 7f7314f7f700 InnoDB: Page dump in ascii and hex (16384 bytes):
|
len 16384; hex 0175ae89187bb12cd0c43d8b07f9235b38047c170000020fd444657669636573446574656374696f6e5f6272616e6473000046262ceac900000a6301a6000000e18fbb2d8fbb2d0199909b6276789c2d4c310ec2400cfb4b76a4cb9542715666a82af62a850e274e6268a50ea7fb3b89dac1b11dd956449$
|
InnoDB: End of page dump
|
...
|
2017-06-26 3:32:12 140132249761536 [ERROR] InnoDB: Space id and page n:o stored in the page read in are 3878401683:3781535490, should be 62802:2559!
|
2017-06-26 3:32:12 140132249761536 [Note] InnoDB: Log sequence number at the start 678497318 and the end 1807888404 do not match.
|
2017-06-26 3:32:12 140132249761536 [ERROR] InnoDB: Database page corruption on disk or a failed file read of tablespace piwik/piwik_archive_blob_2016_04 page [page id: space=62802, page number=2559]. You may have to recover from a backup.
|
2017-06-26 03:32:12 7f7314f7f700 InnoDB: Page dump in ascii and hex (16384 bytes):
|
len 16384; hex 51d73406e165a7027d3191c5c68583f506db4ce028710c268489e1a8cf7aca03a5b8e72bb693cea52e720c2e849985b80f3c485972cb4a5ead790dbde704e16da17ea46b7cbc8b3dfbdc0e1f4a895bc04390262eea81ebbea2de7fc5361f84cf913e79db6bf6ba235d0db3f28e571fd890faecbf81703ee$
|
InnoDB: End of page dump
|
2017-06-26 03:32:12 7f7314f7f700 InnoDB: uncompressed page, stored checksum in field1 1373058054, calculated checksums for field1: crc32 2446682085, innodb 2564686005, none 3735928559, stored checksum in field2 2623377489, calculated checksums for field2:$
|
InnoDB: page type 33929 meaning PAGE TYPE CORRUPTED
|
2017-06-26 3:32:12 140132249761536 [Note] InnoDB: It is also possible that your operating system has corrupted its own file cache and rebooting your computer removes the error. If the corrupt page is an index page. You can also try to fix the corruption $
|
2017-06-26 3:32:12 140132249761536 [ERROR] InnoDB: Read operation failed for tablespace ./piwik/piwik_archive_blob_2016_04.ibd offset 2559 with error Page read from tablespace is corrupted.
|
...
|
|
|
Even if there are no errors within Storage/SAN Subsystem Logs I opened a Case with Virtuozzo (using their Software-Defined-Storage) on this issue. Seems like the Problem is burried here ... (as you already have guessed)
Answer Virtuozzo Support:
since vzkernel-2.6.32-042stab122.3 and newer kernel, we changed inode preallocation, before that kernel may skip drop_preallocation if file is sparse.
|
Some customers reported that on earlier kernels(before 122.3) in rare cases, container's data may be corrupted after defragmentation in ploop.
|
...
|
The issue I mentioned is weird coincident of ploop defragmentation and MariaDB activity that causes some none-0 blocks to be treated as 0 and reused incorrectly.
|
The exact reproduce condition was never found, but no one yet reported this issue to happen on new kernels with new preallocation technique.
|
I will update to latest >122.3 Kernel, repair broken Tables again and hope the Problem is gone then ... will Update this Case when I know more.
|
|
Futureweb, thanks! Especially the space ID and page number mismatch looked like it must be a bug in the file system or storage subsystem.
I do not know if you are using PAGE_COMPRESSED=YES, but if you were, you might expose yourself to rarer bugs.
When MySQL 5.7 copied the idea from MariaDB 10.1, complaints about the performance hit the blogosphere:
Small Datum: Wanted: a file system on which InnoDB transparent page compression works
|
|
alright - even with the latest 2.6.32-042stab123.8 Kernel we got corruption again - mariadb.28062017.log -
contacted Virtuozzo Support again - as it's most likely a Problem on their side as you say ... will keep you posted.
thx for PAGE_COMPRESSED Info - Piwik is not using it - but good to know! 
|
|
Futureweb, was the issue narrowed down to the SAN?
|
|
Hey @Marko Mäkelä,
it turned out that the ploop defragmentation of Virtuozzo 6 Storage sometimes corrupted IBD Files within Containers. Virtuozzo Devs tried to find the Problem but had no luck. (Virtuozzo Support Case: 15178)
Virtuozzo Support:
...
|
I have spoken with the responsible developer, so far there is no clue how this corruption could happen,
|
with all the debug trace we have for defrag operations there are completely no evidence that something may go wrong.
|
Now we are thinking of a way to add debug for IO that was created not by defrag but by MariaDB.
|
---
|
It turns out that we cannot make a sufficient debug method without affecting ploop performance.
|
...
|
Since it was not reproduceable on a Test Container - but only on the Live Container which was productive and we couldn't accept downtimes on this one the research was stopped and in the next steps we moved to Virtuozzo 7.
No corruptions within Virtuozzo 7 Containers so far. So I guess it must be something really specific between MariaDB + Virtuozzo 6 Ploop Defrag .... guess the Details will remain a mystery ... :-/
Thank you for your help on this, bye from sunny Austria
Andreas
|
|
Small Update in case someone faces the same problem: It seems that upgrading to latest Virtuozzo 7 (+ latest Virtuozzo Storage) did not entirely solve this Problem. We are still facing the corruptions - they got way less ... but still happen every now and then ...
New Virtuozzo Ticket: #21768
|
|
I may have found a possible explanation for this in MDEV-31347.
Futureweb, is the database executing ALTER TABLE or OPTIMIZE TABLE on InnoDB tables?
|
|
Unfortunately I' don't know the internals of Matomo. So I can't say for sure if they alter/optimize the Tables in question.
I haven't observed a corruption for longer time now ... maybe some circumstances have changed which lead to those corruptions - even I can't say which ...
|
|
Futureweb, are the corruptions now a thing of the past? In 10.6 we introduced and rather recently fixed some regressions: MDEV-30531 and MDEV-31767 were the worst.
|