Bug #5425
closedkrbd: xfstest 89 hang, 'read_partial_message skipping long message'
Added by Sage Weil almost 11 years ago. Updated over 10 years ago.
0%
Description
... [57282.470312] libceph: osd2 10.214.132.12:6800 socket closed (con state OPEN) [57282.479143] rbd: obj_request ffff880220c7a000 already marked done [57282.479143] [57628.949485] libceph: osd4 10.214.133.30:6805 socket closed (con state OPEN) [57628.958143] rbd: obj_request ffff8802234ca000 already marked done [57628.958143] [57811.199040] libceph: osd1 10.214.132.12:6808 socket closed (con state OPEN) [57811.208038] libceph: read_partial_message skipping long message (8192 > 0) [58183.333356] libceph: osd2 10.214.132.12:6800 socket closed (con state OPEN) [58183.341853] rbd: obj_request ffff880220c7a000 already marked done [58183.341853]
Updated by Sage Weil almost 11 years ago
root@plana34:~# cat /sys/kernel/debug/ceph/*/osdc 280328 osd1 2.f42ad495 rb.0.1012.2cd89a32.000000000001 read
but on osd1,
cranked up osd logging and kicked osd.1, and see
2013-06-23 08:06:31.720016 7f1b02324700 1 -- 10.214.132.12:6808/13655 <== client.4109 10.214.131.6:0/3122654300 1 ==== osd_op(client.4109.1:280328 rb.0.1012.2cd89a32.000000000001 [read 2588672 ~8192] 2.f42ad495 RETRY=1 e7) v4 ==== 170+0+0 (4097517131 0 0) 0x59e8d80 con 0x3c64160 ... 2013-06-23 08:06:32.791038 7f1afcb19700 10 osd.1 pg_epoch: 8 pg[2.15( v 4'22927 (4'19926,4'22927] local-les=8 n=47 ec=1 les/c 6/6 7/7/7) [1,3] r=0 lpr=7 pi=3-6/2 mlcod 0'0 active] read got 8192 / 8192 bytes from obj f42ad495/rb.0.1012.2cd89a32.000000000001/head//2 ... 2013-06-23 08:06:32.791153 7f1afcb19700 1 -- 10.214.132.12:6808/13655 --> 10.214.131.6:0/3122654300 -- osd_op_reply(280328 rb.0.1012.2cd89a32.000000000001 [read 2588672~8192] ondisk = 0) v4 -- ?+0 0x41ab400 con 0x3c64160
Updated by Sage Weil over 10 years ago
Date: Mon, 14 Oct 2013 18:21:48 -0700
From: Josh Durgin <josh.durgin@inktank.com>
To: Sage Weil <sage@inktank.com>, sandon@inktank.com
Cc: ceph-qa <ceph-qa@ceph.com>
Subject: Re: [Ceph-qa] hung tests
[ The following text is in the "ISO-8859-1" character set. ]
[ Your display is set for the "ANSI_X3.4-1968" character set. ]
[ Some characters may be displayed incorrectly. ]On 10/14/2013 06:00 PM, Sage Weil wrote:
looks like a bunch of krbd stuff is hung:
I'm guessing the hangs have something to do with this:
[529065.933957] libceph: read_partial_message skipping long message (65536 > 0)
I don't see any kernel changes that would have caused this though - did
the osd reply encoding change recently - maybe filling in the
individual rvals broke this?
plana12 locked scheduled_teuthology@teuthology
"/var/lib/teuthworker/archive/teuthology-2013-10-10_22:05:25-krbd-master-testi
ng-basic-plana/44790"
plana60 locked scheduled_teuthology@teuthology
"/var/lib/teuthworker/archive/teuthology-2013-10-10_22:05:25-krbd-master-testi
ng-basic-plana/44790"
plana61 locked scheduled_teuthology@teuthology
"/var/lib/teuthworker/archive/teuthology-2013-10-10_22:05:25-krbd-master-testi
ng-basic-plana/44790"
plana89 locked scheduled_teuthology@teuthology
"/var/lib/teuthworker/archive/teuthology-2013-10-10_22:05:25-krbd-master-testi
ng-basic-plana/44790"
plana94 locked scheduled_teuthology@teuthology
"/var/lib/teuthworker/archive/teuthology-2013-10-10_22:05:25-krbd-master-testi
ng-basic-plana/44790"
plana06 locked scheduled_teuthology@teuthology
"/var/lib/teuthworker/archive/teuthology-2013-10-10_23:00:02-rados-next-testin
g-basic-plana/45242"
plana09 locked scheduled_teuthology@teuthology
"/var/lib/teuthworker/archive/teuthology-2013-10-10_23:00:02-rados-next-testin
g-basic-plana/45242"
plana70 locked scheduled_teuthology@teuthology
"/var/lib/teuthworker/archive/teuthology-2013-10-11_23:01:22-krbd-master-testi
ng-basic-plana/47459"
plana72 locked scheduled_teuthology@teuthology
"/var/lib/teuthworker/archive/teuthology-2013-10-11_23:01:22-krbd-master-testi
ng-basic-plana/47460"
plana87 locked scheduled_teuthology@teuthology
"/var/lib/teuthworker/archive/teuthology-2013-10-11_23:01:22-krbd-master-testi
ng-basic-plana/47480"
plana85 locked scheduled_teuthology@teuthology
"/var/lib/teuthworker/archive/teuthology-2013-10-11_23:01:22-krbd-master-testi
ng-basic-plana/47481"also some older stuff that should get nuked?
plana37 locked scheduled_dzafman@ubuntu
"/var/lib/teuthworker/archive/dzafman-2013-10-09_09:20:22-fs-wip-libcephfs-emp
-rb-testing-basic-plana/41907"
plana88 locked scheduled_samuelj@slider
"/var/lib/teuthworker/archive/samuelj-2013-10-03_21:22:50-rados-wip-5992-2-tes
ting-basic-plana/32940"
plana20 locked scheduled_teuthology@teuthology
"/var/lib/teuthworker/archive/teuthology-2013-09-29_23:01:18-krbd-master-testi
ng-basic-plana/25108"
plana36 locked scheduled_teuthology@teuthology
"/var/lib/teuthworker/archive/teuthology-2013-10-02_01:30:25-upgrade-fs-next-t
esting-basic-plana/30325"
plana52 locked scheduled_teuthology@teuthology
"/var/lib/teuthworker/archive/teuthology-2013-10-09_19:01:10-rbd-dumpling-test
ing-basic-plana/42243"it's chewing on stuff scheduled 2 days ago :(. we might want to nuke the
queue so that we're testing current code...s
Updated by Sage Weil over 10 years ago
ubuntu@teuthology:/var/lib/teuthworker/archive/teuthology-2013-10-15_23:02:48-krbd-next-testing-basic-plana/54525
Updated by Sage Weil over 10 years ago
ubuntu@teuthology:/a/teuthology-2013-10-26_23:01:27-krbd-next-testing-basic-plana/70455
Updated by Ilya Dryomov over 10 years ago
- Status changed from 12 to Fix Under Review
For the record, this turned out to be not related to xfstest 89 at all,
it was just a coincidence. See ceph-devel ("libceph: #5425 fix") and
commit "libceph: fix preallocation check in get_reply()" for details.
wip-5425; https://github.com/ceph/ceph-client/commits/wip-5425
Updated by Ilya Dryomov over 10 years ago
- Status changed from Fix Under Review to Resolved
As noted in the ceph-devel post referenced in the above comment, this
is bug is sort of twofold. The first problem is fixed in wip-5425, the
second problem is the fallback case where we allocate a new reply
message: we allocate a message with the front_len we need, but we don't
migrate data pages from the old message. Naturally, when the time
comes to read in the data the new message is skipped with
[57811.208038] libceph: read_partial_message skipping long message (8192 > 0)
However, with the original problem that forced us into the (broken)
fallback path fixed, Sage and I agreed that the fallback path is not
worth worrying about:
<sagelap> i wouldn't worry about the fallback case.. if the reply message is bigger than we expect it that is probably a bug elwewhere. the attempt to allocate a new message is a last ditch effort to cope
So, resolved with the following commits added to the testing branch of
ceph-client.git:
f2be82b0058e libceph: fix preallocation check in get_reply() 3f0a4ac55fe0 libceph: rename front to front_len in get_reply() 3cea4c3071d4 libceph: rename ceph_msg::front_max to front_alloc_len