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

[Roel Van de Paar]

$ rm -Rf /tmp/test1; mkdir /tmp/test1/; /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
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_log_1_0.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
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://dev.mysql.com/doc/refman/5.5/en/operating-system-error-codes.html
InnoDB: Error: failed writing changed page bitmap file './ib_modified_log_1_0.xdb'
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://www.percona.com) 1.1.8-rel29.3 started; log sequence number 0
130126 15:34:08 [Warning] /ssd/Percona-Server-5.5.28-rel29.3-416-debug.Linux.x86_64/bin/mysqld: unknown option '--loose-skip-ndbcluster'

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

[Roel Van de Paar (roel11)]

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.

[Raghavendra D Prabhu (raghavendra-prabhu)]

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.

[Laurynas Biveinis (laurynas-biveinis)]

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;

[Laurynas Biveinis (laurynas-biveinis)]

Error log for the (passing) MTR testcase.

[Roel Van de Paar (roel11)]

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

[Roel Van de Paar (roel11)]

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)]

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?

[Roel Van de Paar (roel11)]

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.

[Alexey Kopytov (akopytov)]

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)]

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'
=============

[Roel Van de Paar (roel11)]

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
============

[Roel Van de Paar (roel11)]

ssd, ext4 with Block size: 4096 | Fragment size: 4096

[Laurynas Biveinis (laurynas-biveinis)]

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)]

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

[Laurynas Biveinis (laurynas-biveinis)]

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.

[Roel Van de Paar (roel11)]

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

[Laurynas Biveinis (laurynas-biveinis)]

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.

[Laurynas Biveinis (laurynas-biveinis)]

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