InnoDB: Error: Write to file ./ib_modified_log_1_0.xdb failed at offset 0 0. when O_DIRECT is used in combination with innodb_track_changed_pages=1
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
| Percona Server moved to https://jira.percona.com/projects/PS |
Fix Released
|
High
|
Laurynas Biveinis | |
| 5.1 |
Fix Released
|
High
|
Laurynas Biveinis | |
| 5.5 |
Fix Released
|
High
|
Laurynas Biveinis |
Bug Description
$ rm -Rf /tmp/test1; mkdir /tmp/test1/; /ssd/Percona-
130126 15:34:05 [Note] Plugin 'FEDERATED' is disabled.
130126 15:34:05 InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
130126 15:34:05 InnoDB: The InnoDB memory heap is disabled
130126 15:34:05 InnoDB: Mutexes and rw_locks use GCC atomic builtins
130126 15:34:05 InnoDB: Compressed tables use zlib 1.2.3
130126 15:34:05 InnoDB: Using Linux native AIO
130126 15:34:05 InnoDB: Initializing buffer pool, size = 128.0M
130126 15:34:05 InnoDB: Completed initialization of buffer pool
InnoDB: The first specified data file ./ibdata1 did not exist:
InnoDB: a new database to be created!
130126 15:34:05 InnoDB: Setting file ./ibdata1 size to 10 MB
InnoDB: Database physically writes the file full: wait...
130126 15:34:05 InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 5 MB
InnoDB: Database physically writes the file full: wait...
130126 15:34:05 InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile1 size to 5 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: starting tracking changed pages from LSN 8204
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
130126 15:34:07 InnoDB: Error: Write to file ./ib_modified_
InnoDB: 4096 bytes should have been written, only 0 were written.
InnoDB: Operating system error number 22.
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 22 means 'Invalid argument'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://
130126 15:34:07 InnoDB: Operating system error number 22 in a file operation.
InnoDB: Error number 22 means 'Invalid argument'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://
InnoDB: Error: failed writing changed page bitmap file './ib_modified_
InnoDB: Error: log tracking bitmap write failed, stopping log tracking thread!
InnoDB: 127 rollback segment(s) active.
InnoDB: Creating foreign key constraint system tables
InnoDB: Foreign key constraint system tables created
130126 15:34:07 InnoDB: Waiting for the background threads to start
130126 15:34:08 Percona XtraDB (http://
130126 15:34:08 [Warning] /ssd/Percona-
Testcase: copy line exactly as above. Build as 'build-binary.sh --debug' To kill server easily for a few testing rounds:
ps -ef | grep "tmp\/test1" | awk '{print $2}' | xargs kill -9
Related branches
- Stewart Smith (community): Approve on 2013-02-06
- George Ormond Lorch III: Approve (g2) on 2013-02-05
-
Diff: 188 lines (+149/-5)3 files modifiedPercona-Server/mysql-test/suite/innodb_plugin/r/percona_changed_page_bmp_flush.result (+19/-0)
Percona-Server/mysql-test/suite/innodb_plugin/t/percona_changed_page_bmp_flush.test (+93/-0)
Percona-Server/storage/innodb_plugin/log/log0online.c (+37/-5)
- Stewart Smith (community): Approve on 2013-02-06
- George Ormond Lorch III: Approve (g2) on 2013-02-05
-
Diff: 190 lines (+150/-6)3 files modifiedPercona-Server/mysql-test/suite/innodb/r/percona_changed_page_bmp_flush.result (+19/-0)
Percona-Server/mysql-test/suite/innodb/t/percona_changed_page_bmp_flush.test (+93/-0)
Percona-Server/storage/innobase/log/log0online.c (+38/-6)
summary: |
InnoDB: Error: Write to file ./ib_modified_log_1_0.xdb failed at offset - 0 0. + 0 0. when O_DIRECT is used in combination with + innodb_track_changed_pages=1 |
Roel Van de Paar (roel11) wrote : | #1 |
If O_DIRECT is used to open the xdb file and it is an non-aligned
write then it can crash with EINVAL (22).
"InnoDB: 4096 bytes should have been written, only 0 were written."
looks suspicious, since 4kb is the default filesystem block size
and it can be checked with a different block size (like with
innodb_
Related to http://
Cannot reproduce with MTR on 5.1 trunk nor on the 5.5 QA branch.
Roel, can you see if the MTR testcase below fails for you, or if you can adjust it somehow to make it fail?
percona_
--innodb-
percona_
--source include/
--source include/
--disable_warnings
DROP TABLE IF EXISTS t1;
--enable_warnings
let $MYSQLD_DATADIR= `select @@datadir`;
CREATE TABLE t1 (a INT) ENGINE=InnoDB;
INSERT INTO t1 VALUES (1);
--source include/
file_exists $MYSQLD_
DROP TABLE t1;
Error log for the (passing) MTR testcase.
Roel Van de Paar (roel11) wrote : | #5 |
Laurynas, I am no expert in creating MTR testcases, but:
[Roel@qaserver mysql-test]$ pwd
/ssd/Percona-
[Roel@qaserver mysql-test]$ ./mysql-test-run.pl --mysqld=
[Roel@qaserver mysql-test]$ cat out.txt | grep "Error:"
130130 8:27:22 InnoDB: Error: Write to file ./ib_modified_
InnoDB: Error: failed writing changed page bitmap file './ib_modified_
[Roel@qaserver mysql-test]$ find . | grep ib_modified_
./var/log/
Roel Van de Paar (roel11) wrote : | #6 |
130129 15:30:42 InnoDB: O_DIRECT is known to result in 'Invalid argument' on Linux on tmpfs, see MySQL Bug#26662
tmpfs... ?
Roel Van de Paar (roel11) wrote : | #7 |
There is also another issue of interest in there:
130129 15:30:48 InnoDB: Failed to set O_DIRECT on file ./ib_modified_
This may be another bug?
Roel Van de Paar (roel11) wrote : | #8 |
Laurynas, your testcase also fails for me (ssd + ext4)
[Roel@qaserver mysql-test]$ ./mysql-test-run percona_
[Roel@qaserver mysql-test]$ grep -i "error" out.txt
130130 8:35:29 InnoDB: Error: Write to file ./ib_modified_
Alexey Kopytov (akopytov) wrote : | #9 |
As explained (but probably misunderstood) by Raghavendra, the reason is that with O_DIRECT you can only do aligned reads/writes, i.e. memory buffer pointers must be aligned to FS block size. Which does not seem to the case with the code in log0online.c.
Roel Van de Paar (roel11) wrote : | #10 |
With --mysqld=
=============
InnoDB: Warning: innodb_
InnoDB: The log block size is set to 4096.
[...]
InnoDB: last tracked LSN in './ib_modified_
t shutdown. Reading the log to advance the last tracked LSN.
130130 9:32:57 InnoDB: Error: Write to file ./ib_modified_
InnoDB: 4096 bytes should have been written, only 0 were written.
InnoDB: Operating system error number 22.
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 22 means 'Invalid argument'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://
130130 9:32:57 InnoDB: Operating system error number 22 in a file operation.
InnoDB: Error number 22 means 'Invalid argument'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://
InnoDB: Error: failed writing changed page bitmap file './ib_modified_
=============
Roel Van de Paar (roel11) wrote : | #11 |
Running with --mem:
============
130130 9:45:29 InnoDB: Failed to set O_DIRECT on file ./ibdata1: OPEN: Invalid argument, continuing anyway
130130 9:45:29 InnoDB: O_DIRECT is known to result in 'Invalid argument' on Linux on tmpfs, see MySQL Bug#26662
130130 9:45:29 InnoDB: Failed to set O_DIRECT on file ./ibdata1: OPEN: Invalid argument, continuing anyway
130130 9:45:29 InnoDB: O_DIRECT is known to result in 'Invalid argument' on Linux on tmpfs, see MySQL Bug#26662
130130 9:45:29 InnoDB: highest supported file format is Barracuda.
130130 9:45:29 InnoDB: Failed to set O_DIRECT on file ./ib_modified_
130130 9:45:29 InnoDB: O_DIRECT is known to result in 'Invalid argument' on Linux on tmpfs, see MySQL Bug#26662
InnoDB: starting tracking changed pages from LSN 1597945
130130 9:45:29 InnoDB: Waiting for the background threads to start
130130 9:45:30 Percona XtraDB (http://
============
Roel Van de Paar (roel11) wrote : | #12 |
ssd, ext4 with Block size: 4096 | Fragment size: 4096
Output alignment is not an issue, at least not in this case, as the offset 0 aligns to everything. Need to align the memory block used for output.
Roel Van de Paar (roel11) wrote : | #14 |
Interesting link by Raghu: http://
There are two separate issues here:
1) innodb_
2) innodb_
Roel Van de Paar (roel11) wrote : | #16 |
Roel Van de Paar (roel11) wrote : | #17 |
Roel Van de Paar (roel11) wrote : | #18 |
Two strace traces. Both were interrupted after some time (strace2 ran much longer - something in the area of 'hours') but it never seemed to finish completely. Command used:
[Roel@qaserver mysql-test]$ rm -Rf /tmp/test1; mkdir /tmp/test1/; strace -f /ssd/Percona-
-dir=/ssd/
One more code issue: a bitmap file is created/opened using either os_file_
After discussing with Alexey the conclusion is to not to open the bitmaps as data or log files, so that they ignore flush_method, by using os_*_simple() interface only. Then issue a posix_fadvice(
os_file_create() used OS_FILE_OVERWRITE, which is probably not what we want. Split off to bug 1111144.
tags: | added: xtradb |
Percona now uses JIRA for bug reports so this bug report is migrated to: https:/
For master_ 29_01_13_ 1.err : the command used (for reference) was:
# 2013-01-27T18:32:33 Starting: runall.pl --queries=100000000 --seed=random --duration=180 --querytimeout=60 --short_ column_ names --sqltrace --reporter= Shutdown, Backtrace, QueryTimeout, ErrorLog, ErrorLogAlarm --mysqld= --log-output= none --mysqld= --sql_mode= ONLY_FULL_ GROUP_BY --grammar= conf/percona_ qa/percona_ qa.yy --genda percona_ qa/percona_ qa.zz --basedir= /ssd/Percona- Server- 5.5.28- rel29.3- 416-debug. Linux.x86_ 64 --threads=25 --notnull --validator= Transformer --mysqld= --innodb_ track_changed_ pages=1 --mysqld= --innodb_ max_bitmap_ file_size= 4096 --mysqld= --innodb_ flush_method= O_DIRECT --mtr-build- thread= 306 --mask=43234 --vardir1= /ssd/832905/ current1_ 4
ta=conf/
MTR startup fails as per mysqld error log.