Re: [Maria-discuss] Horrendeous InnoDB crash

7 Jun 2016

      No, honestly, that wasn't it. :) As per the Jira link Jan Lindström provided, the data becomes corrupted as a result of certain queries! (I didn't know why, but it was pretty repeatable: wipe the database, re-populate it again, run the scheduled script, and bam, the 'xovers' table immediately crashes).

Without the fix provided in 10.1.14, I would have never been able to solve this (except maybe to revert to myisam).

A big thanks again to Jan Lindström, for identifying the issue, and to everyone else willing to think along with me! :)

-----Original Message-----
From: Jan Steinman [mailto:Jan@EcoReality.org] 
Sent: Tuesday, June 7, 2016 01:05
To: Mark <asarian@xs4all.nl>
Cc: chris@mariadb.com; maria-discuss@lists.launchpad.net
Subject: Re: [Maria-discuss] Horrendeous InnoDB crash
...
So, with almost certainty, the scheduled task corrupts the database.
No, it looks to me like the scheduled task is trying to access corrupted data — important distinction!

To rule this out, dump the database, move your datadir to a safe place, run mysql_install_db, then load the dump: “mysql <dump.sql”.

Then run your scheduled task again. My bet is it will work fine, then.

::::  
:::: Jan Steinman, EcoReality Co-op ::::
...
On 2016-06-06, at 08:59, Mark <asarian@xs4all.nl> wrote:
The log starts just with:
2016-06-06 16:39:16 7716 [Note] Server socket created on IP: '::'.
2016-06-06 16:39:16 7716 [Note] C:\xampp\mysql\bin\mysqld.exe: ready 
for connections.
Version: '10.1.13-MariaDB'  socket: ''  port: 3306  mariadb.org binary 
distribution
No errors at startup (database prefilled with manually run retrieval 
script). Then, at 16:47, when the scheduled retrieve task starts for 
the first time, the log adds:
InnoDB: Error: trying to access page number 250370 in space 69,
InnoDB: space name news/commentsxover,
InnoDB: which is outside the tablespace bounds.
InnoDB: Byte offset 0, len 16384, i/o type 10.
InnoDB: If you get this error at mysqld startup, please check that
InnoDB: your my.cnf matches the ibdata files that you have in the
InnoDB: MySQL server.
2016-06-06 16:47:38 a74  InnoDB: Assertion failure in thread 2676 in 
file fil0fil.cc line 5866
So, with almost certainty, the scheduled task corrupts the database.
Especially since I was now (unfortunately) able to replicate the same 
conditions for the crash. But there's nothing in that php script that 
could normally do that. (Especially since it runs manually just fine, 
without corrupting anything). The scheduled task runs as me, but is 
'hidden', though (i.e., doesn't open a console).
-----Original Message-----
From: Chris Calender [mailto:chris.calender@mariadb.com]
Sent: Monday, June 6, 2016 17:44
To: Mark <asarian@xs4all.nl>; maria-discuss@lists.launchpad.net
Subject: Re: [Maria-discuss] Horrendeous InnoDB crash
Hello,
No need for the config file, you have corruption in your tablespace, 
hence the crash.
It starts up here, at 16:39:16:
...
2016-06-06 16:39:16 1e24 InnoDB: Warning: Using...
...
2016-06-06 16:39:16 7716 [Note] C:\xampp\mysql\bin\mysqld.exe: ready 
for connections.
Version: '10.1.13-MariaDB'  socket: ''  port: 3306  mariadb.org 
binary
distribution
At the exact same time, we see the corruption (thus this corruption 
was both detected and mentioned at startup):
...
InnoDB: Error: trying to access page number 250370 in space 69,  >
InnoDB: space name spotweb/commentsxover,  > InnoDB: which is outside 
the tablespace bounds.
InnoDB: Byte offset 0, len 16384, i/o type 10.
InnoDB: If you get this error at mysqld startup, please check that  >
InnoDB: your my.cnf matches the ibdata files that you have in the  > InnoDB:
MySQL server.
Then, about 8 minutes later, you attempt to select from the same table 
that is corrupted ("spotweb.commentsxover"), hence the immediate 
assertion
failure:
...
2016-06-06 16:47:38 a74  InnoDB: Assertion failure in thread 2676 in
...
file fil0fil.cc line 5866
And the stack trace confirms the query:
...
Query (0x4b01740): SELECT messageid FROM commentsxover ORDER BY id 
DESC LIMIT 5000
Since that is the only table referenced as being corrupted, you could 
probably get by with dropping it and then restoring it from a backup.
If you do not have a current backup, then you will need to enable 
innodb_force_recovery (read below link for details), then dump from 
the table, dumping "around" the corruption using mysqldump with ORDER 
BY pk and LIMIT, and then once you have as much data as possible, then 
DROP the table, and import your dump.
http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html
Hope this helps!
Best wishes,
Chris
On 6/6/2016 11:17 AM, Mark wrote:
...
And yet the same 9*&^%^&*()_ crash (see below). I'm beginning to get 
real tired of this.
The corruption starts almost immediately upon running a scheduled 
task that's retrieving posts (at 16:47 hours). It's the same task I 
ran manually first. There's absolutely no reason why a simple 
scheduled post retrieval script should immediately corrupt MariaDB 
beyond all recognition. The scheduled task consists of nothing more 
than a script (that runs as me), like:
c:\xampp\php\php.exe c:\xampp\htdocs\news\retrieve.php -force
It runs every 30 mins.
And no, no write-delays, or computer crashes that preceded this.
2016-06-06 15:52:27 3552 [Note] C:\xampp\mysql\bin\mysqld.exe: Normal 
shutdown
2016-06-06 15:52:27 3552 [Note] Event Scheduler: Purging the queue. 0 
events
2016-06-06 15:52:27 3504 [Note] InnoDB: FTS optimize thread exiting.
2016-06-06 15:52:27 3552 [Note] InnoDB: Starting shutdown...
2016-06-06 15:52:29 3552 [Note] InnoDB: Shutdown completed; log 
sequence number 6767908697
2016-06-06 15:52:29 3552 [Note] C:\xampp\mysql\bin\mysqld.exe: 
Shutdown complete
2016-06-06 16:39:16 1e24 InnoDB: Warning: Using 
innodb_additional_mem_pool_size is DEPRECATED. This option may be 
removed in future releases, together with the option 
innodb_use_sys_malloc and with the InnoDB's internal memory allocator.
2016-06-06 16:39:16 7716 [Note] InnoDB: Using mutexes to ref count 
buffer pool pages
2016-06-06 16:39:16 7716 [Note] InnoDB: The InnoDB memory heap is 
disabled
2016-06-06 16:39:16 7716 [Note] InnoDB: Mutexes and rw_locks use 
Windows interlocked functions
2016-06-06 16:39:16 7716 [Note] InnoDB: Memory barrier is not used
2016-06-06 16:39:16 7716 [Note] InnoDB: Compressed tables use zlib
1.2.3
2016-06-06 16:39:16 7716 [Note] InnoDB: Using generic crc32 
instructions
2016-06-06 16:39:16 7716 [Note] InnoDB: Initializing buffer pool, 
size = 16.0M
2016-06-06 16:39:16 7716 [Note] InnoDB: Completed initialization of 
buffer pool
2016-06-06 16:39:16 7716 [Note] InnoDB: Highest supported file format 
is Barracuda.
2016-06-06 16:39:16 7716 [Note] InnoDB: 128 rollback segment(s) are
active.
2016-06-06 16:39:16 7716 [Note] InnoDB: Waiting for purge to start
2016-06-06 16:39:16 7716 [Note] InnoDB:  Percona XtraDB
(http://www.percona.com) 5.6.28-76.1 started; log sequence number
6767908697
2016-06-06 16:39:16 7100 [Note] InnoDB: Dumping buffer pool(s) not 
yet started
2016-06-06 16:39:16 7716 [Note] Plugin 'FEEDBACK' is disabled.
2016-06-06 16:39:16 7716 [Note] Server socket created on IP: '::'.
2016-06-06 16:39:16 7716 [Note] C:\xampp\mysql\bin\mysqld.exe: ready 
for connections.
Version: '10.1.13-MariaDB'  socket: ''  port: 3306  mariadb.org 
binary distribution
InnoDB: Error: trying to access page number 250370 in space 69,
InnoDB: space name spotweb/commentsxover,
InnoDB: which is outside the tablespace bounds.
InnoDB: Byte offset 0, len 16384, i/o type 10.
InnoDB: If you get this error at mysqld startup, please check that
InnoDB: your my.cnf matches the ibdata files that you have in the
InnoDB: MySQL server.
2016-06-06 16:47:38 a74  InnoDB: Assertion failure in thread 2676 in 
file fil0fil.cc line 5866
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.
160606 16:47:38 [ERROR] mysqld got exception 0x80000003 ;
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.
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
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.
Server version: 10.1.13-MariaDB
key_buffer_size=16777216
read_buffer_size=262144
max_used_connections=1
max_threads=1001
thread_count=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads =
787100 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
Thread pointer: 0x0x4af7270
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...
mysqld.exe!my_parameter_handler()
mysqld.exe!my_mb_ctype_mb()
mysqld.exe!?get_ctx@MDL_ticket@@QBEPAVMDL_context@@XZ()
mysqld.exe!?get_ctx@MDL_ticket@@QBEPAVMDL_context@@XZ()
mysqld.exe!?functype@Item_func_dyncol_create@@UBE?AW4Functype@Item_fu
n
c@@XZ()
mysqld.exe!?get_ctx@MDL_ticket@@QBEPAVMDL_context@@XZ()
mysqld.exe!??0Global_read_lock@@QAE@XZ()
mysqld.exe!??0Global_read_lock@@QAE@XZ()
mysqld.exe!?get_trg_event_map@Update_rows_log_event@@UAEEXZ()
mysqld.exe!?get_trg_event_map@Update_rows_log_event@@UAEEXZ()
mysqld.exe!?ha_open@handler@@QAEHPAUTABLE@@PBDHI@Z()
mysqld.exe!?open_table_from_share@@YA?AW4open_frm_error@@PAVTHD@@PAUT
A
BLE_SHARE@@PBDIIIPAUTABLE@@_N@Z()
mysqld.exe!?open_table@@YA_NPAVTHD@@PAUTABLE_LIST@@PAVOpen_table_cont
e
xt@@@Z()
mysqld.exe!?recover_from_failed_open@Open_table_context@@QAE_NXZ()
mysqld.exe!?open_tables@@YA_NPAVTHD@@ABUDDL_options_st@@PAPAUTABLE_LI
S
T@@PAIIPAVPrelocking_strategy@@@Z()
mysqld.exe!?open_and_lock_tables@@YA_NPAVTHD@@ABUDDL_options_st@@PAUT
A
BLE_LIST@@_NIPAVPrelocking_strategy@@@Z()
mysqld.exe!??0Table_scope_and_contents_source_st@@QAE@ABU0@@Z()
mysqld.exe!?mysql_execute_command@@YAHPAVTHD@@@Z()
mysqld.exe!?mysql_parse@@YAXPAVTHD@@PADIPAVParser_state@@@Z()
mysqld.exe!?dispatch_command@@YA_NW4enum_server_command@@PAVTHD@@PADI
@
Z()
mysqld.exe!?do_command@@YA_NPAVTHD@@@Z()
mysqld.exe!?threadpool_process_request@@YAHPAVTHD@@@Z()
mysqld.exe!?tp_end@@YAXXZ()
KERNEL32.DLL!SetUserGeoID()
ntdll.dll!TpSimpleTryPost()
ntdll.dll!EtwNotificationRegister()
KERNEL32.DLL!BaseThreadInitThunk()
ntdll.dll!RtlUnicodeStringToInteger()
ntdll.dll!RtlUnicodeStringToInteger()
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x4b01740): SELECT messageid FROM commentsxover ORDER BY id 
DESC LIMIT 5000
Connection ID (thread ID): 2
Status: NOT_KILLED
Optimizer switch:
index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_m
e 
rge_intersection=on,index_merge_sort_intersection=off,engine_conditio
n 
_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_wi
t 
h_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=
o 
n,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=o
n 
,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer
_ 
join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,j
o 
in_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,ta
b le_elimination=on,extended_keys=on,exists_to_in=on
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.
*From:*Justin Swanhart [mailto:greenlion@gmail.com]
*Sent:* Monday, June 6, 2016 16:16
*To:* Mark <asarian@xs4all.nl>
*Cc:* maria-discuss@lists.launchpad.net
*Subject:* Re: [Maria-discuss] Horrendeous InnoDB crash
Hi,
Do you have write-behind caching turned on?  Do you have RAID card 
without BBU?  Did your computer crash?  If the OS or hardware (like 
IDE HDD cache) lies about actually writing to disk, InnoDB can become 
corrupted, and this is not the fault of innodb.  Be aware that if 
this is a VM, many VM lie about disk writes, a "feature" you must turn off.
Sent from my iPhone
On Jun 6, 2016, at 6:23 AM, Mark <asarian@xs4all.nl 
<mailto:asarian@xs4all.nl>> wrote:
Sorry I wiped the database; but it got to the point where MariaDB
   immediately crashed upon startup (so the usual repair attempts were
   futile, as they all kinda assume a MariaDB server that's up and
   running). I have years of experience (FreeBSD) with myisam tables;
   but a crash like this is a first for me, really, where the entire
   database was foobarred to the point MariaDB wouldn't even start any
   more.
Thanks for creating the bug report. I shall investigate myself too,
   in trying to find a way to integrate the MariaDB shutdown gracefully
   (in UNIX this is all much simpler and straightforward).
-Mark
*From:*Vladislav Vaintroub [mailto:vvaintroub@gmail.com]
   *Sent:* Monday, June 6, 2016 11:39
   *To:* Mark <asarian@xs4all.nl <mailto:asarian@xs4all.nl>>;
   maria-discuss@lists.launchpad.net
   <mailto:maria-discuss@lists.launchpad.net>
   *Subject:* Re: [Maria-discuss] Horrendeous InnoDB crash
Yes, it is possible that Windows does not give enough time to
   MariaDB to shut down gracefully. I just created a task for this one
   here https://jira.mariadb.org/browse/MDEV-10183.
Still, Innodb should handle this situation gracefully, and recover
   on startup, so what you see is a bug. It is a pity that you wiped
   down the database, it would be useful for a bug report.
On 06.06.2016 11:08, Mark wrote:
Got a huge crash today, right after initializing my first
       MariaDB database (see below). Got several more errors about
       tables having crashed later on, and MariaDB wouldn't even start
       up any more (I wound up wiping the entire database).
So, my question is, what could cause MariaDB to fail so
       horrendeously?! I though InnoDB was supposed to be *better* than
       myisam!? Is is because maybe Windows 10 doesn't give MariaDB
       enough time to shut down gracefully? Could it be because a
       Windows scheduler job (potentially) aborts the fetcher script
       when it's still running? (Again, I though InnoDB was supposed to
       be transaction-safe).
