Ceph » Linux kernel client

Hi,

We are experimenting exactly the same problem when running several concurrent dd operations to a kernel mounted rbd image.

We have tested ubuntu kernels 3.15.0 and 3.15.5 with same results. We have also updated all machines (OSDs, MONs and clients) to ceph to 0.80.4 but the error persists.

In our setup it's quite easy to reproduce the error, we just launch against the same rbd image 4 simultaneous instances of dd.

dd command line:

dd if=/dev/zero of=test-1 bs=64k count=160k conv=fdatasync &
dd if=/dev/zero of=test-2 bs=64k count=160k conv=fdatasync &
dd if=/dev/zero of=test-3 bs=64k count=160k conv=fdatasync &
dd if=/dev/zero of=test-4 bs=64k count=160k conv=fdatasync &

(Each file should create a 10gb file)

RBD image filesystem is ext4.

Thanks.

when this happens again, execute 'echo t > /proc/sysrq-trigger' and upload the kernel message.

By the way, are there the rbd clients and OSDs on the same machine?

Somone reported seeing this same issue in 3.15.2 but not in 3.13.7

Josh Durgin wrote:

Somone reported seeing this same issue in 3.15.2 but not in 3.13.7

Ubuntu Kernel 3.14.9 also works well. Issue seems to be introduced in 3.15.

We also confirmed the issue is with 3.15 above as we back rev'd our system to 3.14.13 and were able to successfully complete our tests.

I have been trying to reproduce this with both parallel dds and the attached script, but so far no luck. We've seen this deadlock before, but then it just stopped happening. The interesting observation is that the first occurrence coincided with the rebase of our testing branch to 3.15.

Xavier or Greg, do you have CONFIG_LOCKDEP enabled in your kernels?

OK, so lockdep is disabled. Since you are able to reproduce it so reliably, can you try our testing kernel? The package is at

http://gitbuilder.ceph.com/kernel-deb-precise-x86_64-basic/ref/testing/linux-image-3.16.0-rc4-ceph-00033-gf18244b_3.16.0-rc4-ceph-00033-gf18244b-1_amd64.deb

It's based on Ubuntu config, so you should be able to boot it.

Hi Ilya,

We used Ubuntu standard kernel as well, specifically:

http://kernel.ubuntu.com/~kernel-ppa/mainline/v3.15.5-utopic/linux-image-3.15.5-031505-generic_3.15.5-031505.201407091543_amd64.deb

Thanks.

Hi Ilya,

I can reliably reproduce the error when running this generic kernel with no changes:

http://kernel.ubuntu.com/~kernel-ppa/mainline/v3.16-rc4-utopic/linux-image-3.16.0-031600rc4-generic_3.16.0-031600rc4.201407061635_amd64.deb

It usually takes less than 15 minutes to hit the issue; even faster recently.

I downloaded and installed the ceph kernel you linked to and have been running it without a failure since Saturday night. It looks like whatever has been changed prevents the issue. I'm going to compare the differences between the config files but is there documentation on what changes exist between the generic and your ceph image?

I'm pretty sure it's the disabled lockdep that affects this. Our testing kernel is built with lockdep enabled, Ubuntu stock kernels - aren't. I'll try reproducing it some more and will get back to you tomorrow. Thanks for your help so far.

I can reproduce this with 100% certainty now on Trusty, 3.15.6-031506-generic.

Running:

bonnie++ -n 512

against a mounted rbd (OSDs on 3 other servers) that comprises 6 x SSD OSD. When it was 3 OSD in the pool it was okay, the move to 6 triggered it every time.

Anything we can do to help/test, let me know.

Update: At this point I'm almost certain this is not an rbd/ceph problem. Trying to track down the exact culprit.

All,

Can you try and confirm that deadlock-bad fails and deadlock-good works for you?

deadlock-bad:

http://gitbuilder.ceph.com/kernel-deb-precise-x86_64-basic/ref/deadlock-bad/linux-image-3.16.0-rc7-ceph-00100-g1e9afaa_3.16.0-rc7-ceph-00100-g1e9afaa-1_amd64.deb

deadlock-good:

http://gitbuilder.ceph.com/kernel-deb-precise-x86_64-basic/ref/deadlock-good/linux-image-3.16.0-rc7-ceph-00101-g0ccdc51_3.16.0-rc7-ceph-00101-g0ccdc51-1_amd64.deb

These are Ubuntu kernels with most of the drivers enabled.

The deadlock-bad kernel showed the error after a few minutes of running multiple dd writes to rbd device. Here is one of many entries in the /var/log/kern.log file:

