[MDEV-6426] Maria DB crashes randomly on creating indexes Created: 2014-07-08  Updated: 2014-07-22  Resolved: 2014-07-22

Status: Closed
Project: MariaDB Server
Component/s: None
Affects Version/s: 10.0.12
Fix Version/s: 10.0.13

Type: Bug Priority: Major
Reporter: Adrian Nicoara Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 0
Labels: None
Environment:

Windows 8.1 update


Attachments: File my.ini     Text File variables.txt    

 Description   

Since i upgraded to 10.0.12 i have a lot of issues with mariadb crashing on innodb operations like create indexes and create primary keys.

First i had problems with FTS indexes creation and SELECT FTS in queries, so i had to start mariadb in recovery mode to be able to dump all the databases and delete all data files to recreate everything from 0 and import all sql files.

Now FTS works(doesn't crash the server) but i get random crash when creating indexes in tables(indexes of any kinds). Also for foreign keys.

This is example of log entries when i start the server after a crash.
with 10.0.10 i didn't had any problems.

2014-07-08 10:08:40 206c InnoDB: Error: Write to file .\ib_logfile0 failed at offset 43800576.
InnoDB: 512 bytes should have been written, only 512 were written.
InnoDB: Operating system error number 6.
InnoDB: Check that your OS and file system support files of this size.
InnoDB: Check also that the disk is not full or a disk quota exceeded.
InnoDB: Error number 6 means 'No such device or address'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
2014-07-08 10:08:40 206c  InnoDB: Assertion failure in thread 8300 in file os0file.cc line 4738
InnoDB: Failing assertion: ret
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.
140708 10:08:58 [Note] InnoDB: Using mutexes to ref count buffer pool pages
140708 10:08:58 [Note] InnoDB: The InnoDB memory heap is disabled
140708 10:08:58 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
140708 10:08:58 [Note] InnoDB: Compressed tables use zlib 1.2.3
140708 10:08:58 [Note] InnoDB: Not using CPU crc32 instructions
140708 10:08:58 [Note] InnoDB: Initializing buffer pool, size = 128.0M
140708 10:08:58 [Note] InnoDB: Completed initialization of buffer pool
140708 10:08:58 [Note] InnoDB: Highest supported file format is Barracuda.
140708 10:08:58 [Note] InnoDB: Log scan progressed past the checkpoint lsn 45412682
140708 10:08:58 [Note] InnoDB: Database was not shutdown normally!
140708 10:08:58 [Note] InnoDB: Starting crash recovery.
140708 10:08:58 [Note] InnoDB: Reading tablespace information from the .ibd files...
140708 10:08:59 [Note] InnoDB: Restoring possible half-written data pages 
140708 10:08:59 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 45415670
140708 10:09:00 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 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 
InnoDB: Apply batch completed
InnoDB: Last MySQL binlog file position 0 29349107, file name .\mysql-bin.000006
140708 10:09:00 [Note] InnoDB: 128 rollback segment(s) are active.
140708 10:09:01 [Note] InnoDB: Waiting for purge to start
140708 10:09:01 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.17-65.0 started; log sequence number 45415670
140708 10:09:01 [Note] Plugin 'FEEDBACK' is disabled.
140708 10:09:01 [Note] Recovering after a crash using mysql-bin
140708 10:09:01 [Note] Starting crash recovery...
140708 10:09:01 [Note] Crash recovery finished.
140708 10:09:01 [Note] Server socket created on IP: '::'.
140708 10:09:01 [Note] Event Scheduler: Loaded 0 events
140708 10:09:01 [Note] MySQL: ready for connections.
Version: '10.0.12-MariaDB-log'  socket: ''  port: 3306  mariadb.org binary distribution



 Comments   
Comment by Elena Stepanova [ 2014-07-08 ]

Hi,

Did you change configuration or move your database-related files (physically, on disk) together with the upgrade?
Have you had any hardware or environment changes, especially related to storage?
Do your datadir, innodb_data_home_dir, and innodb_data_file_path all point at a local storage?

Please attach your ini file(s) and/or SHOW VARIABLES output.

Comment by Adrian Nicoara [ 2014-07-08 ]

Here are Ini files and SHOW VARIABLES.
I didn't changed anything before and after upgrade. I only replaced all files except "data" folder and i ran mysql upgrade

Comment by Elena Stepanova [ 2014-07-08 ]

Hi,

Is this F: disk where the datadir/basedir are located a normal local HDD/SSD, or is it a network or an external storage?
Do you have any kind of monitoring on the machine? Does it show any errors related to access to disk F:?

Comment by Adrian Nicoara [ 2014-07-08 ]

Hello,

All(C,D,E,F,G,H) are partitions on the same disk, i use every partition for specific kinds of operations. On F i have the database and all my php projects and sources, I check the disk frequently(once at 2 days) for errors, and everything seems to work, fine. All the other stuffs works without any problems. I never had a disk read/write error. I also checked SMART monitor and windows performance logs and i saw no error regarding disk access.
The disk is 1 year old and is used on a high perfomance dell xps laptop. I have 8GB of RAM.

I can try to downgrade and check if the errors still persist.

Comment by Elena Stepanova [ 2014-07-19 ]

Thanks for the information.

Actually, it's a weird error in itself:
"InnoDB: 512 bytes should have been written, only 512 were written."

Maybe this weirdness will somehow help jplindst to see what could cause it.

Comment by Adrian Nicoara [ 2014-07-21 ]

Hello,

I tested a while 10.0.10 and didn't had problems. I did the same stuffs(my workflow) and didn't crashed, everything worked fine.
I upgraded today again to 10.0.12 and imported the sql files and it worked until i had to do something with the full text indexes. For example I inserted in a new table some rows, and after i saw that i forgot to create the full text indexes for the columns, so i created them and then inserted a new row for my application testing and then DB crashed again(server process died)

The row i wanted to insert didn't commit into the DB. I didn't used transactions, just the regular INSERT INTO. I have a text column inside but the length of the data was very small(about 20 characters).

BTW I'm using ZEND Framework 1 DB adapter and i use the php 5.4 builtin connector.

Nothing on the log. If i want to reproduce it I can't, but if I use it for normal work flow it crashes from time to time

Hopefully i get a test case for it soon.

Comment by Adrian Nicoara [ 2014-07-21 ]

After DB restart :

InnoDB: Transaction 114408 was in the XA prepared state.
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 0 row operations to undo
InnoDB: Trx id counter is 114688
InnoDB: Last MySQL binlog file position 0 48142942, file name .\mysql-bin.000010
140721 18:23:09 [Note] InnoDB: 128 rollback segment(s) are active.
InnoDB: Starting in background the rollback of uncommitted transactions
2014-07-21 18:23:09 2124 InnoDB: Rollback of non-prepared transactions completed

So query was commited finally after restart.

Comment by Jan Lindström (Inactive) [ 2014-07-22 ]

This sounds like a permission problem, your my.ini is that correct one, why no innodb related configuration is not given ? Note that when InnoDB creates indexes, it creates temporal files, make sure that these temporal files are created on place where there is enough space and sufficient permissions.

Comment by Adrian Nicoara [ 2014-07-22 ]

Hello,

There is no problem with permissions.
Space is a lot.
FS is NTFS. I dont use security stuffs because is dev env. Mariadb has access to write anywhere. This things happens from time to time.

Here is the full start log. I cropped it last time to what i was thinking that is needed.

140721 18:22:59 [Note] InnoDB: Using mutexes to ref count buffer pool pages
140721 18:22:59 [Note] InnoDB: The InnoDB memory heap is disabled
140721 18:22:59 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
140721 18:22:59 [Note] InnoDB: Compressed tables use zlib 1.2.3
140721 18:22:59 [Note] InnoDB: Not using CPU crc32 instructions
140721 18:22:59 [Note] InnoDB: Initializing buffer pool, size = 128.0M
140721 18:22:59 [Note] InnoDB: Completed initialization of buffer pool
140721 18:22:59 [Note] InnoDB: Highest supported file format is Barracuda.
140721 18:22:59 [Note] InnoDB: The log sequence numbers 45902453 and 45902453 in ibdata files do not match the log sequence number 126208445 in the ib_logfiles!
140721 18:22:59 [Note] InnoDB: Database was not shutdown normally!
140721 18:22:59 [Note] InnoDB: Starting crash recovery.
140721 18:22:59 [Note] InnoDB: Reading tablespace information from the .ibd files...
140721 18:23:08 [Note] InnoDB: Restoring possible half-written data pages 
140721 18:23:08 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Transaction 114408 was in the XA prepared state.
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 0 row operations to undo
InnoDB: Trx id counter is 114688
InnoDB: Last MySQL binlog file position 0 48142942, file name .\mysql-bin.000010
140721 18:23:09 [Note] InnoDB: 128 rollback segment(s) are active.
InnoDB: Starting in background the rollback of uncommitted transactions
2014-07-21 18:23:09 2124  InnoDB: Rollback of non-prepared transactions completed
140721 18:23:10 [Note] InnoDB: Waiting for purge to start
140721 18:23:10 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.17-65.0 started; log sequence number 126208445
140721 18:23:10 [Note] Plugin 'FEEDBACK' is disabled.
140721 18:23:10 [Note] Recovering after a crash using mysql-bin
140721 18:23:16 [Note] Starting crash recovery...
2014-07-21 18:23:16 1864  InnoDB: Starting recovery for XA transactions...
2014-07-21 18:23:16 1864  InnoDB: Transaction 114408 in prepared state after recovery
2014-07-21 18:23:16 1864  InnoDB: Transaction contains changes to 1 rows
2014-07-21 18:23:16 1864  InnoDB: 1 transactions in prepared state after recovery
140721 18:23:16 [Note] Found 1 prepared transaction(s) in InnoDB
140721 18:23:16 [Note] Crash recovery finished.
140721 18:23:16 [Note] Server socket created on IP: '::'.
140721 18:23:17 [Note] Event Scheduler: Loaded 0 events
140721 18:23:17 [Note] MySQL: ready for connections.
Version: '10.0.12-MariaDB-log'  socket: ''  port: 3306  mariadb.org binary distribution
2014-07-21 18:46:09 15dc InnoDB: FTS Optimize Removing table wct/#sql2-1864-20
2014-07-21 18:46:25 15dc InnoDB: FTS Optimize Removing table timpmoca/#sql2-1864-23
2014-07-21 18:46:33 15dc InnoDB: FTS Optimize Removing table timpmoca/#sql2-1864-23
2014-07-21 18:50:31 15dc InnoDB: FTS Optimize Removing table timpmoca/#sql2-1864-22
2014-07-21 18:50:36 15dc InnoDB: FTS Optimize Removing table timpmoca/#sql2-1864-22
2014-07-21 18:51:02 15dc InnoDB: FTS Optimize Removing table wct/#sql2-1864-24
2014-07-21 18:51:06 15dc InnoDB: FTS Optimize Removing table wct/#sql2-1864-24
 

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