Project

General

Profile

Actions

Bug #8163

closed

stuck recovering due to a 50 min delay in processing Push op

Added by Samuel Just almost 10 years ago. Updated over 9 years ago.

Status:
Resolved
Priority:
High
Assignee:
-
Category:
-
Target version:
-
% Done:

0%

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

Description

Based on master, 7a61cdbfd533c1092fc61acb7042053251c03f7f (actual branch wip-sam-testing-safe sha1:
ef0fb611696929cb5e5f9a88a45287c61a260479)

2014-04-20 05:21:54.498223 7f8d72499700 15 osd.5 61 enqueue_op 0x3bbcb40 prio 10 cost 460721 latency 0.000293 MOSDPGPush(4.0 61 [PushOp(46d1c488/plana905052-27/head//4, version: 17'42, data_included: [0~459721], data_size: 459721, omap_header_size: 0, omap_entries_size: 0, attrset_size: 3, recovery_info: ObjectRecoveryInfo(46d1c488/plana905052-27/head//4@17'42, copy_subset: [0~459721], clone_subset: {}), after_progress: O
bjectRecoveryProgress(!first, data_recovered_to:459721, data_complete:true, omap_recovered_to:, omap_complete:true), before_progress: ObjectRecoveryProgress(first, data_recovered_to:0, data_complete:false, omap_recovered_to:, omap_complete:false))]) v2
2014-04-20 05:29:55.388973 7f8d7d2e4700 0 log [WRN] : slow request 480.890996 seconds old, received at 2014-04-20 05:21:54.497929: MOSDPGPush(4.0 61 [PushOp(46d1c488/plana905052-27/head//4, version: 17'42, data_included: [0~459721], data_size: 459721, omap_header_size: 0, omap_entries_size: 0, attrset_size: 3, recovery_info: ObjectRecoveryInfo(46d1c488/plana905052-27/head//4@17'42, copy_subset: [0~459721], clone_subset: {}), after_progress: ObjectRecoveryProgress(!first, data_recovered_to:459721, data_complete:true, omap_recovered_to:, omap_complete:true), before_progress: ObjectRecoveryProgress(first, data_recovered_to:0, data_complete:false, omap_recovered_to:, omap_complete:false))]) v2 currently no flag points reached
2014-04-20 05:37:55.472591 7f8d7d2e4700 0 log [WRN] : slow request 960.974613 seconds old, received at 2014-04-20 05:21:54.497929: MOSDPGPush(4.0 61 [PushOp(46d1c488/plana905052-27/head//4, version: 17'42, data_included: [0~459721], data_size: 459721, omap_header_size: 0, omap_entries_size: 0, attrset_size: 3, recovery_info: ObjectRecoveryInfo(46d1c488/plana905052-27/head//4@17'42, copy_subset: [0~459721], clone_subset: {}), after_progress: ObjectRecoveryProgress(!first, data_recovered_to:459721, data_complete:true, omap_recovered_to:, omap_complete:true), before_progress: ObjectRecoveryProgress(first, data_recovered_to:0, data_complete:false, omap_recovered_to:, omap_complete:false))]) v2 currently no flag points reached
2014-04-20 05:53:54.639956 7f8d7d2e4700 0 log [WRN] : slow request 1920.141963 seconds old, received at 2014-04-20 05:21:54.497929: MOSDPGPush(4.0 61 [PushOp(46d1c488/plana905052-27/head//4, version: 17'42, data_included: [0~459721], data_size: 459721, omap_header_size: 0, omap_entries_size: 0, attrset_size: 3, recovery_info: ObjectRecoveryInfo(46d1c488/plana905052-27/head//4@17'42, copy_subset: [0~459721], clone_subset: {}), after_progress: ObjectRecoveryProgress(!first, data_recovered_to:459721, data_complete:true, omap_recovered_to:, omap_complete:true), before_progress: ObjectRecoveryProgress(first, data_recovered_to:0, data_complete:false, omap_recovered_to:, omap_complete:false))]) v2 currently no flag points reached
2014-04-20 06:07:38.983212 7f8d6bc8c700 10 osd.5 pg_epoch: 61 pg[4.0( v 61'4902 lc 17'9 (0'0,61'4902] local-les=61 n=1001 ec=9 les/c 61/58 60/60/60) [5,4] r=0 lpr=60 pi=9-59/5 luod=61'4898 rops=8 crt=58'2677 mlcod 17'9 active+recovering m=623] recover_primary 46d1c488/plana905052-27/head//4 17'42 (missing) (missing head) (recovering) (recovering head)
2014-04-20 06:07:39.627115 7f8d6bc8c700 10 osd.5 pg_epoch: 61 pg[4.0( v 61'4910 lc 17'9 (0'0,61'4910] local-les=61 n=1003 ec=9 les/c 61/58 60/60/60) [5,4] r=0 lpr=60 pi=9-59/5 luod=61'4899 rops=8 crt=58'2677 mlcod 17'9 active+recovering m=623] recover_primary 46d1c488/plana905052-27/head//4 17'42 (missing) (missing head) (recovering) (recovering head)
2014-04-20 06:07:39.727597 7f8d6cc8e700 10 osd.5 61 dequeue_op 0x3bbcb40 prio 10 cost 460721 latency 2745.229668 MOSDPGPush(4.0 61 [PushOp(46d1c488/plana905052-27/head//4, version: 17'42, data_included: [0~459721], data_size: 459721, omap_header_size: 0, omap_entries_size: 0, attrset_size: 3, recovery_info: ObjectRecoveryInfo(46d1c488/plana905052-27/head//4@17'42, copy_subset: [0~459721], clone_subset: {}), after_progress
: ObjectRecoveryProgress(!first, data_recovered_to:459721, data_complete:true, omap_recovered_to:, omap_complete:true), before_progress: ObjectRecoveryProgress(first, data_recovered_to:0, data_complete:false, omap_recovered_to:, omap_complete:false))]) v2 pg pg[4.0( v 61'4910 lc 17'9 (0'0,61'4910] local-les=61 n=1003 ec=9 les/c 61/58 60/60/60) [5,4] r=0 lpr=60 pi=9-59/5 luod=61'4900 rops=9 crt=58'2677 mlcod 0'0 active+rec
overing m=623]

Must be shenanigans in the queue again.


Related issues 2 (0 open2 closed)

Has duplicate Ceph - Bug #7987: osd: backfill/recovery makes no progressDuplicate04/04/2014

Actions
Has duplicate Ceph - Bug #8082: hung recoveryDuplicate04/11/2014

Actions
Actions #1

Updated by Sage Weil almost 10 years ago

  • Priority changed from Urgent to High
Actions #2

Updated by Samuel Just over 9 years ago

  • Status changed from New to Resolved
Actions

Also available in: Atom PDF