18 Jul
2019
18 Jul
'19
6:47 p.m.
Hello cephers,
rbd-nbd crashes in a reproducible way here.
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