Project

General

Profile

Bug #13104

osd: slow requests stuck for a long time

Added by Guang Yang over 8 years ago. Updated over 8 years ago.

Status:
Rejected
Priority:
High
Assignee:
-
Category:
OSD
Target version:
-
% Done:

0%

Source:
other
Tags:
Backport:
Regression:
No
Severity:
2 - major
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

  1. It is a bucket index object.
  2. There was continues writing to the buckets.
  3. The bucket index object is small (< 1MB)

Ceph version: v0.87

2015-08-28 18:41:24.922538 7fdfcbc38700  0 log_channel(default) log [WRN] : slow request 30.740518 seconds old, received at 2015-08-28 18:40:54.181910: osd_op(client.11169.0:45176198 .dir.default.10002.1 [call rgw.bucket_prepare_op] 2.c56f6cf7 ondisk+write+known_if_redirected e2472) currently waiting for degraded object
2015-08-28 18:41:25.922642 7fdfcbc38700  5 osd.81 2472 tick
--
2015-08-28 18:41:54.928524 7fdfcbc38700  0 log_channel(default) log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 60.746545 secs
...
2015-08-28 20:20:43.243028 7fdfcbc38700  0 log_channel(default) log [WRN] : 98 slow reque
sts, 1 included below; oldest blocked for > 5989.061034 secs
2015-08-28 20:20:43.243042 7fdfcbc38700  0 log_channel(default) log [WRN] : slow request 
3840.652611 seconds old, received at 2015-08-28 19:16:42.590333: osd_op(client.11169.0:45
231313 .dir.default.10002.1 [call rgw.bucket_prepare_op] 2.c56f6cf7 ondisk+write+known_if
_redirected e2472) currently waiting for degraded object

History

#1 Updated by Greg Farnum over 8 years ago

  • Status changed from New to Won't Fix

The object is degraded and the OSD is waiting for it to get repaired.

Unless I'm missing some other aspect of the bug, this is definitely a "Won't Fix" sort of thing. (Even if it weren't, Giant isn't getting fixes any more.)

#2 Updated by Guang Yang over 8 years ago

So if the object is degraded and it is a recovery candidate, it would kick off the recovery for the object immediately, and then re-queue the op. Given the size of the object (< 1MB), that should happen in the order of seconds..

However, from the log, we can see that seems the recovery for that object takes forever (sadly I don't have more verbose log to tell which part went wrong :( ).

#3 Updated by Greg Farnum over 8 years ago

  • Status changed from Won't Fix to Need More Info

I'd missed that time jump. Still, I think we'd need something more to go on, especially since much of this has been changed between Giant and Infernalis. :)

#4 Updated by Guang Yang over 8 years ago

I don't have much debug information found from the cluster unless a perf dump:

 { "description": "osd_op(client.11169.0:45231710 .dir.default.10002.1 [] 2.c56f6cf7 RETRY=2 ondisk+retry+write+known_if_redirected e2475)
",
          "initiated_at": "2015-08-28 20:21:06.487746",
          "age": "235.734843",
          "duration": "3.628557",
          "type_data": [
                "commit sent; apply or cleanup",
                { "client": "client.11169",
                  "tid": 45231710},
                [
                    { "time": "2015-08-28 20:21:06.487746",
                      "event": "initiated"},
                    { "time": "2015-08-28 20:21:06.614463",
                      "event": "reached_pg"},
                    { "time": "2015-08-28 20:21:07.587435",
                      "event": "reached_pg"},
                    { "time": "2015-08-28 20:21:07.853259",
                      "event": "reached_pg"},
                    { "time": "2015-08-28 20:21:07.939876",
                      "event": "reached_pg"},
                    { "time": "2015-08-28 20:21:07.939892",
                      "event": "waiting for degraded object"},
                    { "time": "2015-08-28 20:21:09.919391",
                      "event": "reached_pg"},
                    { "time": "2015-08-28 20:21:09.919424",
                      "event": "started"},
                    { "time": "2015-08-28 20:21:09.919437",
                      "event": "started"},
                    { "time": "2015-08-28 20:21:09.920644",
                      "event": "waiting for subops from 66,443"},
                    { "time": "2015-08-28 20:21:09.920770",
                      "event": "commit_queued_for_journal_write"},
                    { "time": "2015-08-28 20:21:09.920818",
                      "event": "write_thread_in_journal_buffer"},
                    { "time": "2015-08-28 20:21:09.920957",
                      "event": "journaled_completion_queued"},
                    { "time": "2015-08-28 20:21:09.921004",
                      "event": "op_commit"},
                    { "time": "2015-08-28 20:21:09.923906",
                      "event": "sub_op_commit_rec"},
                    { "time": "2015-08-28 20:21:09.924089",
                      "event": "sub_op_commit_rec"},
                    { "time": "2015-08-28 20:21:09.924175",
                      "event": "commit_sent"},
                    { "time": "2015-08-28 20:21:10.116271",
                      "event": "op_applied"},
                    { "time": "2015-08-28 20:21:10.116303",
                      "event": "done"}]]}

Which might suggest after two hours the object got recovered.

With Sam's suggestion, I took a look at the PrioritizedQueue's implementation, we might be limited by that we we have a tuning to change the osd recovery op priority to 2, but sadly I don't have anything to prove that :(

#5 Updated by Samuel Just over 8 years ago

  • Status changed from Need More Info to Rejected

This isn't really a bug so much as a desire for a difference in how we handle recovery, I think. Reopen as a feature request with a design direction.

Also available in: Atom PDF