Jul 30 22:07:16 t16 kernel: [ 601.225863] INFO: task kworker/7:7:1959 blocked for more than 120 seconds.
Jul 30 22:07:16 t16 kernel: [ 601.225926] Tainted: G E 3.16.0-rc7-ceph-00100-g1e9afaa #1
Jul 30 22:07:16 t16 kernel: [ 601.225988] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 30 22:07:16 t16 kernel: [ 601.226066] kworker/7:7 D 0000000000000000 0 1959 2 0x00000000
Jul 30 22:07:16 t16 kernel: [ 601.226074] Workqueue: ceph-msgr con_work [libceph]
Jul 30 22:07:16 t16 kernel: [ 601.226078] ffff8800318e7c18 0000000000000046 0000000000000000 0000000000000000
Jul 30 22:07:16 t16 kernel: [ 601.226086] ffff8800368cb240 0000000000012fc0 ffff8800318e7fd8 0000000000012fc0
Jul 30 22:07:16 t16 kernel: [ 601.226087] ffff88007c0e9920 ffff8800368cb240 0000000000000000 ffff880036a1d7c8
Jul 30 22:07:16 t16 kernel: [ 601.226088] Call Trace:
Jul 30 22:07:16 t16 kernel: [ 601.226090] [<ffffffff816ba789>] schedule+0x29/0x70
Jul 30 22:07:16 t16 kernel: [ 601.226091] [<ffffffff816baa5e>] schedule_preempt_disabled+0xe/0x10
Jul 30 22:07:16 t16 kernel: [ 601.226093] [<ffffffff816bc4c3>] __mutex_lock_slowpath+0xd3/0x1c0
Jul 30 22:07:16 t16 kernel: [ 601.226094] [<ffffffff816bc5d3>] mutex_lock+0x23/0x37
Jul 30 22:07:16 t16 kernel: [ 601.226097] [<ffffffffa01fa88f>] alloc_msg+0xcf/0x230 [libceph]
Jul 30 22:07:16 t16 kernel: [ 601.226100] [<ffffffffa01f5fd6>] con_work+0x19d6/0x2020 [libceph]
Jul 30 22:07:16 t16 kernel: [ 601.226101] [<ffffffff81092c4c>] ? put_prev_entity+0x3c/0x320
Jul 30 22:07:16 t16 kernel: [ 601.226102] [<ffffffff81095c72>] ? pick_next_task_fair+0x3e2/0x4e0
Jul 30 22:07:16 t16 kernel: [ 601.226104] [<ffffffff81070f34>] process_one_work+0x174/0x4a0
Jul 30 22:07:16 t16 kernel: [ 601.226105] [<ffffffff81071c5b>] worker_thread+0x11b/0x530
Jul 30 22:07:16 t16 kernel: [ 601.226107] [<ffffffff81071b40>] ? create_and_start_worker+0x50/0x50
Jul 30 22:07:16 t16 kernel: [ 601.226108] [<ffffffff81078829>] kthread+0xc9/0xe0
Jul 30 22:07:16 t16 kernel: [ 601.226110] [<ffffffff81078760>] ? flush_kthread_worker+0xb0/0xb0
Jul 30 22:07:16 t16 kernel: [ 601.226112] [<ffffffff816be12c>] ret_from_fork+0x7c/0xb0
Jul 30 22:07:16 t16 kernel: [ 601.226113] [<ffffffff81078760>] ? flush_kthread_worker+0xb0/0xb0

The deadlock-good kernel has now been running the same test, in a loop, for over 3 hours without any errors reported in /var/log/kern.log. I will let it run overnight and will update the ticket only if it starts reporting issues.

I have done some testing and I am seeing the same thing as Eric. With the deadlock-bad kernel I hit the deadlock issue in less than 15 minutes. With the deadlock-good kernel I have been running for several hours and have not had an issue. I will be running against it all weekend and will update the ticket if an issue is found.

No need to do that just yet. I now fully understand the problem and working on a proper fix that I'd like you to test later. deadlock-good is simply a revert of a core kernel commit that changed the semantics of blocking lock primitives and made this deadlock possible.

Eric, Greg,

The fix on top of 3.16 + testing is in wip-request-fn.

http://gitbuilder.ceph.com/kernel-deb-precise-x86_64-basic/ref/wip-request-fn/linux-image-3.16.0-ceph-00037-g0532581_3.16.0-ceph-00037-g0532581-1_amd64.deb

