Bug #16921
closedrbd-nbd IO hang
Added by Loïc Dachary over 7 years ago. Updated over 7 years ago.
0%
Description
It can be reproduced on jewel with rbd/thrash/{base/install.yaml clusters/{fixed-2.yaml openstack.yaml} fs/xfs.yaml msgr-failures/few.yaml thrashers/default.yaml workloads/rbd_fsx_nbd.yaml}. For instance:
- http://pulpito.ceph.com/loic-2016-08-03_00:03:18-rbd-jewel-backports---basic-smithi/347434
- http://pulpito.ceph.com/loic-2016-08-03_00:03:18-rbd-jewel-backports---basic-smithi/347438
Looking at the jewel branch of ceph-qa-suite, it does not seem to miss a commit that would make a difference. It looks like ceph_test_librbd_fsx is not making any progress. The -p 100 should show a debug line every 100 test call but there are not any.
It can also be reproduced on master.
Updated by Jason Dillaman over 7 years ago
- Status changed from New to In Progress
- Assignee set to Jason Dillaman
- Backport set to jewel
Updated by Jason Dillaman over 7 years ago
- Status changed from In Progress to New
- Assignee deleted (
Jason Dillaman)
Running fsx_nbd on my local trusty VM works just fine. Examining the test logs, they appear to be missing the first console log of "Seed set to XYZ". This should be printed before any real action is executed so it seems like fsx never truly started. Guessing this is a teuthology / lab specific issue.
Updated by Jason Dillaman over 7 years ago
[ 3799.647869] nbd: registered device at major 43
[ 4068.478821] block nbd0: NBD_DISCONNECT
[ 4068.478895] block nbd0: Receive control failed (result -32)
[ 4068.483778] block nbd0: shutting down socket
[ 4068.483781] block nbd0: queue cleared
[ 4068.625005] nbd0: unknown partition table
[ 4075.474586] block nbd0: NBD_DISCONNECT
[ 4075.474648] block nbd0: Receive control failed (result -32)
[ 4075.480478] block nbd0: shutting down socket
[ 4075.480481] block nbd0: queue cleared
[ 4076.962526] nbd0: unknown partition table
[ 4200.940148] INFO: task ceph_test_librb:23872 blocked for more than 120 seconds.
[ 4200.950828] Not tainted 3.13.0-74-generic #118-Ubuntu
[ 4200.955526] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4200.962351] ceph_test_librb D ffff880113013180 0 23872 23871 0x00000000
[ 4200.962356] ffff88003e157958 0000000000000082 ffff88003f79c800 ffff88003e157fd8
[ 4200.962358] 0000000000013180 0000000000013180 ffff88003f79c800 ffff880113013a18
[ 4200.962360] ffff8801133d6fe8 ffff88003e1579e0 0000000000000002 ffffffff8114f5e0
[ 4200.962363] Call Trace:
[ 4200.962371] [<ffffffff8114f5e0>] ? wait_on_page_read+0x60/0x60
[ 4200.962375] [<ffffffff8172929d>] io_schedule+0x9d/0x140
[ 4200.962377] [<ffffffff8114f5ee>] sleep_on_page+0xe/0x20
[ 4200.962380] [<ffffffff81729828>] __wait_on_bit_lock+0x48/0xb0
[ 4200.962383] [<ffffffff811f7a30>] ? blkdev_write_begin+0x30/0x30
[ 4200.962409] [<ffffffff8114f6fa>] __lock_page+0x6a/0x70
[ 4200.962414] [<ffffffff810ab4a0>] ? autoremove_wake_function+0x40/0x40
[ 4200.962416] [<ffffffff811f7a48>] ? blkdev_readpage+0x18/0x20
[ 4200.962419] [<ffffffff81150510>] do_read_cache_page+0x100/0x1a0
[ 4200.962422] [<ffffffff811505e9>] read_cache_page+0x19/0x30
[ 4200.962430] [<ffffffff8134c2ed>] read_dev_sector+0x2d/0x90
[ 4200.962433] [<ffffffff8134d060>] ? check_partition+0x240/0x240
[ 4200.962435] [<ffffffff8134d0d0>] adfspart_check_ICS+0x70/0x280
[ 4200.962438] [<ffffffff81371869>] ? snprintf+0x39/0x40
[ 4200.962440] [<ffffffff8134d060>] ? check_partition+0x240/0x240
[ 4200.962442] [<ffffffff8134cf28>] check_partition+0x108/0x240
[ 4200.962444] [<ffffffff8134cb54>] rescan_partitions+0xb4/0x2c0
[ 4200.962447] [<ffffffff811f8ed2>] __blkdev_get+0x4b2/0x4c0
[ 4200.962449] [<ffffffff811f90a5>] blkdev_get+0x1c5/0x340
[ 4200.962452] [<ffffffff811f92cb>] blkdev_open+0x5b/0x80
[ 4200.962456] [<ffffffff811bb9e3>] do_dentry_open+0x233/0x2e0
[ 4200.962458] [<ffffffff811f9270>] ? blkdev_get_by_dev+0x50/0x50
[ 4200.962460] [<ffffffff811bbd19>] vfs_open+0x49/0x50
[ 4200.962463] [<ffffffff811cac51>] do_last+0x541/0x1200
[ 4200.962466] [<ffffffff8131666b>] ? apparmor_file_alloc_security+0x5b/0x180
[ 4200.962469] [<ffffffff811cde8b>] path_openat+0xbb/0x640
[ 4200.962471] [<ffffffff811cf27a>] do_filp_open+0x3a/0x90
[ 4200.962474] [<ffffffff811dc0d7>] ? __alloc_fd+0xa7/0x130
[ 4200.962477] [<ffffffff811bd839>] do_sys_open+0x129/0x280
[ 4200.962481] [<ffffffff817310ba>] ? do_page_fault+0x1a/0x70
[ 4200.962483] [<ffffffff811bd9ae>] SyS_open+0x1e/0x20
[ 4200.962486] [<ffffffff8173575d>] system_call_fastpath+0x1a/0x1f
Updated by Jason Dillaman over 7 years ago
- Status changed from New to In Progress
- Assignee set to Jason Dillaman
Updated by Jason Dillaman over 7 years ago
Appears to be related to teothology's fixed PID mapping:
2016-09-05 10:18:24.479834 7fddfbc3ce00 -1 open: failed to lock pidfile /var/run/ceph/ceph-client.admin.pid because another process locked it.
Can reproduce 100% of the time if rbd-nbd processes are forced to use the same pid file.
Updated by Jason Dillaman over 7 years ago
- Status changed from In Progress to Fix Under Review
Updated by Jason Dillaman over 7 years ago
[ 7371.959761] INFO: task rbd-nbd:4678 blocked for more than 120 seconds. [ 7371.966354] Not tainted 4.8.0-rc5-ceph-00023-g1b39cec2 #1 [ 7371.972412] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 7371.980413] rbd-nbd D ffff90961b2ab9e8 0 4678 1 0x00000000 [ 7371.987660] ffff90961b2ab9e8 ffff90961b2ab9f8 ffffffff9c0c8e3f ffff909600000000 [ 7371.997983] 0000000000000000 ffff9096ad6b4a00 ffff9094bd50a500 ffffffff9ce58b60 [ 7372.005661] ffff90961b2ac000 ffff9094fb4dbed0 ffff9094bd50a500 7fffffffffffffff [ 7372.013312] Call Trace: [ 7372.015858] [<ffffffff9c0c8e3f>] ? enqueue_entity+0x93f/0xb20 [ 7372.021811] [<ffffffff9c820548>] schedule+0x78/0xa0 [ 7372.026844] [<ffffffff9c824713>] schedule_timeout+0x43/0x470 [ 7372.032749] [<ffffffff9c82165c>] ? wait_for_completion+0x3c/0x110 [ 7372.039011] [<ffffffff9c8216e0>] wait_for_completion+0xc0/0x110 [ 7372.045192] [<ffffffff9c0b7470>] ? try_to_wake_up+0x590/0x590 [ 7372.051155] [<ffffffff9c0abebc>] kthread_stop+0x14c/0x280 [ 7372.056847] [<ffffffffc0670709>] __nbd_ioctl+0xbb9/0xd40 [nbd] [ 7372.062964] [<ffffffff9c0b4fdb>] ? task_rq_lock+0x5b/0xd0 [ 7372.068701] [<ffffffff9c0c36e1>] ? update_cfs_rq_load_avg+0x221/0x3f0 [ 7372.075513] [<ffffffffc06708f2>] ? nbd_ioctl+0x62/0xa0 [nbd] [ 7372.081630] [<ffffffff9c0e02ed>] ? trace_hardirqs_on+0xd/0x10 [ 7372.087663] [<ffffffffc06708f2>] ? nbd_ioctl+0x62/0xa0 [nbd] [ 7372.093560] [<ffffffff9c3887ac>] ? security_capable+0x3c/0x60 [ 7372.099659] [<ffffffffc0670903>] nbd_ioctl+0x73/0xa0 [nbd] [ 7372.105461] [<ffffffff9c4062e8>] blkdev_ioctl+0x9e8/0xa20 [ 7372.111125] [<ffffffff9c28d3d0>] block_ioctl+0x40/0x50 [ 7372.116541] [<ffffffff9c261f42>] do_vfs_ioctl+0x692/0x6e0 [ 7372.122242] [<ffffffff9c26e495>] ? __fget+0x1a5/0x1c0 [ 7372.127558] [<ffffffff9c26e2f5>] ? __fget+0x5/0x1c0 [ 7372.132692] [<ffffffff9c261fee>] SyS_ioctl+0x5e/0xa0 [ 7372.138001] [<ffffffff9c825fc0>] entry_SYSCALL_64_fastpath+0x23/0xc1 [ 7372.144697] INFO: lockdep is turned off. [ 7372.148749] INFO: task nbd0:4708 blocked for more than 120 seconds. [ 7372.155232] Not tainted 4.8.0-rc5-ceph-00023-g1b39cec2 #1 [ 7372.161362] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 7372.169492] nbd0 D ffff9094fb4dbd28 0 4708 2 0x00000000 [ 7372.176921] ffff9094fb4dbd28 0000000000000000 0000000000000000 ffff9094fb4dbd58 [ 7372.184865] 0000000000000246 ffff9096ad6b0000 ffff90945095a500 ffff909400000000 [ 7372.192777] ffff9094fb4dc000 ffff9096a9ed4110 ffff90945095a500 0000000000000246 [ 7372.200690] Call Trace: [ 7372.203175] [<ffffffff9c820548>] schedule+0x78/0xa0 [ 7372.208446] [<ffffffff9c820765>] schedule_preempt_disabled+0x15/0x20 [ 7372.215012] [<ffffffff9c82329d>] mutex_lock_nested+0x1dd/0x350 [ 7372.221271] [<ffffffffc0670aa1>] ? nbd_thread_send+0x171/0x2ac [nbd] [ 7372.228027] [<ffffffffc0670aa1>] nbd_thread_send+0x171/0x2ac [nbd] [ 7372.234418] [<ffffffff9c0d22c0>] ? wait_woken+0x90/0x90 [ 7372.240043] [<ffffffffc0670930>] ? nbd_ioctl+0xa0/0xa0 [nbd] [ 7372.245992] [<ffffffff9c0ac7ca>] kthread+0x10a/0x120 [ 7372.251306] [<ffffffff9c82620f>] ret_from_fork+0x1f/0x40 [ 7372.257063] [<ffffffff9c0ac6c0>] ? flush_kthread_worker+0x110/0x110 [ 7372.263669] INFO: lockdep is turned off. [ 7372.267863] INFO: task rbd-nbd:7379 blocked for more than 120 seconds. [ 7372.274662] Not tainted 4.8.0-rc5-ceph-00023-g1b39cec2 #1 [ 7372.280919] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 7372.288980] rbd-nbd D ffff90949960b7e8 0 7379 23861 0x00000000 [ 7372.296457] ffff90949960b7e8 ffff90949960b808 0000000000000004 ffff90949960b7e8 [ 7372.304297] 000000009c0ad424 ffff9096ad69ca00 ffff9093c6222500 ffffffff9ddc81df [ 7372.312203] ffff90949960c000 ffff9096bfd19c40 7fffffffffffffff 0000000000000002 [ 7372.320123] Call Trace: [ 7372.322602] [<ffffffff9c820cd0>] ? bit_wait+0x60/0x60 [ 7372.328009] [<ffffffff9c820548>] schedule+0x78/0xa0 [ 7372.333191] [<ffffffff9c824713>] schedule_timeout+0x43/0x470 [ 7372.339124] [<ffffffff9c15da53>] ? __delayacct_blkio_start+0x23/0x30 [ 7372.345854] [<ffffffff9c0e02ed>] ? trace_hardirqs_on+0xd/0x10 [ 7372.352025] [<ffffffff9c10f594>] ? ktime_get+0xc4/0x120 [ 7372.357621] [<ffffffff9c15da53>] ? __delayacct_blkio_start+0x23/0x30 [ 7372.364354] [<ffffffff9c820cd0>] ? bit_wait+0x60/0x60 [ 7372.369636] [<ffffffff9c81f904>] io_schedule_timeout+0xa4/0x110 [ 7372.375905] [<ffffffff9c0d2731>] ? prepare_to_wait_exclusive+0x81/0x90 [ 7372.382780] [<ffffffff9c820cef>] bit_wait_io+0x1f/0x60 [ 7372.388263] [<ffffffff9c8208f0>] __wait_on_bit_lock+0x50/0xa0 [ 7372.394347] [<ffffffff9c1b9540>] ? find_get_entries+0x30/0x370 [ 7372.400591] [<ffffffff9c1b4e8d>] __lock_page+0xbd/0xc0 [ 7372.406095] [<ffffffff9c0d2340>] ? wake_atomic_t_function+0x30/0x30 [ 7372.412699] [<ffffffff9c1cb96a>] truncate_inode_pages_range+0x6ea/0x820 [ 7372.419698] [<ffffffff9c289570>] ? buffer_cpu_notify+0x90/0x90 [ 7372.425842] [<ffffffff9c289570>] ? buffer_cpu_notify+0x90/0x90 [ 7372.432085] [<ffffffff9c1cbb25>] truncate_inode_pages+0x15/0x20 [ 7372.438323] [<ffffffff9c28e6f9>] kill_bdev+0x39/0x40 [ 7372.443664] [<ffffffffc066fca0>] __nbd_ioctl+0x150/0xd40 [nbd] [ 7372.449779] [<ffffffff9c0b6f19>] ? try_to_wake_up+0x39/0x590 [ 7372.455769] [<ffffffff9c0e02ed>] ? trace_hardirqs_on+0xd/0x10 [ 7372.461786] [<ffffffffc06708f2>] ? nbd_ioctl+0x62/0xa0 [nbd] [ 7372.467894] [<ffffffff9c0e02ed>] ? trace_hardirqs_on+0xd/0x10 [ 7372.473971] [<ffffffffc06708f2>] ? nbd_ioctl+0x62/0xa0 [nbd] [ 7372.479938] [<ffffffff9c3887ac>] ? security_capable+0x3c/0x60 [ 7372.486008] [<ffffffffc0670903>] nbd_ioctl+0x73/0xa0 [nbd] [ 7372.491942] [<ffffffff9c4062e8>] blkdev_ioctl+0x9e8/0xa20 [ 7372.497695] [<ffffffff9c28d3d0>] block_ioctl+0x40/0x50 [ 7372.503130] [<ffffffff9c261f42>] do_vfs_ioctl+0x692/0x6e0 [ 7372.508897] [<ffffffff9c26e495>] ? __fget+0x1a5/0x1c0 [ 7372.514265] [<ffffffff9c26e2f5>] ? __fget+0x5/0x1c0 [ 7372.519598] [<ffffffff9c261fee>] SyS_ioctl+0x5e/0xa0 [ 7372.525012] [<ffffffff9c825fc0>] entry_SYSCALL_64_fastpath+0x23/0xc1 [ 7372.531829] INFO: lockdep is turned off.
Updated by Jason Dillaman over 7 years ago
2016-09-07 17:15:50.931644 7f59527fc700 -1 librbd::AioCompletion: 0x7f5938000cc0 fail: (22) Invalid argument
2016-09-07 17:15:50.931844 7f59527fc700 -1 librbd::AioCompletion: 0x7f5938000ef0 fail: (22) Invalid argument
2016-09-07 17:15:50.932045 7f59527fc700 -1 librbd::AioCompletion: 0x7f5938000cc0 fail: (22) Invalid argument
2016-09-07 17:15:50.932204 7f59527fc700 -1 librbd::AioCompletion: 0x7f5938000ef0 fail: (22) Invalid argument
2016-09-07 17:15:50.944848 7f59527fc700 -1 librbd::ImageCtx: could not release all objects from cache: 4096 bytes remain
2016-09-07 17:15:50.944899 7f59527fc700 -1 librbd::ResizeRequest: failed to invalidate cache: (16) Device or resource busy
Updated by Jason Dillaman over 7 years ago
Spurious read request from kernel via rbd-nbd that raced with the resize resulted in the cache not being able to invalidate a bufferhead.
2016-09-08 15:01:13.738476 7f69c1ffb700 5 librbd::ResizeRequest: 0x7f69b4006b80 send_invalidate_cache 2016-09-08 15:01:13.738479 7f69c1ffb700 10 objectcacher release_set 0x7f69b4002890 2016-09-08 15:01:13.738483 7f69c1ffb700 10 objectcacher release trimming object[rbd_data.102279d4bf93.0000000000000007/head oset 0x7f69b4002890 wr 54/54] 2016-09-08 15:01:13.738487 7f69c1ffb700 10 objectcacher close_object object[rbd_data.102279d4bf93.0000000000000007/head oset 0x7f69b4002890 wr 54/54] 2016-09-08 15:01:13.738504 7f69c1ffb700 10 objectcacher release trimming object[rbd_data.102279d4bf93.0000000000000006/head oset 0x7f69b4002890 wr 53/53] 2016-09-08 15:01:13.738507 7f69c1ffb700 10 objectcacher close_object object[rbd_data.102279d4bf93.0000000000000006/head oset 0x7f69b4002890 wr 53/53] 2016-09-08 15:01:13.738515 7f69c1ffb700 10 objectcacher release trimming object[rbd_data.102279d4bf93.0000000000000004/head oset 0x7f69b4002890 wr 55/55] 2016-09-08 15:01:13.738518 7f69c1ffb700 10 objectcacher close_object object[rbd_data.102279d4bf93.0000000000000004/head oset 0x7f69b4002890 wr 55/55] 2016-09-08 15:01:13.738525 7f69c1ffb700 10 objectcacher release_set 0x7f69b4002890 object[rbd_data.102279d4bf93.0000000000000000/head oset 0x7f69b4002890 wr 0/0] has 4096 bytes left 2016-09-08 15:01:13.738537 7f69c1ffb700 10 objectcacher release trimming object[rbd_data.102279d4bf93.0000000000000005/head oset 0x7f69b4002890 wr 0/0] 2016-09-08 15:01:13.738539 7f69c1ffb700 10 objectcacher close_object object[rbd_data.102279d4bf93.0000000000000005/head oset 0x7f69b4002890 wr 0/0] 2016-09-08 15:01:13.738543 7f69c1ffb700 10 objectcacher release_set 0x7f69b4002890, 4096 bytes left 2016-09-08 15:01:13.738546 7f69c1ffb700 10 objectcacher flush_set 0x7f69b4002890 2016-09-08 15:01:13.738548 7f69c1ffb700 10 objectcacher flush_set has no dirty|tx bhs 2016-09-08 15:01:13.738551 7f69c1ffb700 10 objectcacher release_set 0x7f69b4002890 2016-09-08 15:01:13.738552 7f69c1ffb700 10 objectcacher release_set 0x7f69b4002890 object[rbd_data.102279d4bf93.0000000000000000/head oset 0x7f69b4002890 wr 0/0] has 4096 bytes left 2016-09-08 15:01:13.738556 7f69c1ffb700 10 objectcacher release_set 0x7f69b4002890, 4096 bytes left 2016-09-08 15:01:13.738558 7f69c1ffb700 -1 librbd::ImageCtx: could not release all objects from cache: 4096 bytes remain 2016-09-08 15:01:13.738566 7f69c1ffb700 5 librbd::ResizeRequest: 0x7f69b4006b80 handle_invalidate_cache: r=-16 2016-09-08 15:01:13.738568 7f69c1ffb700 -1 librbd::ResizeRequest: failed to invalidate cache: (16) Device or resource busy
Updated by Mykola Golub over 7 years ago
- Status changed from Fix Under Review to Pending Backport
Updated by Loïc Dachary over 7 years ago
- Copied to Backport #17262: jewel: rbd-nbd IO hang added
Updated by Loïc Dachary over 7 years ago
- Status changed from Pending Backport to Resolved