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

[crawfxrd]

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]

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]

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]

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]

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]

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

[crawfxrd]

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]

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

[jarun]

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]

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 <[email protected]

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]

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

[crawfxrd]

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]

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.