The testing-bad branch is 3.16 + testing without the fix.

http://gitbuilder.ceph.com/kernel-deb-precise-x86_64-basic/ref/testing-bad/linux-image-3.16.0-ceph-00036-gbd78ef2_3.16.0-ceph-00036-gbd78ef2-1_amd64.deb

The 00036 "bad" kernel started showing the problem in the /var/log/kern.log file within minutes of starting my test script which runs multiple dd writes to the raw rbd device. An example of the failure reported in kern.log:

Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764346] INFO: task kworker/1:0:15 blocked for more than 120 seconds.
Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764355] Tainted: G E 3.16.0-ceph-00036-gbd78ef2 #1
Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764358] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764361] kworker/1:0 D 0000000000000000 0 15 2 0x00000000
Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764405] Workqueue: ceph-msgr con_work [libceph]
Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764410] ffff880bfce87c18 0000000000000046 0000000000000296 0000000000000000
Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764415] ffff880bfce6cb60 0000000000012fc0 ffff880bfce87fd8 0000000000012fc0
Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764420] ffff880bfb251920 ffff880bfce6cb60 0000000000000000 ffff880bf796a7c8
Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764424] Call Trace:
Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764440] [<ffffffff816ba789>] schedule+0x29/0x70
Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764446] [<ffffffff816baa5e>] schedule_preempt_disabled+0xe/0x10
Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764452] [<ffffffff816bc4c3>] __mutex_lock_slowpath+0xd3/0x1c0
Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764457] [<ffffffff816bc5d3>] mutex_lock+0x23/0x37
Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764469] [<ffffffffa017788f>] alloc_msg+0xcf/0x230 [libceph]
Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764479] [<ffffffffa0172fd6>] con_work+0x19d6/0x2020 [libceph]
Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764487] [<ffffffff81095c56>] ? pick_next_task_fair+0x3c6/0x4e0
Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764493] [<ffffffff81070f34>] process_one_work+0x174/0x4a0
Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764498] [<ffffffff81071c5b>] worker_thread+0x11b/0x530
Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764503] [<ffffffff81071b40>] ? create_and_start_worker+0x50/0x50
Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764509] [<ffffffff81078829>] kthread+0xc9/0xe0
Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764515] [<ffffffff81078760>] ? flush_kthread_worker+0xb0/0xb0
Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764521] [<ffffffff816be12c>] ret_from_fork+0x7c/0xb0
Aug 5 17:38:42 ic1gw01 kernel: [ 3243.764526] [<ffffffff81078760>] ? flush_kthread_worker+0xb0/0xb0

The "good" 00037 kernel has been running the same dd write test script for about 2 hours now without reporting any issues. It looks like your changes to the rbd driver has fixed the problem. I will leave it run overnight, and only update the bug report if it fails.

I switched to the good kernel (3.16.0-ceph-00037-g0532581) yesterday and re-ran my scripts overnight. The scripts completed without issue so I concur with Eric that the changes in 00037 seem to have fixed the mutex issue.

Upgrade to kernel: 3.16.0 and got the same problem:

