search

datto / dattobd

kernel module for taking block-level snapshots and incremental backups of Linux block devices
GNU General Public License v2.0
576 stars 122 forks source link

CFQ: Snapshot floods dmesg: "request aux data allocation failed" #6

Open crawfxrd opened 9 years ago

crawfxrd commented 9 years ago

Taking a snapshot when using CFQ will flood dmesg with the following line:

__get_request: dev 8:0: request aux data allocation failed, iosched may be disturbed

This appears to only happens on partitions (/dev/sda2); I do not see the issue with dm volumes (/dev/mapper/centos-root).

Steps to reproduce:

echo cfq > /sys/block/sda/queue/scheduler
dbdctl setup-snapshot /dev/sda1 /cow.snap 1
dd if=/dev/urandom of=/urand bs=1M count=32
sync
jarun commented 9 years ago

is it possible that the root cause is Ubuntu and Fedora using different I/O schedulers? Ubuntu uses "deadline" and Fedora uses "cfq".

I tried with Fedora 22 Virtual Machine (I noticed Fedora 20 is mentioned in issue report. Will try that as well.) but I couldn't reproduce the issue. However, from the code it seems memory constraint might be an issue too:

fail_elvpriv:  
        /*  
         * elvpriv init failed.  ioc, icq and elvpriv aren't mempool backed  
         * and may fail indefinitely under memory pressure and thus  
         * shouldn't stall IO.  Treat this request as !elvpriv.  This will  
         * disturb iosched and blkcg but weird is bettern than dead.  
         */
crawfxrd commented 9 years ago

Would you happen to be using LVM? My VMs are setup to use standard partitioning, which is where I see this issue (including Fedora 22), but I noticed when testing a RAID0 setup of Fedora 22 this message was not getting printed.

jarun commented 9 years ago

I am using RAID0, external hard disk connected via USB. The hard disk is connected to the guest VM running Fedora 22. The hard disk has 2 partitions setup in RAID0. RAID0 has ext4 and the volume starts at sector 63.

Are you suggesting that I add 2 more partitions directly on the Fedora 22 VM's virtual disk and set up these 2 new partitions (on the virtual disk) as RAID0?

crawfxrd commented 9 years ago

A VM with standard partitioning. For example, here is my setup on a 16G disk.

[root@fed-22-srv-std ~]# lsblk
NAME   MAJ:MIN RM  SIZE RO TYPE MOUNTPOINT
sda      8:0    0   16G  0 disk 
├─sda1   8:1    0  500M  0 part /boot
├─sda2   8:2    0    8G  0 part /
├─sda3   8:3    0    2G  0 part [SWAP]
├─sda4   8:4    0    1K  0 part 
└─sda5   8:5    0  5.5G  0 part /home
sr0     11:0    1 1024M  0 rom
jarun commented 9 years ago

OK. Got it. I will snapshot on a similar setup for reproduction.

crawfxrd commented 9 years ago

You were right about the schedulers. Setting the scheduler on Fedora to deadline causes this issue to go away. Setting it to cfq on Ubuntu causes the issue to appear.

jarun commented 9 years ago

Cool! I'll look into the cause and fix.

jarun commented 8 years ago

I didn't find time to investigate further on this one. Working on another bug and have some personal priorities right now. If interested, feel free to pick it up.

tcaputi commented 8 years ago

We're should be looking more at this (as well as newer kernel compatibility and the fix you submitted) within 2 weeks or so. Thank you so much for the help.

On Wed, Jan 13, 2016 at 1:02 AM, Arun Prakash Jana <notifications@github.com

wrote:

I didn't find time to investigate further on this one. Working on another bug and have some personal priorities right now. If interested, feel free to pick it up.

— Reply to this email directly or view it on GitHub https://github.com/datto/dattobd/issues/6#issuecomment-171179302.

XeJames commented 6 years ago

Any update on this? I am having the same problem on Deb 9 with cfq.

crawfxrd commented 6 years ago

We never found the cause of this, and because there has been no data corruption in relation to it we have not given it any priority.

emmeowzing commented 5 years ago

I'm seeing the same issue in my system.

