xtrabackup as SST fails when innodb_flush_method is O_DIRECT

Tested with http://sprunge.us/FAWW config and it works with O_DIRECT flush method.

Complete log: http://sprunge.us/eMZO

I also tested with ALL_O_DIRECT for the innodb_flush_method and it works.

The platform is CentOS 6.3

Now, 22 is "Invalid argument", so either the platform is old (and so doesn't support misaligned O_DIRECT if any) or the filesystem doesn't support it (tmpfs etc.).

Yes I tested on other system and it works too, so currently I've this only on one system, where xtrabackup fails when using O_DIRECT and it seems mysqld doesn't even start when using ALL_O_DIRECT.

Got today again the same problem on another system, same workaround fixed it:

120928 04:48:05 innobackupex: Starting ibbackup with command: xtrabackup_55 --defaults-file="/etc/my.cnf" --defaults-group="mysqld" --prepare --target-dir=/var/lib/mysql

xtrabackup_55 version 2.0.1 for Percona Server 5.5.16 Linux (x86_64) (revision id: 446)
xtrabackup: cd to /var/lib/mysql
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=(7820822299761)
xtrabackup: Temporary instance for recovery is set as followings.
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:128M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 2097152
120928 4:48:05 InnoDB: Using Linux native AIO
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
120928 4:48:05 InnoDB: The InnoDB memory heap is disabled
120928 4:48:05 InnoDB: Mutexes and rw_locks use GCC atomic builtins
120928 4:48:05 InnoDB: Compressed tables use zlib 1.2.3
120928 4:48:05 InnoDB: Using Linux native AIO
120928 4:48:05 InnoDB: Warning: innodb_file_io_threads is deprecated. Please use innodb_read_io_threads and innodb_write_io_threads instead
120928 4:48:05 InnoDB: Initializing buffer pool, size = 100.0M
120928 4:48:05 InnoDB: Completed initialization of buffer pool
120928 4:48:05 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 7820822299761
120928 4:48:05 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Doing recovery: scanned up to log sequence number 7820822363128 (3 %)
120928 4:48:05 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 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 56157731, file name /var/lib/mysql/mysql-bin.000773
120928 4:48:06 InnoDB: Waiting for the background threads to start
120928 4:48:07 Percona XtraDB (http://www.percona.com) 1.1.8-20.1 started; log sequence number 7820822363128

[notice (again)]
  If you use binary log and don't use any hack of group commit,
  the binary log position seems to be:
InnoDB: Last MySQL binlog file position 0 56157731, file name /var/lib/mysql/mysql-bin.000773

xtrabackup: starting shutdown with innodb_fast_shutdown = 1
120928 4:48:14 InnoDB: Starting shutdown...
120928 4:48:16 InnoDB: Shutdown completed; log sequence number 7820822363128
InnoDB: Error: tried to read 2048 bytes at offset 0 0.
InnoDB: Was only able to read 0.
120928 4:48:16 InnoDB: Operating system error number 22 in a file operation.
InnoDB: Error number 22 means 'Invalid argument'.
InnoDB: Some ope...

[Expired for Percona XtraDB Cluster because there has been no activity for 60 days.]

New machine same issue :

121211 13:33:31 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 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 678533168, file name logs/binlogs/dbOffice1-bin.000004
121211 13:33:32 InnoDB: Waiting for the background threads to start
121211 13:33:33 Percona XtraDB (http://www.percona.com) 1.1.8-20.1 started; log sequence number 193351509856

[notice (again)]
  If you use binary log and don't use any hack of group commit,
  the binary log position seems to be:
InnoDB: Last MySQL binlog file position 0 678533168, file name logs/binlogs/dbOffice1-bin.000004

xtrabackup: starting shutdown with innodb_fast_shutdown = 1
121211 13:33:38 InnoDB: Starting shutdown...
121211 13:33:42 InnoDB: Shutdown completed; log sequence number 193351515201
InnoDB: Error: tried to read 2048 bytes at offset 0 0.
InnoDB: Was only able to read 0.
121211 13:33:42 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: File operation call: 'read'.
InnoDB: Cannot continue operation.
innobackupex: Error:
innobackupex: ibbackup failed at /usr//bin/innobackupex line 378.

For info, these are the mount options:

/dev/sda1 /mysql/data xfs rw,noatime,nodiratime,attr2,delaylog,nobarrier,sunit=256,swidth=1280,noquota 0 0

OS info:

Distributor ID: Ubuntu
Description: Ubuntu 12.04.1 LTS
Release: 12.04
Codename: precise

Fred,

What about just xtrabackup backup ?
Does it work ?

I wonder if this is a xtrabackup bug.

Same server referenced by Frederic, (#29974) - it worked with xtrabackup manually but not with with SST script. Could be a variable present on SST.

Wrote too soon, after an upgrade to PXC 5.5.29-23.7.3 and xtrabackup 2.0.5 the workaround did not work anymore. FWIW, this server is using Fusion-IO.

I set this to Incomplete as I still have no clear understanding how to repeat this issue.

I use
innodb_flush_method = O_DIRECT all time
and I have never had problems with xtrabackup_SST.

It feels it somehow related to XFS alignment and/or Fusion-io.
I also added this bug to XtraBackup projects, as it seems it is more bug on xtrabackup side.

According to

Usage: [xtrabackup_55 [--defaults-file=#] --backup | xtrabackup_55 [--defaults-file=#] --prepare] [OPTIONS]

Default options are read from the following files in the given order:
/etc/my.cnf /etc/mysql/my.cnf /usr/local/mysql/etc/my.cnf ~/.my.cnf
The following groups are read: mysqld xtrabackup
The following options may be given as the first argument:
...
  --innodb-flush-method=name
                      With which method to flush data.
...

it is possible to override innodb_flush_method given to xtrabackup in my.cnf without actually messing with my.cnf perhaps innobackupex should call xtrabackup with a --innodb-flush-method set independently of my.cnf?

xtrabackup must use the same innodb_flush_method value on --backup, because direct and buffered I/O on the same file is a very bad idea according to kernel developers.

There's are no strict requirements to use O_DIRECT on --prepare. However, the problem here appears to be the following code in xtrabackup_close_temp_log():

 log_buf_ = static_cast<byte *>(ut_malloc(LOG_FILE_HDR_SIZE * 2));
 log_buf = static_cast<byte *>(ut_align(log_buf_, LOG_FILE_HDR_SIZE));

 success = os_file_read(src_file, log_buf, 0, 0, LOG_FILE_HDR_SIZE);

It aligns the buffer to LOG_FILE_HDR_SIZE (2048 bytes) which is wrong. Using UNIV_PAGE_SIZE_MAX as done in other code parts should fix this.

I was not able to reproduce this issue either. But, incidence of
this depends on specific combination(s) of filesystem, distro/kernel, media which is why it didn't occur as often. Not all filesystems (and versions of them) accept unaligned DIO in the same way.

Marked as 'fix released' since xtrabackup 2.0.6 has been released.

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

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