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
18 Jul
18 Jul
7:10 p.m.
New subject: [ceph-users] reproducable rbd-nbd crashes
On Thu, Jul 18, 2019 at 1:47 PM Marc Schöchlin <ms(a)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(a)lists.ceph.com
http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
--
Jason
19 Jul
19 Jul
8:42 a.m.
New subject: [ceph-users] reproducable rbd-nbd crashes
Hello Jason,
Am 18.07.19 um 20:10 schrieb Jason Dillaman:
On Thu, Jul 18, 2019 at 1:47 PM Marc Schöchlin
<ms(a)256bit.org> wrote:
I do not get a crash report of rbd-nbd.
I seems that "rbd-nbd" just terminates, and crashes the xfs filesystem because
the nbd device is not available anymore.
("rbd nbd ls" shows no mapped device anymore)
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 have also a 36TB XFS (non_ec) volume on this virtual system mapped by krbd which
is under really heavy read/write usage.
I never experienced problems like this on this system with similar usage patterns.
The volume which is involved in the problem only handles a really low load and i was
capable to create the error situation by using the simple "find . -type f -name
"*.sql" -exec ionice -c3 nice -n 20 gzip -v {} \;" command.
I copied and read ~1.5 TB of data to this volume without a problem - it seems that the
gzip command provokes a io pattern which leads to the error situation.
As described i use a luminous "12.2.11" client which does not support that
"--timeout" option (btw. a backport would be nice).
Our ceph system runs with a heavy write load, therefore we already set a 60 seconds
timeout using the following code:
(https://github.com/OnApp/nbd-kernel_mod/blob/master/nbd_set_timeout.c)
We have ~500 heavy load rbd-nbd devices in our xen cluster (rbd-nbd 12.2.5, kernel
4.4.0+10, centos clone) and ~20 high load krbd devices (kernel 4.15.0-45, ubuntu 16.04) -
we never experienced problems like this.
We only experience problems like this with rbd-nbd > 12.2.5 on ubuntu 16.04 (kernel
4.15) or ubuntu 18.04 (kernel 4.15) with erasure encoding or without.
Regards
Marc
9:20 p.m.
New subject: [ceph-users] reproducable rbd-nbd crashes
On 07/19/2019 02:42 AM, Marc Schöchlin wrote:
Hello Jason,
Am 18.07.19 um 20:10 schrieb Jason Dillaman:
Are you only using the nbd_set_timeout tool for this newer kernel combo
to try and workaround the disconnect+io_errors problem in newer kernels,
or did you use that tool to set a timeout with older kernels? I am just
trying to clarify the problem, because the kernel changed behavior and I
am not sure if your issue is the very slow IO or that the kernel now
escalates its error handler by default.
With older kernels no timeout would be set for each command by default,
so if you were not running that tool then you would not see the nbd
disconnect+io_errors+xfs issue. You would just see slow IOs.
With newer kernels, like 4.15, nbd.ko always sets a per command timeout
even if you do not set it via a nbd ioctl/netlink command. By default
the timeout is 30 seconds. After the timeout period then the kernel does
that disconnect+IO_errors error handling which causes xfs to get errors.
On Thu, Jul 18, 2019 at 1:47 PM Marc Schöchlin
<ms(a)256bit.org> wrote:
I do not get a crash report of rbd-nbd.
I seems that "rbd-nbd" just terminates, and crashes the xfs filesystem because
the nbd device is not available anymore.
("rbd nbd ls" shows no mapped device anymore)
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 have also a 36TB XFS (non_ec) volume on this virtual system mapped by krbd which
is under really heavy read/write usage.
I never experienced problems like this on this system with similar usage patterns.
The volume which is involved in the problem only handles a really low load and i was
capable to create the error situation by using the simple "find . -type f -name
"*.sql" -exec ionice -c3 nice -n 20 gzip -v {} \;" command.
I copied and read ~1.5 TB of data to this volume without a problem - it seems that the
gzip command provokes a io pattern which leads to the error situation.
As described i use a luminous "12.2.11" client which does not support that
"--timeout" option (btw. a backport would be nice).
Our ceph system runs with a heavy write load, therefore we already set a 60 seconds
timeout using the following code:
(https://github.com/OnApp/nbd-kernel_mod/blob/master/nbd_set_timeout.c)
We have ~500 heavy load rbd-nbd devices in our xen cluster (rbd-nbd 12.2.5, kernel
4.4.0+10, centos clone) and ~20 high load krbd devices (kernel 4.15.0-45, ubuntu 16.04) -
we never experienced problems like this.
We only experience problems like this with rbd-nbd > 12.2.5 on ubuntu 16.04 (kernel
4.15) or ubuntu 18.04 (kernel 4.15) with erasure encoding or without.
22 Jul
22 Jul
noon
New subject: [ceph-users] reproducable rbd-nbd crashes
Hello Mike,
i attached inline comments.
Am 19.07.19 um 22:20 schrieb Mike Christie:
I only use nbd_set_timeout with the 4.15
kernels on obuntu 16.04 and 18.04 because we experienced problems some weeks ago on
"fstrim" activities a few weeks ago.
Adding timeouts of 60 seconds seemed to help, but did not solve the problem completely.
The problem situation described in my request is a different distuation but seems to be
sourced in the same rootcause.
Not using the nbd_set_timeout tool, results in the same but more prominent problem
situations :-)
(test with unloading the nbd module and re-executing the test)
We have ~500 heavy load rbd-nbd devices in our
xen cluster (rbd-nbd 12.2.5, kernel 4.4.0+10, centos clone) and ~20 high load krbd devices
(kernel 4.15.0-45, ubuntu 16.04) - we never experienced problems like this.
We only experience problems like this with rbd-nbd > 12.2.5 on ubuntu 16.04 (kernel
4.15) or ubuntu 18.04 (kernel 4.15) with erasure encoding or without.
Are you only using the nbd_set_timeout tool for this newer kernel combo
to try and workaround the disconnect+io_errors problem in newer kernels,
or did you use that tool to set a timeout with older kernels? I am just
trying to clarify the problem, because the kernel changed behavior and I
am not sure if your issue is the very slow IO or that the kernel now
escalates its error handler by default.
With older kernels no timeout would be set for each command by default,
so if you were not running that tool then you would not see the nbd
disconnect+io_errors+xfs issue. You would just see slow IOs.
With newer kernels, like 4.15, nbd.ko always sets a per command timeout
even if you do not set it via a nbd ioctl/netlink command. By default
the timeout is 30 seconds. After the timeout period then the kernel does
that disconnect+IO_errors error handling which causes xfs to get errors.
Did i get you correctly: Setting a unlimited timeout should prevent crashes on
kernel 4.15?
For testing purposes i set the timeout to unlimited ("nbd_set_ioctl /dev/nbd0
0", on already mounted device).
I re-executed the problem procedure and discovered that the compression-procedure crashes
not at the same file, but crashes 30 seconds later with the same crash behavior.
Regards
Marc
3:48 p.m.
New subject: [ceph-users] reproducable rbd-nbd crashes
On 07/22/2019 06:00 AM, Marc Schöchlin wrote:
It looks like with newer kernels there is no way to turn it off.
You can set it really high. There is no max check and so it depends on
various calculations and what some C types can hold and how your kernel
is compiled. You should be able to set the timer to an hour.
With older
kernels no timeout would be set for each command by default,
so if you were not running that tool then you would not see the nbd
disconnect+io_errors+xfs issue. You would just see slow IOs.
With newer kernels, like 4.15, nbd.ko always sets a per command timeout
even if you do not set it via a nbd ioctl/netlink command. By default
the timeout is 30 seconds. After the timeout period then the kernel does
that disconnect+IO_errors error handling which causes xfs to get errors.
Did i get you correctly: Setting a unlimited timeout should prevent crashes on
kernel 4.15?
For testing purposes i set the timeout to unlimited ("nbd_set_ioctl /dev/nbd0
0", on already mounted device).
I re-executed the problem procedure and discovered that the compression-procedure crashes
not at the same file, but crashes 30 seconds later with the same crash behavior.
0 will cause the default timeout of 30 secs to be used.
4:01 p.m.
New subject: [ceph-users] reproducable rbd-nbd crashes
On 07/19/2019 02:42 AM, Marc Schöchlin wrote:
We have ~500 heavy load rbd-nbd devices in our xen
cluster (rbd-nbd 12.2.5, kernel 4.4.0+10, centos clone) and ~20 high load krbd devices
(kernel 4.15.0-45, ubuntu 16.04) - we never experienced problems like this.
For this setup, do you have 257 or more rbd-nbd devices running on a
single system?
If so then you are hitting another bug where newer kernels only support
256 devices. It looks like a regression was added when mq and netlink
support was added upstream. You can create more then 256 devices, but
some devices will not be able to execute any IO. Commands sent to the
rbd-nbd device are going to always timeout and you will see the errors
in your log.
I am testing some patches for that right now.
23 Jul
23 Jul
5:26 a.m.
New subject: [ceph-users] reproducable rbd-nbd crashes
Hi Mike,
Am 22.07.19 um 17:01 schrieb Mike Christie:
On 07/19/2019 02:42 AM, Marc Schöchlin wrote:
No, these rbd-nbds are distributed over more than a dozen of xen
dom-0 systems on our xenservers.
We have ~500 heavy load rbd-nbd devices in our
xen cluster (rbd-nbd 12.2.5, kernel 4.4.0+10, centos clone) and ~20 high load krbd devices
(kernel 4.15.0-45, ubuntu 16.04) - we never experienced problems like this.
For
this setup, do you have 257 or more rbd-nbd devices running on a
single system? If so then you are hitting another bug where newer
kernels only support
256 devices. It looks like a regression was added when mq and netlink
support was added upstream. You can create more then 256 devices, but
some devices will not be able to execute any IO. Commands sent to the
rbd-nbd device are going to always timeout and you will see the errors
in your log.
I am testing some patches for that right now.
From my point of view there is no limitation besides io from ceph cluster perspective.
Regards
Marc
6:28 a.m.
New subject: [ceph-users] reproducable rbd-nbd crashes
Hi Mike,
Am 22.07.19 um 16:48 schrieb Mike Christie:
Okay, then the usage description of
https://github.com/OnApp/nbd-kernel_mod/blob/master/nbd_set_timeout.c not seems to be
correct :-)
Regards
Marc
On 07/22/2019 06:00 AM, Marc Schöchlin wrote:
It looks like with newer kernels there is no way to turn it off.
You can set it really high. There is no max check and so it depends on
various calculations and what some C types can hold and how your kernel
is compiled. You should be able to set the timer to an hour.
Okay, i already experimented with high timeouts (i.e 600 seconds). As i can remember this
leaded to pretty unusable system if i put high amounts of io on the ec volume.
This system also runs als krbd volume which saturates the system with ~30-60% iowait -
this volume never had a problem.
A comment writer in https://tracker.ceph.com/issues/40822#change-141205 suggests me to
reduce the rbd cache.
What do you think about that?
With
older kernels no timeout would be set for each command by default,
so if you were not running that tool then you would not see the nbd
disconnect+io_errors+xfs issue. You would just see slow IOs.
With newer kernels, like 4.15, nbd.ko always sets a per command timeout
even if you do not set it via a nbd ioctl/netlink command. By default
the timeout is 30 seconds. After the timeout period then the kernel does
that disconnect+IO_errors error handling which causes xfs to get errors.
Did i get you correctly: Setting a unlimited timeout should prevent crashes on
kernel 4.15? For testing purposes i set the timeout to
unlimited ("nbd_set_ioctl /dev/nbd0 0", on already mounted device).
I re-executed the problem procedure and discovered that the compression-procedure crashes
not at the same file, but crashes 30 seconds later with the same crash behavior.
0 will cause the default timeout of 30 secs to be used.
24 Jul
24 Jul
5:31 p.m.
New subject: [ceph-users] reproducable rbd-nbd crashes
On 07/23/2019 12:28 AM, Marc Schöchlin wrote:
It is correct for older kernels:
With older kernels you could turn it off by setting it to 0, and it was
off by default.
With newer kernels, it's on by default, and there is no way to turn it off.
So with older kernels, you could have been hitting similar slow downs,
but you would have never seen the timeouts, io errors, etc.
> For
testing purposes i set the timeout to unlimited ("nbd_set_ioctl /dev/nbd0 0", on
already mounted device).
> >> I re-executed the problem procedure and discovered that the
compression-procedure crashes not at the same file, but crashes 30 seconds later with the
same crash behavior.
> >>
> 0 will cause the default timeout of 30 secs to be used.
Okay, then the usage
description of https://github.com/OnApp/nbd-kernel_mod/blob/master/nbd_set_timeout.c not
seems to be correct :-)
1760
days inactive
1766
days old
9 comments
3 participants
participants (3)
-
Jason Dillaman -
Marc Schöchlin -
Mike Christie