Bug #16921: rbd-nbd IO hang - rbd - Ceph

Actions

Copy link

Bug #16921

closed

rbd-nbd IO hang

Added by Loïc Dachary over 7 years ago. Updated over 7 years ago.

Status:

Resolved

Priority:

Normal

Assignee:

Jason Dillaman

Target version:

% Done:

Source:

other

Tags:

Backport:

jewel

Regression:

Severity:

3 - minor

Reviewed:

Affected Versions:

ceph-qa-suite:

Pull request ID:

Crash signature (v1):

Crash signature (v2):

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:

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.

Related issues 1 (0 open — 1 closed)

Actions

Copy link

Updated by Jason Dillaman over 7 years ago

Status changed from New to In Progress
Assignee set to Jason Dillaman
Backport set to jewel

Actions

Copy link

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.

Actions

Copy link

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

Actions

Copy link

Updated by Jason Dillaman over 7 years ago

Status changed from New to In Progress
Assignee set to Jason Dillaman

Actions

Copy link

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.

Actions

Copy link

Updated by Jason Dillaman over 7 years ago

Status changed from In Progress to Fix Under Review

PR: https://github.com/ceph/ceph/pull/10985

Actions

Copy link

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.

Actions

Copy link

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

Actions

Copy link

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

Actions

Copy link

#10