Bug #8876: kcephfs: hang on read of length 0 - CephFS - Ceph

Actions

Copy link

Bug #8876

closed

kcephfs: hang on read of length 0

Added by Sage Weil almost 10 years ago. Updated almost 8 years ago.

Status:

Resolved

Priority:

Urgent

Assignee:

Category:

Target version:

% Done:

Source:

Q/A

Tags:

Backport:

Regression:

Severity:

3 - minor

Reviewed:

Affected Versions:

ceph-qa-suite:

Component(FS):

kceph

Labels (FS):

Pull request ID:

Crash signature (v1):

Crash signature (v2):

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).

Actions

Copy link

Updated by Sage Weil almost 10 years ago

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

Actions

Copy link

Updated by Zheng Yan almost 10 years ago

probably fixed by https://github.com/ceph/ceph-client/commit/d0d0db2268cc343c2361c83510d8e9711021fcce

Actions

Copy link

Updated by Sage Weil almost 10 years ago

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?).

Actions

Copy link