Nov 29 22:16:09 brandon-AB350-Gaming-3 kernel: [ 1256.696706] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:16:09 brandon-AB350-Gaming-3 kernel: [ 1256.696695] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:16:09 brandon-AB350-Gaming-3 kernel: [ 1256.696684] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:16:09 brandon-AB350-Gaming-3 kernel: [ 1256.696673] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:16:09 brandon-AB350-Gaming-3 kernel: [ 1256.696655] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:16:09 brandon-AB350-Gaming-3 kernel: [ 1256.696452] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:16:09 brandon-AB350-Gaming-3 kernel: [ 1256.696449] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:16:09 brandon-AB350-Gaming-3 kernel: [ 1256.696447] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:16:09 brandon-AB350-Gaming-3 kernel: [ 1256.696442] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:16:09 brandon-AB350-Gaming-3 kernel: [ 1256.696264] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:16:09 brandon-AB350-Gaming-3 kernel: [ 1256.696262] __get_request: 3 callbacks suppressed
Nov 29 22:16:04 brandon-AB350-Gaming-3 kernel: [ 1251.576778] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:16:04 brandon-AB350-Gaming-3 kernel: [ 1251.576774] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:16:04 brandon-AB350-Gaming-3 kernel: [ 1251.576770] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:16:04 brandon-AB350-Gaming-3 kernel: [ 1251.576766] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:16:04 brandon-AB350-Gaming-3 kernel: [ 1251.576762] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:16:04 brandon-AB350-Gaming-3 kernel: [ 1251.576757] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:16:04 brandon-AB350-Gaming-3 kernel: [ 1251.576753] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:16:04 brandon-AB350-Gaming-3 kernel: [ 1251.576748] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:16:04 brandon-AB350-Gaming-3 kernel: [ 1251.576739] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:16:04 brandon-AB350-Gaming-3 kernel: [ 1251.576535] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:16:04 brandon-AB350-Gaming-3 kernel: [ 1251.576533] __get_request: 57 callbacks suppressed
Nov 29 22:15:59 brandon-AB350-Gaming-3 kernel: [ 1246.456298] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:59 brandon-AB350-Gaming-3 kernel: [ 1246.456240] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:59 brandon-AB350-Gaming-3 kernel: [ 1246.456238] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:59 brandon-AB350-Gaming-3 kernel: [ 1246.456236] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:59 brandon-AB350-Gaming-3 kernel: [ 1246.456233] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:59 brandon-AB350-Gaming-3 kernel: [ 1246.456230] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:59 brandon-AB350-Gaming-3 kernel: [ 1246.456225] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:59 brandon-AB350-Gaming-3 kernel: [ 1246.456121] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:59 brandon-AB350-Gaming-3 kernel: [ 1246.456112] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:59 brandon-AB350-Gaming-3 kernel: [ 1246.456017] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:59 brandon-AB350-Gaming-3 kernel: [ 1246.456016] __get_request: 1 callbacks suppressed
Nov 29 22:15:53 brandon-AB350-Gaming-3 kernel: [ 1241.335628] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:53 brandon-AB350-Gaming-3 kernel: [ 1241.335624] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:53 brandon-AB350-Gaming-3 kernel: [ 1241.335619] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:53 brandon-AB350-Gaming-3 kernel: [ 1241.335612] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:53 brandon-AB350-Gaming-3 kernel: [ 1241.335608] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:53 brandon-AB350-Gaming-3 kernel: [ 1241.335604] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:53 brandon-AB350-Gaming-3 kernel: [ 1241.335600] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:53 brandon-AB350-Gaming-3 kernel: [ 1241.335595] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:53 brandon-AB350-Gaming-3 kernel: [ 1241.335589] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:53 brandon-AB350-Gaming-3 kernel: [ 1241.335393] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:53 brandon-AB350-Gaming-3 kernel: [ 1241.335391] __get_request: 3 callbacks suppressed
Nov 29 22:15:48 brandon-AB350-Gaming-3 kernel: [ 1236.217898] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:48 brandon-AB350-Gaming-3 kernel: [ 1236.217894] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:48 brandon-AB350-Gaming-3 kernel: [ 1236.217887] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:48 brandon-AB350-Gaming-3 kernel: [ 1236.217883] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:48 brandon-AB350-Gaming-3 kernel: [ 1236.217879] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:48 brandon-AB350-Gaming-3 kernel: [ 1236.217875] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:48 brandon-AB350-Gaming-3 kernel: [ 1236.217871] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:48 brandon-AB350-Gaming-3 kernel: [ 1236.217861] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed
Nov 29 22:15:48 brandon-AB350-Gaming-3 kernel: [ 1236.217418] __get_request: dev 8:48: request aux data allocation failed, iosched may be disturbed

My /var/log/syslog is loaded with these messages. dlad version 1.0.16.

brandon@brandon-AB350-Gaming-3:~$ sudo dlad --help
dlad version 1.0.16

System info:

brandon@brandon-AB350-Gaming-3:~$ uname -a
Linux brandon-AB350-Gaming-3 4.15.0-39-generic #42-Ubuntu SMP Tue Oct 23 15:48:01 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

Ubuntu 18.