...
[ 70.858716] Key type ceph registered
[ 70.858800] libceph: loaded (mon/osd proto 15/24)
[ 70.863011] rbd: loaded (major 251)
[ 70.867935] libceph: client5437 fsid 56e56e4c-ea59-4157-8b98-acae109bebe1
[ 70.869338] libceph: mon1 10.97.10.2:6789 session established
[ 70.879934] rbd0: unknown partition table
[ 70.880354] rbd: rbd0: added with size 0x3200000000
[ 164.737028] do_IRQ: 6.104 No irq handler for vector (irq -1)
[ 360.696573] INFO: task fio:3119 blocked for more than 120 seconds.
[ 360.699202] Tainted: G I 3.16.1-031601-generic #201408140014
[ 360.702248] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 360.705625] fio D 0000000000000000 0 3119 3117 0x00000000
[ 360.705631] ffff880234347818 0000000000000086 ffff880234347828 ffff880234347fd8
[ 360.705639] 0000000000014400 0000000000014400 ffff880139f4c6e0 ffff8800b9e7b2a0
[ 360.705643] ffff8802343477e8 ffff88013bc14d00 ffff8800b9e7b2a0 0000000000000000
[ 360.705646] Call Trace:
[ 360.705658] [<ffffffff81790129>] schedule+0x29/0x70
[ 360.705667] [<ffffffff817901ff>] io_schedule+0x8f/0xd0
[ 360.705673] [<ffffffff8135a9b0>] get_request+0x150/0x350
[ 360.705679] [<ffffffff8135bf67>] ? bio_attempt_back_merge+0x37/0x100
[ 360.705687] [<ffffffff810bab00>] ? __wake_up_sync+0x20/0x20
[ 360.705691] [<ffffffff8135ca1c>] blk_queue_bio+0xcc/0x380
[ 360.705697] [<ffffffff813579b5>] generic_make_request.part.75+0x75/0xb0
[ 360.705701] [<ffffffff81357fd8>] generic_make_request+0x68/0x70
[ 360.705704] [<ffffffff81358066>] submit_bio+0x86/0x160
[ 360.705711] [<ffffffff8177d4a1>] ? put_compound_page.part.21+0xf8/0x12f
[ 360.705718] [<ffffffff8121b668>] do_direct_IO+0xa78/0xf60
[ 360.705722] [<ffffffff8121beaa>] do_blockdev_direct_IO+0x35a/0xcc0
[ 360.705727] [<ffffffff81217370>] ? I_BDEV+0x10/0x10
[ 360.705731] [<ffffffff8121c85c>] __blockdev_direct_IO+0x4c/0x50
[ 360.705734] [<ffffffff81217370>] ? I_BDEV+0x10/0x10
[ 360.705738] [<ffffffff81217d41>] blkdev_direct_IO+0x51/0x60
[ 360.705741] [<ffffffff81217370>] ? I_BDEV+0x10/0x10
[ 360.705747] [<ffffffff8116d9f3>] generic_file_read_iter+0x143/0x150
[ 360.705750] [<ffffffff812174e0>] ? ioctl_by_bdev+0x50/0x50
[ 360.705754] [<ffffffff81217517>] blkdev_read_iter+0x37/0x40
[ 360.705758] [<ffffffff81229c57>] aio_run_iocb+0x207/0x3a0
[ 360.705761] [<ffffffff81229f0b>] io_submit_one+0x11b/0x260
[ 360.705768] [<ffffffff81013730>] ? __switch_to+0x260/0x5c0
[ 360.705771] [<ffffffff8122a424>] do_io_submit+0x104/0x1d0
[ 360.705775] [<ffffffff8122a500>] SyS_io_submit+0x10/0x20
[ 360.705780] [<ffffffff81793fad>] system_call_fastpath+0x1a/0x1f
...

Then I upgrade to 3.16.1 and the error continues. The test is with "fio", I'm running the following command:

fio --filename=/dev/rbd0 --direct=1 --rw=read --bs=8m --size=10G --iodepth=16 --ioengine=libaio --runtime=60 --group_reporting --name=file1

The fix looks like it made it into 3.17rc1. I have been testing this kernel since Sunday, and have not triggered the problem.
I do not think it has been pushed into any 3.16.x kernel yet

Eric is correct, the fix isn't in 3.16 stable yet, and unfortunately won't be in 3.15 at all - Linus pulled it into his tree on the day the last 3.15 stable release was cut.

OTOH, the stack trace doesn't look the same to me. German, what exactly are you seeing - does all rbd activity halt eventually? Are there any other hung tasks in dmesg?

Ok, I've applied the "..." with Kernel 3.16.0 and the error continues:

...
Aug 21 14:38:45 mail02-old kernel: [ 7206.274363] INFO: task fio:3590 blocked for more than 120 seconds.
Aug 21 14:38:45 mail02-old kernel: [ 7206.276954] Tainted: G I 3.16.1-031601-generic #201408140014
Aug 21 14:38:45 mail02-old kernel: [ 7206.279969] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 21 14:38:45 mail02-old kernel: [ 7206.283310] fio D 0000000000000002 0 3590 3580 0x00000000
Aug 21 14:38:45 mail02-old kernel: [ 7206.283316] ffff880139513768 0000000000000086 ffff880139513778 ffff880139513fd8
Aug 21 14:38:45 mail02-old kernel: [ 7206.283320] 0000000000014400 0000000000014400 ffff8802366a0000 ffff880234982880
Aug 21 14:38:45 mail02-old kernel: [ 7206.283323] ffff880139513738 ffff88013bc54d00 ffff880234982880 0000000000000010
Aug 21 14:38:45 mail02-old kernel: [ 7206.283327] Call Trace:
Aug 21 14:38:45 mail02-old kernel: [ 7206.283339] [<ffffffff81790129>] schedule+0x29/0x70
Aug 21 14:38:45 mail02-old kernel: [ 7206.283342] [<ffffffff817901ff>] io_schedule+0x8f/0xd0
Aug 21 14:38:45 mail02-old kernel: [ 7206.283348] [<ffffffff8135a9b0>] get_request+0x150/0x350
Aug 21 14:38:45 mail02-old kernel: [ 7206.283352] [<ffffffff8135bf67>] ? bio_attempt_back_merge+0x37/0x100
Aug 21 14:38:45 mail02-old kernel: [ 7206.283360] [<ffffffff810bab00>] ? __wake_up_sync+0x20/0x20
Aug 21 14:38:45 mail02-old kernel: [ 7206.283363] [<ffffffff8135ca1c>] blk_queue_bio+0xcc/0x380
Aug 21 14:38:45 mail02-old kernel: [ 7206.283370] [<ffffffff813579b5>] generic_make_request.part.75+0x75/0xb0
Aug 21 14:38:45 mail02-old kernel: [ 7206.283374] [<ffffffff81357fd8>] generic_make_request+0x68/0x70
Aug 21 14:38:45 mail02-old kernel: [ 7206.283377] [<ffffffff81358066>] submit_bio+0x86/0x160
Aug 21 14:38:45 mail02-old kernel: [ 7206.283384] [<ffffffff8177d4a1>] ? put_compound_page.part.21+0xf8/0x12f
Aug 21 14:38:45 mail02-old kernel: [ 7206.283391] [<ffffffff8121b668>] do_direct_IO+0xa78/0xf60
Aug 21 14:38:45 mail02-old kernel: [ 7206.283395] [<ffffffff8121beaa>] do_blockdev_direct_IO+0x35a/0xcc0
Aug 21 14:38:45 mail02-old kernel: [ 7206.283400] [<ffffffff81217370>] ? I_BDEV+0x10/0x10
Aug 21 14:38:45 mail02-old kernel: [ 7206.283404] [<ffffffff8121c85c>] __blockdev_direct_IO+0x4c/0x50
Aug 21 14:38:45 mail02-old kernel: [ 7206.283407] [<ffffffff81217370>] ? I_BDEV+0x10/0x10
Aug 21 14:38:45 mail02-old kernel: [ 7206.283411] [<ffffffff81217d41>] blkdev_direct_IO+0x51/0x60
Aug 21 14:38:45 mail02-old kernel: [ 7206.283414] [<ffffffff81217370>] ? I_BDEV+0x10/0x10
Aug 21 14:38:45 mail02-old kernel: [ 7206.283420] [<ffffffff8116d3cb>] generic_file_direct_write+0xbb/0x180
Aug 21 14:38:45 mail02-old kernel: [ 7206.283423] [<ffffffff8116d737>] __generic_file_write_iter+0x2a7/0x360
Aug 21 14:38:45 mail02-old kernel: [ 7206.283427] [<ffffffff812176d0>] ? bdput+0x20/0x20
Aug 21 14:38:45 mail02-old kernel: [ 7206.283431] [<ffffffff81217706>] blkdev_write_iter+0x36/0xb0
Aug 21 14:38:45 mail02-old kernel: [ 7206.283435] [<ffffffff81229c57>] aio_run_iocb+0x207/0x3a0
Aug 21 14:38:45 mail02-old kernel: [ 7206.283438] [<ffffffff81229f0b>] io_submit_one+0x11b/0x260
Aug 21 14:38:45 mail02-old kernel: [ 7206.283441] [<ffffffff8122a424>] do_io_submit+0x104/0x1d0
Aug 21 14:38:45 mail02-old kernel: [ 7206.283445] [<ffffffff8122a500>] SyS_io_submit+0x10/0x20
Aug 21 14:38:45 mail02-old kernel: [ 7206.283451] [<ffffffff81793fad>] system_call_fastpath+0x1a/0x1f
Aug 21 14:38:51 mail02-old kernel: [ 7212.391288] libceph: osd35 10.97.20.4:6824 socket closed (con state CONNECTING)
...

Same test "fio --filename=/dev/rbd0 --direct=1 --rw=read --bs=8m --size=10G --iodepth=16 --ioengine=libaio --runtime=60 --group_reporting --name=file1"

Any ideas?

I apply http://gitbuilder.ceph.com/kernel-deb-precise-x86_64-basic/ref/wip-request-fn/linux-image-3.16.0-ceph-00037-g0532581_3.16.0-ceph-00037-g0532581-1_amd64.deb

Does fio complete eventually? Are there any other hung tasks in dmesg? A task blocking for more than 120 seconds is not an error in itself.