In its current state, MariaDB is completely unusable for me.
And no, I don't have hard disk errors. :)
Seriously, though, I could use some major insight!
Thanks.
2016-06-06 10:32:15 2552 [Note] Server socket created on IP: '::'.
2016-06-06 10:32:15 2552 [Note] C:\xampp\mysql\bin\mysqld.exe:
       ready for connections.
Version: '10.1.13-MariaDB'  socket: ''  port: 3306 mariadb.org
       <http://mariadb.org> binary distribution
InnoDB: Error: trying to access page number 251010 in space 
69,
InnoDB: space name news/commentsxover,
InnoDB: which is outside the tablespace bounds.
InnoDB: Byte offset 0, len 16384, i/o type 10.
InnoDB: If you get this error at mysqld startup, please check 
that
InnoDB: your my.cnf matches the ibdata files that you have in 
the
InnoDB: MySQL server.
2016-06-06 08:47:46 e08  InnoDB: Assertion failure in thread
       3592 in file fil0fil.cc <http://fil0fil.cc> line 5866
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.
160606  8:47:46 [ERROR] mysqld got exception 0x80000003 ;
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.
_______________________________________________
Mailing list:https://launchpad.net/~maria-discuss
Post to     :maria-discuss@lists.launchpad.net
       <mailto:maria-discuss@lists.launchpad.net>
Unsubscribe :https://launchpad.net/~maria-discuss
More help   :https://help.launchpad.net/ListHelp
_______________________________________________
   Mailing list: https://launchpad.net/~maria-discuss
   Post to     : maria-discuss@lists.launchpad.net
   <mailto:maria-discuss@lists.launchpad.net>
   Unsubscribe : https://launchpad.net/~maria-discuss
   More help   : https://help.launchpad.net/ListHelp
_______________________________________________
Mailing list: https://launchpad.net/~maria-discuss
Post to     : maria-discuss@lists.launchpad.net
Unsubscribe : https://launchpad.net/~maria-discuss
More help   : https://help.launchpad.net/ListHelp
--
Chris Calender, M.S., Principal Support Engineer MariaDB Corporation
_______________________________________________
Mailing list: https://launchpad.net/~maria-discuss
Post to     : maria-discuss@lists.launchpad.net
Unsubscribe : https://launchpad.net/~maria-discuss
More help   : https://help.launchpad.net/ListHelp

Mark

tags

participants (1)