On Thu, Jul 18, 2019 at 1:47 PM Marc Schöchlin <m...@256bit.org> wrote: > > Hello cephers, > > rbd-nbd crashes in a reproducible way here.
I don't see a crash report in the log below. Is it really crashing or is it shutting down? If it is crashing and it's reproducable, can you install the debuginfo packages, attach gdb, and get a full backtrace of the crash? It seems like your cluster cannot keep up w/ the load and the nbd kernel driver is timing out the IO and shutting down. There is a "--timeout" option on "rbd-nbd" that you can use to increase the kernel IO timeout for nbd. > I created the following bug report: https://tracker.ceph.com/issues/40822 > > Do you also experience this problem? > Do you have suggestions for in depth debug data collection? > > I invoke the following command on a freshly mapped rbd and rbd_rbd crashes: > > # find . -type f -name "*.sql" -exec ionice -c3 nice -n 20 gzip -v {} \; > gzip: ./deprecated_data/data_archive.done/entry_search_201232.sql.gz already > exists; do you wish to overwrite (y or n)? y > ./deprecated_data/data_archive.done/entry_search_201232.sql: 84.1% -- > replaced with ./deprecated_data/data_archive.done/entry_search_201232.sql.gz > ./deprecated_data/data_archive.done/entry_search_201233.sql: > gzip: ./deprecated_data/data_archive.done/entry_search_201233.sql: > Input/output error > gzip: ./deprecated_data/data_archive.done/entry_search_201234.sql: > Input/output error > gzip: ./deprecated_data/data_archive.done/entry_search_201235.sql: > Input/output error > gzip: ./deprecated_data/data_archive.done/entry_search_201236.sql: > Input/output error > .... > > dmesg output: > > [579763.020890] block nbd0: Connection timed out > [579763.020926] block nbd0: shutting down sockets > [579763.020943] print_req_error: I/O error, dev nbd0, sector 3221296950 > [579763.020946] block nbd0: Receive data failed (result -32) > [579763.020952] print_req_error: I/O error, dev nbd0, sector 4523172248 > [579763.021001] XFS (nbd0): metadata I/O error: block 0xc0011736 > ("xlog_iodone") error 5 numblks 512 > [579763.021031] XFS (nbd0): xfs_do_force_shutdown(0x2) called from line 1261 > of file /build/linux-hwe-xJVMkx/linux-hwe-4.15.0/fs/xfs/xfs_log.c. Return > address = 0x00000000918af758 > [579763.021046] print_req_error: I/O error, dev nbd0, sector 4523172248 > [579763.021161] XFS (nbd0): Log I/O Error Detected. Shutting down filesystem > [579763.021176] XFS (nbd0): Please umount the filesystem and rectify the > problem(s) > [579763.176834] print_req_error: I/O error, dev nbd0, sector 3221296969 > [579763.176856] print_req_error: I/O error, dev nbd0, sector 2195113096 > [579763.176869] XFS (nbd0): metadata I/O error: block 0xc0011749 > ("xlog_iodone") error 5 numblks 512 > [579763.176884] XFS (nbd0): xfs_do_force_shutdown(0x2) called from line 1261 > of file /build/linux-hwe-xJVMkx/linux-hwe-4.15.0/fs/xfs/xfs_log.c. Return > address = 0x00000000918af758 > [579763.252836] print_req_error: I/O error, dev nbd0, sector 2195113352 > [579763.252859] print_req_error: I/O error, dev nbd0, sector 2195113608 > [579763.252869] print_req_error: I/O error, dev nbd0, sector 2195113864 > [579763.356841] print_req_error: I/O error, dev nbd0, sector 2195114120 > [579763.356885] print_req_error: I/O error, dev nbd0, sector 2195114376 > [579763.358040] XFS (nbd0): writeback error on sector 2195119688 > [579763.916813] block nbd0: Connection timed out > [579768.140839] block nbd0: Connection timed out > [579768.140859] print_req_error: 21 callbacks suppressed > [579768.140860] print_req_error: I/O error, dev nbd0, sector 2195112840 > [579768.141101] XFS (nbd0): writeback error on sector 2195115592 > > /var/log/ceph/ceph-client.archiv.log > > 2019-07-18 14:52:55.387815 7fffcf7fe700 1 -- 10.23.27.200:0/3920476044 --> > 10.23.27.151:6806/2322641 -- osd_op(unknown.0.0:1853 34.132 > 34:4cb446f4:::rbd_header.6c73776b8b4567:head [watch unwatch cookie > 140736414969824] snapc 0=[] ondisk+write+known_if_redirected e256219) v8 -- > 0x7fffc803a340 con 0 > 2019-07-18 14:52:55.388656 7fffe913b700 1 -- 10.23.27.200:0/3920476044 <== > osd.17 10.23.27.151:6806/2322641 90 ==== watch-notify(notify (1) cookie > 140736414969824 notify 1100452225614816 ret 0) v3 ==== 68+0+0 (1852866777 0 > 0) 0x7fffe187b4c0 con 0x7fffc00054d0 > 2019-07-18 14:52:55.388738 7fffe913b700 1 -- 10.23.27.200:0/3920476044 <== > osd.17 10.23.27.151:6806/2322641 91 ==== osd_op_reply(1852 > rbd_header.6c73776b8b4567 [notify cookie 140736550101040] v0'0 uv2102967 > ondisk = 0) v8 ==== 169+0+8 (3077247585 0 3199212159) 0x7fffe0002ef0 con > 0x7fffc00054d0 > 2019-07-18 14:52:55.388815 7fffcffff700 5 librbd::Watcher: 0x7fffc0001010 > notifications_blocked: blocked=1 > 2019-07-18 14:52:55.388904 7fffcffff700 1 -- 10.23.27.200:0/3920476044 --> > 10.23.27.151:6806/2322641 -- osd_op(unknown.0.0:1854 34.132 > 34:4cb446f4:::rbd_header.6c73776b8b4567:head [notify-ack cookie 0] snapc 0=[] > ondisk+read+known_if_redirected e256219) v8 -- 0x7fffc00600a0 con 0 > 2019-07-18 14:52:55.389594 7fffe913b700 1 -- 10.23.27.200:0/3920476044 <== > osd.17 10.23.27.151:6806/2322641 92 ==== osd_op_reply(1853 > rbd_header.6c73776b8b4567 [watch unwatch cookie 140736414969824] > v256219'2102968 uv2102967 ondisk = 0) v8 ==== 169+0+0 (242862078 0 0) > 0x7fffe0002ef0 con 0x7fffc00054d0 > 2019-07-18 14:52:55.389838 7fffcd7fa700 10 librbd::image::CloseRequest: > 0x555555946390 handle_unregister_image_watcher: r=0 > 2019-07-18 14:52:55.389849 7fffcd7fa700 10 librbd::image::CloseRequest: > 0x555555946390 send_flush_readahead > 2019-07-18 14:52:55.389848 7fffe913b700 1 -- 10.23.27.200:0/3920476044 <== > osd.17 10.23.27.151:6806/2322641 93 ==== watch-notify(notify_complete (2) > cookie 140736550101040 notify 1100452225614816 ret 0) v3 ==== 42+0+8 > (2900410459 0 0) 0x7fffe09888e0 con 0x7fffc00054d0 > 2019-07-18 14:52:55.389895 7fffe913b700 1 -- 10.23.27.200:0/3920476044 <== > osd.17 10.23.27.151:6806/2322641 94 ==== osd_op_reply(1854 > rbd_header.6c73776b8b4567 [notify-ack cookie 0] v0'0 uv2102967 ondisk = 0) v8 > ==== 169+0+0 (3363304947 0 0) 0x7fffe0002ef0 con 0x7fffc00054d0 > 2019-07-18 14:52:55.389944 7fffcffff700 20 librbd::watcher::Notifier: > 0x7fffc00010c0 handle_notify: r=0 > 2019-07-18 14:52:55.389955 7fffcffff700 20 librbd::watcher::Notifier: > 0x7fffc00010c0 handle_notify: pending=0 > 2019-07-18 14:52:55.389974 7fffcf7fe700 10 librbd::image::CloseRequest: > 0x555555946390 handle_flush_readahead: r=0 > 2019-07-18 14:52:55.389978 7fffcf7fe700 10 librbd::image::CloseRequest: > 0x555555946390 send_shut_down_cache > 2019-07-18 14:52:55.390119 7fffcf7fe700 10 librbd::image::CloseRequest: > 0x555555946390 handle_shut_down_cache: r=0 > 2019-07-18 14:52:55.390125 7fffcf7fe700 10 librbd::image::CloseRequest: > 0x555555946390 send_flush_op_work_queue > 2019-07-18 14:52:55.390130 7fffcf7fe700 10 librbd::image::CloseRequest: > 0x555555946390 handle_flush_op_work_queue: r=0 > 2019-07-18 14:52:55.390135 7fffcf7fe700 10 librbd::image::CloseRequest: > 0x555555946390 handle_flush_image_watcher: r=0 > 2019-07-18 14:52:55.390168 7fffcf7fe700 10 librbd::ImageState: 0x555555947170 > 0x555555947170 handle_close: r=0 > 2019-07-18 14:52:55.391016 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.151:6806/2322641 conn(0x7fffc00054d0 :-1 s=STATE_OPEN pgs=823187 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.391054 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.152:6804/3417032 conn(0x7fffc8108a70 :-1 s=STATE_OPEN pgs=517757 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.391070 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.150:6814/2366227 conn(0x7fffc807dcb0 :-1 s=STATE_OPEN pgs=529918 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.391098 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.150:6804/2366065 conn(0x7fffc80fb770 :-1 s=STATE_OPEN pgs=912307 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.391120 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.151:6810/2322644 conn(0x7fffc81e2130 :-1 s=STATE_OPEN pgs=612830 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.391129 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.150:6818/2366231 conn(0x7fffc81fa980 :-1 s=STATE_OPEN pgs=791458 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.391145 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.150:6812/2366206 conn(0x555555954480 :-1 s=STATE_OPEN pgs=528620 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.391153 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.151:6818/2322735 conn(0x7fffc80d42f0 :-1 s=STATE_OPEN pgs=696439 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.391161 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.151:6802/2322629 conn(0x7fffc805b6a0 :-1 s=STATE_OPEN pgs=623470 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.391477 7fffe993c700 1 -- 10.23.27.200:0/3920476044 > reap_dead start > 2019-07-18 14:52:55.391566 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.150:6802/2366074 conn(0x7fffc8068670 :-1 s=STATE_OPEN pgs=757332 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.392068 7fffe993c700 1 -- 10.23.27.200:0/3920476044 > reap_dead start > 2019-07-18 14:52:55.392086 7fffe993c700 1 -- 10.23.27.200:0/3920476044 > reap_dead start > 2019-07-18 14:52:55.392093 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.151:6814/2322637 conn(0x7fffc8077360 :-1 s=STATE_OPEN pgs=680587 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.392114 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.151:6816/2322731 conn(0x7fffc8061f00 :-1 s=STATE_OPEN pgs=605415 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.392129 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.152:6820/51139 conn(0x7fffc811d5e0 :-1 s=STATE_OPEN pgs=343039 cs=1 > l=1).mark_down > 2019-07-18 14:52:55.392138 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.152:6800/3416932 conn(0x7fffc820fa10 :-1 s=STATE_OPEN pgs=781718 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.392147 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.152:6806/3417034 conn(0x7fffc80533c0 :-1 s=STATE_OPEN pgs=536148 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.392165 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.152:6808/3417140 conn(0x7fffc8134810 :-1 s=STATE_OPEN pgs=761314 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.392181 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.152:6816/3416957 conn(0x7fffc8146610 :-1 s=STATE_OPEN pgs=837393 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.392214 7fffe993c700 1 -- 10.23.27.200:0/3920476044 > reap_dead start > 2019-07-18 14:52:55.392228 7fffe993c700 1 -- 10.23.27.200:0/3920476044 > reap_dead start > 2019-07-18 14:52:55.392256 7fffe993c700 1 -- 10.23.27.200:0/3920476044 > reap_dead start > 2019-07-18 14:52:55.392286 7fffe993c700 1 -- 10.23.27.200:0/3920476044 > reap_dead start > 2019-07-18 14:52:55.392436 7fffe993c700 1 -- 10.23.27.200:0/3920476044 > reap_dead start > 2019-07-18 14:52:55.392448 7fffe993c700 1 -- 10.23.27.200:0/3920476044 > reap_dead start > 2019-07-18 14:52:55.392452 7fffe993c700 1 -- 10.23.27.200:0/3920476044 > reap_dead start > 2019-07-18 14:52:55.392194 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.150:6810/2366205 conn(0x7fffc810f360 :-1 s=STATE_OPEN pgs=587338 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.392882 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.150:6806/2366079 conn(0x7fffc8005320 :-1 s=STATE_OPEN pgs=588682 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.393119 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.152:6822/3417160 conn(0x7fffc813b3d0 :-1 s=STATE_OPEN pgs=667392 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.393136 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.151:6812/2322646 conn(0x7fffc8148070 :-1 s=STATE_OPEN pgs=671116 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.393150 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.161:6810/3215426 conn(0x7fffc800f2c0 :-1 s=STATE_OPEN pgs=432372 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.393165 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.161:6822/3215746 conn(0x7fffc8166d60 :-1 s=STATE_OPEN pgs=363273 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.393179 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.161:6814/3215437 conn(0x7fffc8045cd0 :-1 s=STATE_OPEN pgs=360091 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.393187 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.161:6806/3215303 conn(0x7fffc80f4e90 :-1 s=STATE_OPEN pgs=301563 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.393195 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.161:6802/3215397 conn(0x7fffc806eec0 :-1 s=STATE_OPEN pgs=288488 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.393644 7fffe993c700 1 -- 10.23.27.200:0/3920476044 > reap_dead start > 2019-07-18 14:52:55.393717 7fffe993c700 1 -- 10.23.27.200:0/3920476044 > reap_dead start > 2019-07-18 14:52:55.393732 7fffe993c700 1 -- 10.23.27.200:0/3920476044 > reap_dead start > 2019-07-18 14:52:55.393736 7fffe993c700 1 -- 10.23.27.200:0/3920476044 > reap_dead start > 2019-07-18 14:52:55.393741 7fffe993c700 1 -- 10.23.27.200:0/3920476044 > reap_dead start > 2019-07-18 14:52:55.393208 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.161:6804/3215221 conn(0x7fffc81259b0 :-1 s=STATE_OPEN pgs=321005 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.393758 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.161:6808/3215396 conn(0x7fffc812d9a0 :-1 s=STATE_OPEN pgs=361415 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.393767 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.161:6818/3215660 conn(0x7fffc817ca00 :-1 s=STATE_OPEN pgs=357502 > cs=1 l=1).mark_down > 2019-07-18 14:52:55.393933 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.153:6801/2546 conn(0x7fffd000ca40 :-1 s=STATE_OPEN pgs=2798975 cs=1 > l=1).mark_down > 2019-07-18 14:52:55.393965 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 >> > 10.23.27.154:6789/0 conn(0x7fffa801a900 :-1 s=STATE_OPEN pgs=7851695 cs=1 > l=1).mark_down > 2019-07-18 14:52:55.394004 7fffe993c700 1 -- 10.23.27.200:0/3920476044 > reap_dead start > 2019-07-18 14:52:55.396891 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 > shutdown_connections > 2019-07-18 14:52:55.397293 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 > shutdown_connections > 2019-07-18 14:52:55.397384 7ffff7fe3000 1 -- 10.23.27.200:0/3920476044 wait > complete. > > > The problem appeared now every 3 reproduction attempts: > > Simple read/write of a file larger than rbd cache works without a problem: > > # dd if=/dev/zero of=la bs=1M count=1024 > 1024+0 records in > 1024+0 records out > 1073741824 bytes (1.1 GB, 1.0 GiB) copied, 27.9281 s, 38.4 MB/s > > # dd if=la of=/dev/null bs=1M > 1024+0 records in > 1024+0 records out > 1073741824 bytes (1.1 GB, 1.0 GiB) copied, 93.6031 s, 11.5 MB/s > > > Environment: > > - Kernel: 4.15.0-45-generic > - Ceph Client: 12.2.11 > - XFS Mount options: > rw,relatime,attr2,discard,largeio,inode64,allocsize=4096k,logbufs=8,logbsize=256k,noquota,_netdev > - Volume: > rbd image 'archive-001-srv_ec': > size 3TiB in 786432 objects > order 22 (4MiB objects) > data_pool: rbd_hdd_ec > block_name_prefix: rbd_data.34.6c73776b8b4567 > format: 2 > features: layering, exclusive-lock, object-map, fast-diff, deep-flatten, > data-pool > flags: > create_timestamp: Thu Jul 11 17:59:00 2019 > - Client configuration > [client] > rbd cache = true > rbd cache size = 536870912 > rbd cache max dirty = 268435456 > rbd cache target dirty = 134217728 > rbd cache max dirty age = 15 > rbd readahead max bytes = 4194304 > - Pool created by > ceph osd erasure-code-profile set archive_profile \ > k=2 \ > m=2 \ > crush-device-class=hdd \ > crush-failure-domain=host > > ceph osd pool create rbd_hdd_ec 64 64 erasure archive_profile > ceph osd pool set rbd_hdd_ec allow_ec_overwrites true > ceph osd pool application enable rbd_hdd_ec rbd > > What can i do? > I never experienced something like this krbd or rbd-nbd (12.2.5 in my > xen-hypervisor, https://github.com/vico-research-and-consulting/RBDSR) > > Regards > Marc > > > _______________________________________________ > ceph-users mailing list > ceph-users@lists.ceph.com > http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com -- Jason _______________________________________________ ceph-users mailing list ceph-users@lists.ceph.com http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