It seems that using kernel 3.14.9 resolved the issue. Have tested for more than two days with lot of perf tests and run fine.

Well, the issue didn't get resolved, you simply found a kernel it doesn't show up on. I'm still interested to hear answers to the questions I posted above.

German,

3.14.x will work well, but it will not work with TUNABLES V3, specifically chooseleaf_vary_r turned on. For that you need kernel >= 3.5.x and those are the kernels affected by the issue.

Ilya, on our experience all Debian and ubuntu kernels above 3.14.x are affected. I did not have the time to test 3.16.1 or the 3.16.0 you posted, but for what I've read the problem is solved on that specific one.

Do you have any idea about when the issue will be solved in >= 3.16.x mainstream kernels?

Thanks!

Xavier Trilla wrote:

German,

3.14.x will work well, but it will not work with TUNABLES V3, specifically chooseleaf_vary_r turned on. For that you need kernel >= 3.5.x and those are the kernels affected by the issue.

Ilya, on our experience all Debian and ubuntu kernels above 3.14.x are affected. I did not have the time to test 3.16.1 or the 3.16.0 you posted, but for what I've read the problem is solved on that specific one.

Do you have any idea about when the issue will be solved in >= 3.16.x mainstream kernels?

Let's not mix the two "issues". The deadlock, which this ticket refers
to, was introduced in 3.15 and has been fixed. The fix has been marked
for stable, and I imagine it should make the next stable release, that
is 3.16.2. (As I mentioned earlier, 3.16.1 along with 3.15.10 were
released on the day Linus pulled our fix into mainline, so 3.15 kernels
will stay affected forever - 3.15.10 was the last 3.15 stable release.)

Now, there is something else reported by German, which appears to have
been introduced in 3.15 as well. However German hasn't replied with
the details I asked for yet, so we don't know if it's the same issue,
a different issue or if it's an issue at all.

Ilya sorry, I did a mistyping, I was trying to give some background to German about why it's important to have stable >= 3.15.x kernel, as it's the minor version needed for TUNNABLES V3, but I typed 3.5 instead of 3.15.x :/

Ok, well try 3.16.2 once it's released and we will let you know.

Thanks!

Ilya Dryomov wrote:

Well, the issue didn't get resolved, you simply found a kernel it doesn't show up on. I'm still interested to hear answers to the questions I posted above.

The fio didn't finished, and a hard-reset of the server is needed.

We're seeing this on CoreOS, kernel 3.15.8. Upgrading the kernel ourselves isn't an option, so this'll block RBD usage until they upgrade to a fixed kernel.

I'll try to reproduce German's fio problem.

To those who are stuck on 3.15 for some reason but can rebuild their kernel, rebuild with CONFIG_DEBUG_MUTEXES=y or try to get a "debug" kernel. This problem showed up due to a subtle change to the mutex fastpath, DEBUG_MUTEXES works around it.

Xavier Trilla wrote:

Ok, well try 3.16.2 once it's released and we will let you know.

Sadly, your patch has not been integrated in 3.16.2, so this new kernel release doesn't fix the but.

Guillaume Subiron wrote:

Xavier Trilla wrote:

Ok, well try 3.16.2 once it's released and we will let you know.

Sadly, your patch has not been integrated in 3.16.2, so this new kernel release doesn't fix the but.

Yeah, I've already sent an inquiry to the stable team. Some bad luck with this patch, huh.

The patch is in the queue, just haven't been applied yet: https://lkml.org/lkml/2014/9/3/918.

Ilya,

