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

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
ta=conf/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

MTR startup fails as per mysqld error log.

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_log_block_size=4096) can be used here.

Related to http://bugs.mysql.com/bug.php?id=26662.

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_changed_page_bmp_flush_direct-master.opt:
--innodb-track-changed-pages=1 --innodb_flush_method=O_DIRECT

percona_changed_page_bmp_flush_direct.test:
--source include/not_windows.inc
--source include/have_innodb.inc

--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/restart_mysqld.inc

file_exists $MYSQLD_DATADIR/ib_modified_log_1_0.xdb;

DROP TABLE t1;

Error log for the (passing) MTR testcase.

Laurynas, I am no expert in creating MTR testcases, but:

[Roel@qaserver mysql-test]$ pwd
/ssd/Percona-Server-5.5.28-rel29.3-416-debug.Linux.x86_64/mysql-test

[Roel@qaserver mysql-test]$ ./mysql-test-run.pl --mysqld="--innodb_flush_method=O_DIRECT" --mysqld="--innodb_track_changed_pages=1" 1st.test > out.txt 2>&1

[Roel@qaserver mysql-test]$ cat out.txt | grep "Error:"
130130 8:27:22 InnoDB: Error: Write to file ./ib_modified_log_2_8204.xdb failed at offset 0 0.
InnoDB: Error: failed writing changed page bitmap file './ib_modified_log_2_8204.xdb'

[Roel@qaserver mysql-test]$ find . | grep ib_modified_log_2_8204.xdb
./var/log/main.1st/mysqld.1/data/ib_modified_log_2_8204.xdb

130129 15:30:42 InnoDB: O_DIRECT is known to result in 'Invalid argument' on Linux on tmpfs, see MySQL Bug#26662

tmpfs... ?

There is also another issue of interest in there:

130129 15:30:48 InnoDB: Failed to set O_DIRECT on file ./ib_modified_log_2_1600455.xdb: OVERWRITE: Invalid argument, continuing anyway

This may be another bug?

Laurynas, your testcase also fails for me (ssd + ext4)

[Roel@qaserver mysql-test]$ ./mysql-test-run percona_changed_page_bmp_flush_direct.test > out.txt 2>&1
[Roel@qaserver mysql-test]$ grep -i "error" out.txt
130130 8:35:29 InnoDB: Error: Write to file ./ib_modified_log_1_0.xdb failed at offset 0 0.

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.

With --mysqld=--innodb_log_block_size=4096:

=============
InnoDB: Warning: innodb_log_block_size has been changed from default value 512. (###EXPERIMENTAL### operation)
InnoDB: The log block size is set to 4096.
[...]
InnoDB: last tracked LSN in './ib_modified_log_2_65548.xdb' is 65548, but the last checkpoint LSN is 1611657. This might be due to a server crash or a very fas
t shutdown. Reading the log to advance the last tracked LSN.
130130 9:32:57 InnoDB: Error: Write to file ./ib_modified_log_2_65548.xdb failed at offset 0 0.
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://dev.mysql.com/doc/refman/5.5/en/operating-system-error-codes.html
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://dev.mysql.com/doc/refman/5.5/en/operating-system-error-codes.html
InnoDB: Error: failed writing changed page bitmap file './ib_modified_log_2_65548.xdb'
=============

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_log_2_1597945.xdb: OVERWRITE: 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
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://www.percona.com) 1.1.8-rel29.3 started; log sequence number 1597945
============

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.

Interesting link by Raghu: http://www.alexonlinux.com/direct-io-in-python

There are two separate issues here:
1) innodb_flush_method=O_DIRECT should not make bitmap files O_DIRECT;
2) innodb_flush_method=ALL_O_DIRECT should work with bitmap files.

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-Server-5.5.28-rel29.3-416-debug.Linux.x86_64/bin/mysqld --no-defaults --bootstrap --basedir=/ssd/Percona-Server-5.5.28-rel29.3-416-debug.Linux.x86_64 --datadir=/tmp/test1 --loose-skip-ndbcluster --tmpdir=. --core-file --lc-messages
-dir=/ssd/Percona-Server-5.5.28-rel29.3-416-debug.Linux.x86_64/share --character-sets-dir=/ssd/Percona-Server-5.5.28-rel29.3-416-debug.Linux.x86_64/share/charsets --innodb_track_changed_pages=1 --innodb_flush_method=O_DIRECT > out2.txt 2>&1

One more code issue: a bitmap file is created/opened using either os_file_create_simple() during startup , either os_file_create() during rotate. This results in selective flush_method honoring.

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(DONTNEED) after a block write.

os_file_create() used OS_FILE_OVERWRITE, which is probably not what we want. Split off to bug 1111144.

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-622