Project

General

Profile

Actions
Copy link

Bug #5425

closed

krbd: xfstest 89 hang, 'read_partial_message skipping long message'

Added by Sage Weil almost 11 years ago. Updated over 10 years ago.

Status:
Resolved
Priority:
Urgent
Assignee:
Ilya Dryomov
Target version:
-
% Done:

0%

Source:
Q/A
Tags:
Backport:
Regression:
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):

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]
Actions
Copy link
 #1

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
Actions
Copy link
 #2

Updated by Ian Colle almost 11 years ago

  • Assignee set to Josh Durgin
Actions
Copy link
 #3

Updated by Sage Weil over 10 years ago

  • Priority changed from Urgent to High
Actions
Copy link
 #4

Updated by Sage Weil over 10 years ago

Date: Mon, 14 Oct 2013 18:21:48 -0700
From: Josh Durgin <>
To: Sage Weil <>,
Cc: ceph-qa <>
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

Actions
Copy link
 #5

Updated by Sage Weil over 10 years ago

  • Assignee deleted (Josh Durgin)
Actions
Copy link
 #6

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

Actions
Copy link
 #7

Updated by Sage Weil over 10 years ago

  • Priority changed from High to Urgent
Actions
Copy link
 #8

Updated by Sage Weil over 10 years ago

ubuntu@teuthology:/a/teuthology-2013-10-26_23:01:27-krbd-next-testing-basic-plana/70455

Actions
Copy link
 #9

Updated by Sage Weil over 10 years ago

  • Status changed from New to 12
Actions
Copy link
 #10

Updated by Sage Weil over 10 years ago

  • Assignee set to Ilya Dryomov
Actions
Copy link
 #11

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

Actions
Copy link
 #12

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
Actions
Copy link

Also available in: Atom PDF