I've tried the kernel that was patched, but I am still experiencing hang tasks. Although less often than before. Here is a recent hang task:

Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455012] INFO: task kworker/u26:2:721 blocked for more than 120 seconds.
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455028] Tainted: G E 3.16.0-ceph-00037-g0532581 #1
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455039] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455044] kworker/u26:2 D 0000000000000000 0 721 2 0x00000000
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455057] Workqueue: writeback bdi_writeback_workfn (flush-251:0)
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455060] ffff8806717fb7b8 0000000000000046 ffff8806717fb778 ffffffff810bdc5c
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455063] ffff88066ed53240 0000000000012fc0 ffff8806717fbfd8 0000000000012fc0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455066] ffff880673de1920 ffff88066ed53240 ffff8806717fb788 ffff88067fd538d0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455080] Call Trace:
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455089] [<ffffffff810bdc5c>] ? ktime_get_ts+0x4c/0xe0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455094] [<ffffffff81142fc0>] ? lock_page+0x70/0x70
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455102] [<ffffffff816ba789>] schedule+0x29/0x70
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455104] [<ffffffff816ba85f>] io_schedule+0x8f/0xd0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455107] [<ffffffff81142fce>] sleep_on_page+0xe/0x20
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455110] [<ffffffff816bac73>] __wait_on_bit_lock+0x73/0xb0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455114] [<ffffffff81143a9b>] ? find_get_pages_tag+0xcb/0x170
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455116] [<ffffffff81142fb7>] __lock_page+0x67/0x70
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455122] [<ffffffff8109ba60>] ? wake_atomic_t_function+0x40/0x40
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455127] [<ffffffff81249a57>] mpage_prepare_extent_to_map+0x267/0x320
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455131] [<ffffffff8124fedd>] ext4_writepages+0x46d/0xca0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455138] [<ffffffff8133cd97>] ? __blk_run_queue+0x37/0x50
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455144] [<ffffffff8114e3c6>] ? generic_writepages+0x56/0x70
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455147] [<ffffffff8114fdb0>] do_writepages+0x20/0x40
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455150] [<ffffffff811d7995>] __writeback_single_inode+0x45/0x290
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455153] [<ffffffff811d85d6>] writeback_sb_inodes+0x216/0x450
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455156] [<ffffffff811d88ae>] __writeback_inodes_wb+0x9e/0xd0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455159] [<ffffffff811d908b>] wb_writeback+0x27b/0x320
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455162] [<ffffffff811d917e>] ? wb_check_old_data_flush+0x4e/0xb0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455165] [<ffffffff811db899>] bdi_writeback_workfn+0x209/0x460
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455171] [<ffffffff81070f34>] process_one_work+0x174/0x4a0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455174] [<ffffffff81071c5b>] worker_thread+0x11b/0x530
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455176] [<ffffffff81071b40>] ? create_and_start_worker+0x50/0x50
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455181] [<ffffffff81078829>] kthread+0xc9/0xe0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455184] [<ffffffff81078760>] ? flush_kthread_worker+0xb0/0xb0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455188] [<ffffffff816be12c>] ret_from_fork+0x7c/0xb0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455191] [<ffffffff81078760>] ? flush_kthread_worker+0xb0/0xb0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455585] INFO: task jbd2/rbd0p1-8:17420 blocked for more than 120 seconds.
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455589] Tainted: G E 3.16.0-ceph-00037-g0532581 #1
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455592] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455595] jbd2/rbd0p1-8 D 0000000000000009 0 17420 2 0x00000000
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455598] ffff88017bc87c58 0000000000000046 ffff8800794922a0 0000000300000001
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455601] ffff8804af43cb60 0000000000012fc0 ffff88017bc87fd8 0000000000012fc0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455604] ffff880469d9b240 ffff8804af43cb60 ffff88017bc87c68 ffff88017bc87d90
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455606] Call Trace:
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455610] [<ffffffff816ba789>] schedule+0x29/0x70
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455617] [<ffffffff8129c0d3>] jbd2_journal_commit_transaction+0x223/0x18f0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455620] [<ffffffff81091921>] ? dequeue_entity+0x181/0x520
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455623] [<ffffffff81092c4c>] ? put_prev_entity+0x3c/0x320
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455626] [<ffffffff8109b9e0>] ? __wake_up_sync+0x20/0x20
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455630] [<ffffffff812a0a83>] kjournald2+0xb3/0x230
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455633] [<ffffffff8109b9e0>] ? __wake_up_sync+0x20/0x20
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455636] [<ffffffff812a09d0>] ? commit_timeout+0x10/0x10
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455639] [<ffffffff81078829>] kthread+0xc9/0xe0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455642] [<ffffffff81078760>] ? flush_kthread_worker+0xb0/0xb0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455646] [<ffffffff816be12c>] ret_from_fork+0x7c/0xb0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455649] [<ffffffff81078760>] ? flush_kthread_worker+0xb0/0xb0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455716] INFO: task dd:23350 blocked for more than 120 seconds.
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455720] Tainted: G E 3.16.0-ceph-00037-g0532581 #1
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455722] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455726] dd D 0000000000000009 0 23350 8521 0x00000002
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455728] ffff88001e793908 0000000000000086 ffff88001e793988 ffffffff81085544
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455731] ffff8800041ae480 0000000000012fc0 ffff88001e793fd8 0000000000012fc0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455733] ffff880673dd6480 ffff8800041ae480 ffff88001e7938d8 ffff88067fcd38d0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455736] Call Trace:
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455740] [<ffffffff81085544>] ? set_task_cpu+0x74/0x1c0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455743] [<ffffffff816ba789>] schedule+0x29/0x70
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455746] [<ffffffff816ba85f>] io_schedule+0x8f/0xd0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455748] [<ffffffff8133e264>] get_request+0x414/0x800
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455751] [<ffffffff810854c6>] ? ttwu_do_activate.constprop.121+0x66/0x70
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455754] [<ffffffff8109b9e0>] ? __wake_up_sync+0x20/0x20
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455758] [<ffffffff8134292c>] blk_queue_bio+0xcc/0x360
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455760] [<ffffffff8133ecd0>] generic_make_request+0xc0/0x100
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455762] [<ffffffff8133ed85>] submit_bio+0x75/0x140
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455766] [<ffffffff8114e8ef>] ? __test_set_page_writeback+0x16f/0x1c0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455769] [<ffffffff81251a69>] ext4_io_submit+0x29/0x50
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455772] [<ffffffff81251c61>] ext4_bio_write_page+0x1a1/0x2d0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455781] [<ffffffff81248c08>] mpage_submit_page+0x68/0x90
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455784] [<ffffffff812492bf>] mpage_map_and_submit_buffers+0x15f/0x260
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455787] [<ffffffff812501ab>] ext4_writepages+0x73b/0xca0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455792] [<ffffffff811ce292>] ? mnt_clone_write+0x12/0x30
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455798] [<ffffffff816b3d8d>] ? __slab_free+0xee/0x234
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455801] [<ffffffff81095c56>] ? pick_next_task_fair+0x3c6/0x4e0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455803] [<ffffffff8114fdb0>] do_writepages+0x20/0x40
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455806] [<ffffffff81144a79>] __filemap_fdatawrite_range+0x59/0x60
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455809] [<ffffffff811456cc>] filemap_flush+0x1c/0x20
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455812] [<ffffffff8124b769>] ext4_alloc_da_blocks+0x49/0xa0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455814] [<ffffffff812447d9>] ext4_release_file+0x79/0xc0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455819] [<ffffffff811b2155>] __fput+0xb5/0x200
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455822] [<ffffffff811b22ee>] __fput+0xe/0x10
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455824] [<ffffffff81075317>] task_work_run+0xa7/0xe0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455828] [<ffffffff81002f0a>] do_notify_resume+0xaa/0xc0
Sep 14 15:33:07 arh-ibstorage1-ib kernel: [ 1920.455832] [<ffffffff816be462>] int_signal+0x12/0x17

