linux + o_direct + stream backup = broken?

We also experience this bug

Also using O_DIRECT with innodb_flush_log_at_trx_commit=2

With the following command
innobackupex-1.5.1 --slave-info --stream=tar . 2> /tmp/$source.xtrabackup.log| gzip - | nc -vw60 $target $port

Sample output from /var/log/messages

[6896419.396214] ------------[ cut here ]------------
[6896419.396214] WARNING: at fs/xfs/linux-2.6/xfs_lrw.c:726 xfs_write+0x3f5/0x722 [xfs]()
[6896419.396214] Modules linked in: ipv6 xfs loop snd_pcm snd_timer snd soundcore snd_page_alloc i2c_i801 psmouse pcspkr i2c_core serio_raw button joydev evdev ext3 jbd mbcache dm_mirror dm_log dm_snapshot dm_mod raid1 raid0 md_mod sd_mod sg sr_mod cdrom usbhid hid ff_memless mptsas mptscsih mptbase ahci scsi_transport_sas libata scsi_mod dock ehci_hcd uhci_hcd igb thermal processor fan thermal_sys [last unloaded: scsi_wait_scan]
[6896419.396214] Pid: 6909, comm: mysqld Tainted: G W 2.6.26-2-amd64 #1
[6896419.396214]
[6896419.396214] Call Trace:
[6896419.396214] [<ffffffff80234930>] warn_on_slowpath+0x51/0x7a
[6896419.396214] [<ffffffff80231997>] check_preempt_wakeup+0xc4/0xf0
[6896419.396214] [<ffffffff8022c157>] try_to_wake_up+0x118/0x129
[6896419.396214] [<ffffffff8031e230>] __up_write+0x82/0x10e
[6896419.396214] [<ffffffffa022ec68>] :xfs:xfs_iunlock+0x42/0x7c
[6896419.396214] [<ffffffffa02526cc>] :xfs:xfs_write+0x3f5/0x722
[6896419.396214] [<ffffffff802483e0>] enqueue_hrtimer+0xd7/0xe4
[6896419.396223] [<ffffffff8029ae83>] do_sync_write+0xc9/0x10c
[6896419.396231] [<ffffffff80246171>] autoremove_wake_function+0x0/0x2e
[6896419.396236] [<ffffffff8029b62d>] vfs_write+0xad/0x156
[6896419.396236] [<ffffffff8029c2ee>] fget_light+0x4f/0x82
[6896419.396236] [<ffffffff8029bcb8>] sys_pwrite64+0x50/0x70
[6896419.396236] [<ffffffff8020c267>] ptregscall_common+0x67/0xb0
[6896419.396236] [<ffffffff8020beda>] system_call_after_swapgs+0x8a/0x8f
[6896419.396236]

Andrew,

Does it cause any problems for you (like crash) ? From the trace it looks
like it is warning on "slowpath"
I'm sure it does not look nice and it would be great if XFS guys fix it.
If it can cause kernel crash
it is even more issue as this means plain user could crash server by opening
same file with O_DIRECT and without
and stressing it with IO.

On Thu, Jul 29, 2010 at 4:33 PM, Andrew Platts <email address hidden>wrote:

> We also experience this bug
>
> Also using O_DIRECT with innodb_flush_log_at_trx_commit=2
>
> With the following command
> innobackupex-1.5.1 --slave-info --stream=tar . 2>
> /tmp/$source.xtrabackup.log| gzip - | nc -vw60 $target $port
>
> Sample output from /var/log/messages
>
>
> [6896419.396214] ------------[ cut here ]------------
> [6896419.396214] WARNING: at fs/xfs/linux-2.6/xfs_lrw.c:726
> xfs_write+0x3f5/0x722 [xfs]()
> [6896419.396214] Modules linked in: ipv6 xfs loop snd_pcm snd_timer snd
> soundcore snd_page_alloc i2c_i801 psmouse pcspkr i2c_core serio_raw button
> joydev evdev ext3 jbd mbcache dm_mirror dm_log dm_snapshot dm_mod raid1
> raid0 md_mod sd_mod sg sr_mod cdrom usbhid hid ff_memless mptsas mptscsih
> mptbase ahci scsi_transport_sas libata scsi_mod dock ehci_hcd uhci_hcd igb
> thermal processor fan thermal_sys [last unloaded: scsi_wait_scan]
> [6896419.396214] Pid: 6909, comm: mysqld Tainted: G W 2.6.26-2-amd64
> #1
> [6896419.396214]
> [6896419.396214] Call Trace:
> [6896419.396214] [<ffffffff80234930>] warn_on_slowpath+0x51/0x7a
> [6896419.396214] [<ffffffff80231997>] check_preempt_wakeup+0xc4/0xf0
> [6896419.396214] [<ffffffff8022c157>] try_to_wake_up+0x118/0x129
> [6896419.396214] [<ffffffff8031e230>] __up_write+0x82/0x10e
> [6896419.396214] [<ffffffffa022ec68>] :xfs:xfs_iunlock+0x42/0x7c
> [6896419.396214] [<ffffffffa02526cc>] :xfs:xfs_write+0x3f5/0x722
> [6896419.396214] [<ffffffff802483e0>] enqueue_hrtimer+0xd7/0xe4
> [6896419.396223] [<ffffffff8029ae83>] do_sync_write+0xc9/0x10c
> [6896419.396231] [<ffffffff80246171>] autoremove_wake_function+0x0/0x2e
> [6896419.396236] [<ffffffff8029b62d>] vfs_write+0xad/0x156
> [6896419.396236] [<ffffffff8029c2ee>] fget_light+0x4f/0x82
> [6896419.396236] [<ffffffff8029bcb8>] sys_pwrite64+0x50/0x70
> [6896419.396236] [<ffffffff8020c267>] ptregscall_common+0x67/0xb0
> [6896419.396236] [<ffffffff8020beda>] system_call_after_swapgs+0x8a/0x8f
> [6896419.396236]
>
> --
> linux + o_direct + stream backup = broken?
> https://bugs.launchpad.net/bugs/606981
> You received this bug notification because you are a member of Percona
> developers, which is the registrant for Percona-XtraBackup.
>
> Status in Open source backup tool for InnoDB and XtraDB: New
>
> Bug description:
> I'm running mysql-5.0.90, xtrabackup 1.2, and have the following two
> options set relating to innodb flushing:
>
> innodb_flush_log_at_trx_commit=2
> innodb_flush_method=O_DIRECT
>
> Every time we run a (streaming) backup, we see many instances of
>
> [170371.562926] ------------[ cut here ]------------
> [170371.562930] WARNING: at fs/xfs/linux-2.6/xfs_lrw.c:651
> xfs_write+0x3dc/0x784()
> [170371.562931] Hardware name: PowerEdge R710
> [170371.56293...

Well,

what we see is the slave lag exceeds our threshold during backups (causing MMM to take action) . So I believe we're getting a filesystem hang as the first bug reporter mentioned. This happens just prior to the call trace. Also very simple PK queries start taking over 30 secs.

This is debian 5.0.4 with xfs (Linux 2.6.26-2-amd64 #1 SMP Wed May 12 18:03:14 UTC 2010 x86_64 GNU/Linux)

I see from the link below that this is not something the file system guys think is their problem

http://oss.sgi.com/archives/xfs/2010-07/msg00184.html

Dave Chinner says :
"Right now I'm not particularly inclined to dig into this further;
it's obvious the applications are doing something that is not
supported (by XFS or the generic page cache code), so this is the
first thing you really need to care about getting fixed if you value
your backups..."

The alternative right now for us might be to turn O_DIRECT off - we're using SSDs , not sure if O_DIRECT will have a hugh impact in this case ...

Andrew,

Thanks. This is helpful information.

As I understand the XFS guys would rather get some test case which may be
helpful
We also should see what can be done with Xtrabackup so it uses DIRECT_IO for
copy
so things are consistent.

On Thu, Jul 29, 2010 at 5:52 PM, Andrew Platts <email address hidden>wrote:

> Well,
>
> what we see is the slave lag exceeds our threshold during backups
> (causing MMM to take action) . So I believe we're getting a
> filesystem hang as the first bug reporter mentioned. This happens
> just prior to the call trace. Also very simple PK queries start
> taking over 30 secs.
>
> This is debian 5.0.4 with xfs (Linux 2.6.26-2-amd64 #1 SMP Wed May 12
> 18:03:14 UTC 2010 x86_64 GNU/Linux)
>
> I see from the link below that this is not something the file
> system guys think is their problem
>
> http://oss.sgi.com/archives/xfs/2010-07/msg00184.html
>
>
> Dave Chinner says :
> "Right now I'm not particularly inclined to dig into this further;
> it's obvious the applications are doing something that is not
> supported (by XFS or the generic page cache code), so this is the
> first thing you really need to care about getting fixed if you value
> your backups..."
>
> The alternative right now for us might be to turn O_DIRECT off - we're
> using SSDs , not sure if O_DIRECT will have a hugh impact in this case
> ...
>
> --
> linux + o_direct + stream backup = broken?
> https://bugs.launchpad.net/bugs/606981
> You received this bug notification because you are a member of Percona
> developers, which is the registrant for Percona-XtraBackup.
>
> Status in Open source backup tool for InnoDB and XtraDB: New
>
> Bug description:
> I'm running mysql-5.0.90, xtrabackup 1.2, and have the following two
> options set relating to innodb flushing:
>
> innodb_flush_log_at_trx_commit=2
> innodb_flush_method=O_DIRECT
>
> Every time we run a (streaming) backup, we see many instances of
>
> [170371.562926] ------------[ cut here ]------------
> [170371.562930] WARNING: at fs/xfs/linux-2.6/xfs_lrw.c:651
> xfs_write+0x3dc/0x784()
> [170371.562931] Hardware name: PowerEdge R710
> [170371.562932] Modules linked in: cifs iTCO_wdt iTCO_vendor_support
> [170371.562936] Pid: 4322, comm: mysqld Tainted: G W
> 2.6.33-gentoo-r2 #1
> [170371.562937] Call Trace:
> [170371.562940] [<ffffffff8120da46>] ? xfs_write+0x3dc/0x784
> [170371.562943] [<ffffffff81038733>] warn_slowpath_common+0x77/0xa4
> [170371.562945] [<ffffffff8103876f>] warn_slowpath_null+0xf/0x11
> [170371.562947] [<ffffffff8120da46>] xfs_write+0x3dc/0x784
> [170371.562950] [<ffffffff81034825>] ? wake_up_state+0xb/0xd
> [170371.562953] [<ffffffff8120a51a>] xfs_file_aio_write+0x5a/0x5c
> [170371.562955] [<ffffffff810d7cbe>] do_sync_write+0xc0/0x106
> [170371.562959] [<ffffffff810d8624>] vfs_write+0xab/0x105
> [170371.562962] [<ffffffff810d86da>] sys_pwrite64+0x5c/0x7d
> [170371.562966] [<ffffffff81002a6b>] system_call_fastpath+0x16/0x1b
> [170371.562969] ---[ end trace 915525cd726ee99f ]---
>
> in the logs.
>
> The XFS guys say that this is a warning about bad O_DIRECT + not O_DIRECT
> interactions:
>
> http://lkml.org/lkml/2010/5/23/50 [The thread ...

We've also been seeing this exact same "BUG" message logged. After some hair pulling we were able to track it down to xtrabackup with --stream=tar mode. I think the tar-streaming mode is fundamentally broken due to this. Maybe it was the original cause of the corruption complaints which triggered the creation of tar4ibd as well? Mixing of direct (InnoDB) and buffered (tar) IO is always dangerous.

Peter: How hard would it be to add support to tar4ibd to use O_DIRECT if InnoDB is configured for it (which you already know from the rest of the configuration). It seems like this would be the best solution, and I don't think it would require much work.

Jeremy,

Yes I think this is what we should look into doing. I also do not think it
will be hard work.

We want to work around this issue on our side - absolutely but It is also
good if this problem is fixed on XFS
side... as it is general issue which can be triggered by other apps.

On Fri, Jul 30, 2010 at 6:58 PM, Jeremy Cole <email address hidden>wrote:

> We've also been seeing this exact same "BUG" message logged. After some
> hair pulling we were able to track it down to xtrabackup with
> --stream=tar mode. I think the tar-streaming mode is fundamentally
> broken due to this. Maybe it was the original cause of the corruption
> complaints which triggered the creation of tar4ibd as well? Mixing of
> direct (InnoDB) and buffered (tar) IO is always dangerous.
>
> Peter: How hard would it be to add support to tar4ibd to use O_DIRECT if
> InnoDB is configured for it (which you already know from the rest of the
> configuration). It seems like this would be the best solution, and I
> don't think it would require much work.
>
> --
> linux + o_direct + stream backup = broken?
> https://bugs.launchpad.net/bugs/606981
> You received this bug notification because you are a member of Percona
> developers, which is the registrant for Percona-XtraBackup.
>
> Status in Open source backup tool for InnoDB and XtraDB: New
>
> Bug description:
> I'm running mysql-5.0.90, xtrabackup 1.2, and have the following two
> options set relating to innodb flushing:
>
> innodb_flush_log_at_trx_commit=2
> innodb_flush_method=O_DIRECT
>
> Every time we run a (streaming) backup, we see many instances of
>
> [170371.562926] ------------[ cut here ]------------
> [170371.562930] WARNING: at fs/xfs/linux-2.6/xfs_lrw.c:651
> xfs_write+0x3dc/0x784()
> [170371.562931] Hardware name: PowerEdge R710
> [170371.562932] Modules linked in: cifs iTCO_wdt iTCO_vendor_support
> [170371.562936] Pid: 4322, comm: mysqld Tainted: G W
> 2.6.33-gentoo-r2 #1
> [170371.562937] Call Trace:
> [170371.562940] [<ffffffff8120da46>] ? xfs_write+0x3dc/0x784
> [170371.562943] [<ffffffff81038733>] warn_slowpath_common+0x77/0xa4
> [170371.562945] [<ffffffff8103876f>] warn_slowpath_null+0xf/0x11
> [170371.562947] [<ffffffff8120da46>] xfs_write+0x3dc/0x784
> [170371.562950] [<ffffffff81034825>] ? wake_up_state+0xb/0xd
> [170371.562953] [<ffffffff8120a51a>] xfs_file_aio_write+0x5a/0x5c
> [170371.562955] [<ffffffff810d7cbe>] do_sync_write+0xc0/0x106
> [170371.562959] [<ffffffff810d8624>] vfs_write+0xab/0x105
> [170371.562962] [<ffffffff810d86da>] sys_pwrite64+0x5c/0x7d
> [170371.562966] [<ffffffff81002a6b>] system_call_fastpath+0x16/0x1b
> [170371.562969] ---[ end trace 915525cd726ee99f ]---
>
> in the logs.
>
> The XFS guys say that this is a warning about bad O_DIRECT + not O_DIRECT
> interactions:
>
> http://lkml.org/lkml/2010/5/23/50 [The thread was started by someone else
> seeing the same warning, but I joined in later]
>
> Also, we had a filesystem hang, which was suggested to have been caused by
> this same problem:
>
> http://oss.sgi.com/archives/xfs/2010-07/msg00163.html
>
> Basically they claim that xtrabackup/tar4ibd is doing something that can
> break on any linux filesy...

I'm pretty sure that all the XFS devs are in agreement that fixing the hang is something that needs to be done. I brought up removing the warning earlier on LKML, and at least Dave Chinner's position was that it was best left in. [Not sure if Andrew Platts's warning is the same as mine, as it comes from a considerably older kernel.]

However the claim that the XFS devs make is that mixing mysqld's O_DIRECT and the mechanism that tar4ibd uses to read the files in will result in inconsistent data being read in for any filesystem (and also exacerbates the XFS problem).

Ilia,

Thanks. I just have not understood this is the outcome of the discussion
on the XFS developers list. We will see to change tar4ibd to use same
IO mode as the MySQL running on files which is probably right solution

What is about in consistence - what kind of inconsistency one would observe
in this case ? Xtrabackup in general should be rather tolerant to it
(re-reading on bad
checksums)

On Sun, Aug 1, 2010 at 11:00 PM, Ilia Mirkin <email address hidden>wrote:

> I'm pretty sure that all the XFS devs are in agreement that fixing the
> hang is something that needs to be done. I brought up removing the
> warning earlier on LKML, and at least Dave Chinner's position was that
> it was best left in. [Not sure if Andrew Platts's warning is the same as
> mine, as it comes from a considerably older kernel.]
>
> However the claim that the XFS devs make is that mixing mysqld's
> O_DIRECT and the mechanism that tar4ibd uses to read the files in will
> result in inconsistent data being read in for any filesystem (and also
> exacerbates the XFS problem).
>
> --
> linux + o_direct + stream backup = broken?
> https://bugs.launchpad.net/bugs/606981
> You received this bug notification because you are a member of Percona
> developers, which is the registrant for Percona-XtraBackup.
>
> Status in Open source backup tool for InnoDB and XtraDB: New
>
> Bug description:
> I'm running mysql-5.0.90, xtrabackup 1.2, and have the following two
> options set relating to innodb flushing:
>
> innodb_flush_log_at_trx_commit=2
> innodb_flush_method=O_DIRECT
>
> Every time we run a (streaming) backup, we see many instances of
>
> [170371.562926] ------------[ cut here ]------------
> [170371.562930] WARNING: at fs/xfs/linux-2.6/xfs_lrw.c:651
> xfs_write+0x3dc/0x784()
> [170371.562931] Hardware name: PowerEdge R710
> [170371.562932] Modules linked in: cifs iTCO_wdt iTCO_vendor_support
> [170371.562936] Pid: 4322, comm: mysqld Tainted: G W
> 2.6.33-gentoo-r2 #1
> [170371.562937] Call Trace:
> [170371.562940] [<ffffffff8120da46>] ? xfs_write+0x3dc/0x784
> [170371.562943] [<ffffffff81038733>] warn_slowpath_common+0x77/0xa4
> [170371.562945] [<ffffffff8103876f>] warn_slowpath_null+0xf/0x11
> [170371.562947] [<ffffffff8120da46>] xfs_write+0x3dc/0x784
> [170371.562950] [<ffffffff81034825>] ? wake_up_state+0xb/0xd
> [170371.562953] [<ffffffff8120a51a>] xfs_file_aio_write+0x5a/0x5c
> [170371.562955] [<ffffffff810d7cbe>] do_sync_write+0xc0/0x106
> [170371.562959] [<ffffffff810d8624>] vfs_write+0xab/0x105
> [170371.562962] [<ffffffff810d86da>] sys_pwrite64+0x5c/0x7d
> [170371.562966] [<ffffffff81002a6b>] system_call_fastpath+0x16/0x1b
> [170371.562969] ---[ end trace 915525cd726ee99f ]---
>
> in the logs.
>
> The XFS guys say that this is a warning about bad O_DIRECT + not O_DIRECT
> interactions:
>
> http://lkml.org/lkml/2010/5/23/50 [The thread was started by someone else
> seeing the same warning, but I joined in later]
>
> Also, we had a filesystem hang, which was suggested to have been caused by
> this same problem:
>
> http://oss.sgi.com/archives/xfs/2010-07/msg00163.html
>
> Basically they claim that xtrabackup/tar4ibd is doing something that ...

Honestly, I don't fully understand the implications myself. Dave Chinner semi-describes this at http://lkml.org/lkml/2010/5/23/158 but I don't have any more specifics than that. FWIW I've never gotten a bad backup with xtrabackup yet.

not sure if there any actions needed. "Won't fix"

The action is to make tar4ibd read the ibd files with the same O_DIRECT'ness as the rest of the system.

Alternatively you could just mark xtrabackup to be incompatible with O_DIRECT.

The message from Dave Chinner (one of the XFS guys) is that simultaneous O_DIRECT + non-O_DIRECT access to a file on linux is disallowed (and XFS warns about it, most FS's don't). [Perhaps I can convince him to post something here as well that goes into more detail?]

ok, let's check if we can run tar4ibd with O_DIRECT

I just wanted to highlight this seems to be going beyond warnings but causing kernel to hang for some our customers.
We will see what can be done on Xtrabackup side but it is serious security issue if one can cause kernel to hang as a unprivileged
user by mixing o_direct and non_odirect IO on the same files. It is good if we can report it as a bug to XFS team

will it be fixed in 1.6? very good!! I hope it be fixed quickly

Alexey,

We need to make sure that tar4ibd is run in O_DIRECT mode.

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