Bug #8876
closed
kcephfs: hang on read of length 0
Added by Sage Weil almost 10 years ago.
Updated almost 8 years ago.
Description
[674656.313542] libceph: osd5 down
[674657.368218] libceph: tid 148530 reply has 49839 bytes we had only 0 bytes ready
[674680.713864] libceph: osd5 up
[674683.728762] libceph: tid 148530 reply has 49839 bytes we had only 0 bytes ready
flab:367203 01:25 PM # cat /proc/2080/stack
[<ffffffffa06c9bdf>] ceph_osdc_wait_request+0x2f/0x100 [libceph]
[<ffffffffa06cb26b>] ceph_osdc_readpages+0x14b/0x1c0 [libceph]
[<ffffffffa0713c43>] striped_read+0x143/0x350 [ceph]
[<ffffffffa071471c>] ceph_sync_read.isra.12+0x1dc/0x300 [ceph]
[<ffffffffa0714a52>] ceph_aio_read+0x212/0x360 [ceph]
[<ffffffff811d1f0a>] do_sync_read+0x5a/0x90
[<ffffffff811d30e1>] vfs_read+0xb1/0x180
[<ffffffff811d335f>] SyS_read+0x4f/0xb0
[<ffffffff8178527f>] tracesys+0xe1/0xe6
[<ffffffffffffffff>] 0xffffffffffffffff
2014-07-18 13:24:50.294071 7fa84a9b3700 1 -- 10.214.133.134:6826/26983 <== client.206191 10.214.131.102:0/921266500 1 ==== osd_op(client.206191.1:148530 10001296a89.00000000 [read 3428405~0 [1@-1]] 0.a95e59dd RETRY=1 retry+read e348892) v4 ==== 159+0+0 (3831072992 0 0) 0x23436240 con 0x18a14b00
2014-07-18 13:24:53.286215 7fa8439a5700 1 -- 10.214.133.134:6826/26983 --> 10.214.131.102:0/921266500 -- osd_op_reply(148530 10001296a89.00000000 [read 3428405~49839] v0'0 uv423857 ondisk = 0) v6 -- ?+0 0x2740500 con 0x18a14b00
I think the bug here is that the kernel client is sending a read of len 0 in the first place, right? The OSD is (correctly) translating that into a read of the whole object (well, starting from offset).
got debug output from a resend, but not very helpful.. i think teh bug is in the striped read code, which happened log ago.
Jul 18 13:28:21 flab kernel: [674892.444502] libceph: ===== ffff88000a871268 3654 from mon2 41=osd_map len 211+0 (3059104111 0 0) =====
Jul 18 13:28:21 flab kernel: [674892.444507] libceph: handle_map have 348922
Jul 18 13:28:21 flab kernel: [674892.444512] libceph: 1 inc maps
Jul 18 13:28:21 flab kernel: [674892.444517] libceph: applying incremental map 348923 len 171
Jul 18 13:28:21 flab kernel: [674892.444523] libceph: osdmap_apply_incremental ffff88007ca56c1c to ffff88007ca56cc7 len 171
Jul 18 13:28:21 flab kernel: [674892.444529] libceph: 0 pool names
Jul 18 13:28:21 flab kernel: [674892.444532] libceph: osd5 down
Jul 18 13:28:21 flab kernel: [674892.444538] libceph: inc osdmap epoch 348923 max_osd 71
Jul 18 13:28:21 flab kernel: [674892.444542] libceph: kick_requests
Jul 18 13:28:21 flab kernel: [674892.444548] libceph: map_request ffff8802295a2bc0 tid 148530
Jul 18 13:28:21 flab kernel: [674892.444556] libceph: ceph_oloc_oid_to_pg '10001296a89.00000000' pgid 0.a95e59dd
Jul 18 13:28:21 flab kernel: [674892.444584] libceph: map_request tid 148530 pgid 0.a95e59dd osd34 (was osd5)
Jul 18 13:28:21 flab kernel: [674892.444591] libceph: __remove_osd_from_lru ffff880036028000
Jul 18 13:28:21 flab kernel: [674892.444596] libceph: ffff8802295a2bc0 tid 148530 requeued on osd34
Jul 18 13:28:21 flab kernel: [674892.444601] libceph: __reset_osd ffff88007c4ce000 osd5
Jul 18 13:28:21 flab kernel: [674892.444606] libceph: __remove_osd ffff88007c4ce000
Jul 18 13:28:21 flab kernel: [674892.444615] libceph: con_close ffff88007c4ce030 peer 10.214.133.134:6826
Jul 18 13:28:21 flab kernel: [674892.444619] libceph: reset_connection ffff88007c4ce030
Jul 18 13:28:21 flab kernel: [674892.444625] libceph: con_close_socket on ffff88007c4ce030 sock ffff8800559ba580
Jul 18 13:28:21 flab kernel: [674892.444657] libceph: ceph_sock_state_change ffff88007c4ce030 state = 1 sk_state = 4
Jul 18 13:28:21 flab kernel: [674892.444733] libceph: con_sock_state_closed con ffff88007c4ce030 sock 3 -> 1
Jul 18 13:28:21 flab kernel: [674892.444738] libceph: put_osd ffff88007c4ce000 1 -> 0
Jul 18 13:28:21 flab kernel: [674892.444745] libceph: buffer_release ffff88007b5323e0
Jul 18 13:28:21 flab kernel: [674892.444760] libceph: __send_queued
Jul 18 13:28:21 flab kernel: [674892.444828] libceph: send_request ffff8802295a2bc0 tid 148530 to osd34 flags 24 pg 0.a95e59dd
Jul 18 13:28:21 flab kernel: [674892.444851] libceph: get_osd ffff880036028000 1 -> 2
Jul 18 13:28:21 flab kernel: [674892.444862] libceph: ----- ffff88022af807c0 to osd34 42=osd_op len 159+0+0 -----
...
Jul 18 13:28:23 flab kernel: [674893.774697] libceph: ceph_sock_data_ready on ffff880036028030 state = 5, queueing work
Jul 18 13:28:23 flab kernel: [674893.774702] libceph: get_osd ffff880036028000 1 -> 2
Jul 18 13:28:23 flab kernel: [674893.774707] libceph: queue_con_delay ffff880036028030 0
Jul 18 13:28:23 flab kernel: [674893.774723] libceph: try_read start on ffff880036028030 state 5
Jul 18 13:28:23 flab kernel: [674893.774724] libceph: try_read tag 1 in_base_pos 0
Jul 18 13:28:23 flab kernel: [674893.774727] libceph: try_read got tag 7
Jul 18 13:28:23 flab kernel: [674893.774728] libceph: prepare_read_message ffff880036028030
Jul 18 13:28:23 flab kernel: [674893.774730] libceph: read_partial_message con ffff880036028030 msg (null)
Jul 18 13:28:23 flab kernel: [674893.774733] libceph: got hdr type 43 front 187 data 49839
Jul 18 13:28:23 flab kernel: [674893.774735] libceph: ceph_msg_revoke_incoming msg ffff88022af81078 null con
Jul 18 13:28:23 flab kernel: [674893.774737] libceph: tid 148530 reply has 49839 bytes we had only 0 bytes ready
Jul 18 13:28:23 flab kernel: [674893.774738] libceph: alloc_msg said skip message
Jul 18 13:28:23 flab kernel: [674893.774740] libceph: try_read done on ffff880036028030 ret 0
Jul 18 13:28:23 flab kernel: [674893.774741] libceph: try_write start ffff880036028030 state 5
Jul 18 13:28:23 flab kernel: [674893.774743] libceph: try_write out_kvec_bytes 0
The workload that triggered this was one client doing repeated tail -1, and another client doing appends. Can we construct a teuthology test to do that? Maybe something as simple as:
- parallel:
- client.0:
- timeout 3600 bash -c "while true ; do echo foo >> file ; sleep .01 ; done"
- client.1:
- timeout 3600 bash -c "while true ; do tail -1 file ; sleep .07 ; done"
(with a suitable path?).
- Status changed from 12 to Resolved
- Component(FS) kceph added
Also available in: Atom
PDF