This is using 3.16.0-ceph-00037-g0532581 kernel. My rbd cache settings are turned off. I've ran the following command to cause the hang task:

for i in {1..100} ; do dd if=/dev/zero of=2G bs=4K count=500K ; done

The hang tasks happened after about 40 dd runs, whereas before it was hanging on a 3rd or 4th run. So, definitely an improvement from the ubuntu 3.15 and 3.16 kernels, but not perfect ((

Thanks

Andrei
Thanks

Do those dds eventually complete?

Ilya,

Not sure as I've not left it to run for a long time. There was no progress for about 30 minutes, so I've rebooted the server.

I am running some more tests with this kernel and will report on the progress. I am doing various block sizes and oflag=direct as well.

If you would like me to run some more tests, please let me know.

Andrei

Okay, just tried with block size 4M and after about 20 dd runs I got a hang task.

Also, I've noticed that the speed of dd runs is gradually decreasing with every run. The dds start with about 60MB/s and at the end the speed is only around 20MB/s. Something odd is going on here.

Andrei

Done more testing. The hang tasks happen regardless of the block size (tried 4K, 1M ,4M). Without rbd cache enabled the hang tasks tend to happen sooner (I am seeing the first hang task after about 40 dd runs, whereas with rbd cache enabled it happens after about run 70-75).

Andrei

Ilya,

I was wondering if you've managed to verify my findings? Has anyone experienced similar behaviour as I am?

Thanks

Andrei,

No, I haven't, but plan to try harder. I am however seeing an extreme slowdown, will open a ticket to take a deeper look.

The stacktraces you provided don't have any rbd calls in them. Can you try to see if it's the actual hang or there is some progress? Also, running clients on OSD nodes is not recommended and may lead to lockups, although what you are seeing is not related. Try doing 'echo w > /proc/sysrq-trigger' if/when it locks up?

Hi!

Are there any news here?
We are still having exactly the same issues with our cluster. And our ONLY usecase is to use the kernel rbd driver. What happened to this bug?

Regards,
Christian