Project

General

Profile

Bug #18927

on_flushed: object ... obc still alive

Added by Sage Weil 2 months ago. Updated 2 months ago.

Status:
Resolved
Priority:
Immediate
Assignee:
Category:
-
Target version:
-
Start date:
02/14/2017
Due date:
% Done:

0%

Source:
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Release:
Needs Doc:
No

Description

 -3882> 2017-02-14 09:24:07.769698 7efe41f01700 10 osd.2 pg_epoch: 543 pg[6.11( v 543'237 lc 530'181 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 rops=1 crt=543'237 mlcod 530'181 active+recovering+degraded m=30] handle_message: 0x7efe68686300
 -3874> 2017-02-14 09:24:07.769726 7efe41f01700 10 osd.2 pg_epoch: 543 pg[6.11( v 543'237 lc 530'181 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 rops=1 crt=543'237 mlcod 530'181 active+recovering+degraded m=30] handle_pull_response ObjectRecoveryInfo(6:8fe5e129:::benchmark_data_smithi046_16502_object4349:head@530'182, size: 4194304, copy_subset: [0~4194304], clone_subset: {})ObjectRecoveryProgress(!first, data_recovered_to:4194304, data_complete:true, omap_recovered_to:, omap_complete:true) data.size() is 1048576 data_included: [3145728~1048576]
 -3867> 2017-02-14 09:24:07.769754 7efe41f01700 10 osd.2 pg_epoch: 543 pg[6.11( v 543'237 lc 530'181 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 rops=1 crt=543'237 mlcod 530'181 active+recovering+degraded m=30] new recovery_info ObjectRecoveryInfo(6:8fe5e129:::benchmark_data_smithi046_16502_object4349:head@530'182, size: 4194304, copy_subset: [0~4194304], clone_subset: {}), new progress ObjectRecoveryProgress(!first, data_recovered_to:4194304, data_complete:true, omap_recovered_to:, omap_complete:true)
 -3858> 2017-02-14 09:24:07.769782 7efe41f01700 20 osd.2 pg_epoch: 543 pg[6.11( v 543'237 lc 530'181 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 rops=1 crt=543'237 mlcod 530'181 active+recovering+degraded m=30] get_temp_recovery_object -8:88000000:::temp_recovering_6.11_530'182_540_head:head
 -3842> 2017-02-14 09:24:07.769809 7efe41f01700 10 osd.2 pg_epoch: 543 pg[6.11( v 543'237 lc 530'181 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 rops=1 crt=543'237 mlcod 530'181 active+recovering+degraded m=30] submit_push_data: Removing oid -8:88000000:::temp_recovering_6.11_530'182_540_head:head from the temp collection
 -3836> 2017-02-14 09:24:07.769837 7efe41f01700 10 osd.2 pg_epoch: 543 pg[6.11( v 543'237 lc 530'181 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 rops=1 crt=543'237 mlcod 530'181 active+recovering+degraded m=30] on_local_recover: 6:8fe5e129:::benchmark_data_smithi046_16502_object4349:head
 -3835> 2017-02-14 09:24:07.769862 7efe41f01700 10 osd.2 pg_epoch: 543 pg[6.11( v 543'237 lc 530'181 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 rops=1 crt=543'237 mlcod 530'181 active+recovering+degraded m=30] got missing 6:8fe5e129:::benchmark_data_smithi046_16502_object4349:head v 530'182
 -3834> 2017-02-14 09:24:07.769888 7efe41f01700 10 osd.2 pg_epoch: 543 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 rops=1 crt=543'237 lcod 530'181 mlcod 530'181 active+recovering+degraded m=29] last_complete now 530'182 log.complete_to 530'183
 -3833> 2017-02-14 09:24:07.769931 7efe41f01700 15 osd.2 pg_epoch: 543 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 rops=1 crt=543'237 lcod 530'181 mlcod 530'181 active+recovering+degraded m=29] publish_stats_to_osd 543:482
 -3832> 2017-02-14 09:24:07.769958 7efe41f01700 10 osd.2 pg_epoch: 543 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 rops=1 crt=543'237 lcod 530'181 mlcod 530'181 active+recovering+degraded m=29] release_backoffs [6:8fe5e129:::benchmark_data_smithi046_16502_object4349:head,6:8fe5e129:::benchmark_data_smithi046_16502_object4349:head)
 -3831> 2017-02-14 09:24:07.769986 7efe41f01700 10 osd.2 pg_epoch: 543 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 rops=1 crt=543'237 lcod 530'181 mlcod 530'181 active+recovering+degraded m=29] readable_with_acting: locs:1,2
 -3703> 2017-02-14 09:24:07.770961 7efe4870e700 10 osd.2 pg_epoch: 543 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 rops=1 crt=543'237 lcod 530'181 mlcod 530'181 active+recovering+degraded m=29] null
 -3627> 2017-02-14 09:24:07.771878 7efe43704700 10 osd.2 pg_epoch: 543 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 rops=1 crt=543'237 lcod 530'181 mlcod 530'181 active+recovering+degraded m=29] handle_advance_map [0,4]/[0,4] -- 0/0
 -3625> 2017-02-14 09:24:07.771906 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 rops=1 crt=543'237 lcod 530'181 mlcod 530'181 active+recovering+degraded m=29] state<Started/Primary/Active>: Active advmap
 -3624> 2017-02-14 09:24:07.771926 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 rops=1 crt=543'237 lcod 530'181 mlcod 530'181 active+recovering+degraded m=29] state<Started>: Started advmap
 -3623> 2017-02-14 09:24:07.771947 7efe43704700 20 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 rops=1 crt=543'237 lcod 530'181 mlcod 530'181 active+recovering+degraded m=29] new interval newup [0,4] newacting [0,4]
 -3622> 2017-02-14 09:24:07.771967 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 rops=1 crt=543'237 lcod 530'181 mlcod 530'181 active+recovering+degraded m=29] state<Started>: should_restart_peering, transitioning to Reset
 -3621> 2017-02-14 09:24:07.771988 7efe43704700  5 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 rops=1 crt=543'237 lcod 530'181 mlcod 530'181 active+recovering+degraded m=29] exit Started/Primary/Active/Recovering 6.119777 9 0.003220
 -3620> 2017-02-14 09:24:07.772011 7efe43704700  5 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 rops=1 crt=543'237 lcod 530'181 mlcod 530'181 active+recovering+degraded m=29] exit Started/Primary/Active 6.131149 0 0.000000
 -3619> 2017-02-14 09:24:07.772037 7efe43704700 20 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 rops=1 crt=543'237 lcod 530'181 mlcod 530'181 active+recovering m=29] agent_stop
 -3618> 2017-02-14 09:24:07.772059 7efe43704700  5 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 rops=1 crt=543'237 lcod 530'181 mlcod 530'181 active+recovering m=29] exit Started/Primary 6.396481 0 0.000000
 -3617> 2017-02-14 09:24:07.772080 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 rops=1 crt=543'237 lcod 530'181 mlcod 530'181 active+recovering m=29] clear_primary_state
 -3616> 2017-02-14 09:24:07.772113 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 luod=0'0 rops=1 crt=543'237 lcod 530'181 mlcod 0'0 active+recovering m=29] release_backoffs [6:88000000::::head,6:90000000::::head)
 -3615> 2017-02-14 09:24:07.772123 7efe43704700 20 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 luod=0'0 rops=1 crt=543'237 lcod 530'181 mlcod 0'0 active+recovering m=29] agent_stop
 -3614> 2017-02-14 09:24:07.772131 7efe43704700  5 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 luod=0'0 rops=1 crt=543'237 lcod 530'181 mlcod 0'0 active+recovering m=29] exit Started 6.396611 0 0.000000
 -3613> 2017-02-14 09:24:07.772141 7efe43704700  5 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 luod=0'0 rops=1 crt=543'237 lcod 530'181 mlcod 0'0 active+recovering m=29] enter Reset
 -3612> 2017-02-14 09:24:07.772148 7efe43704700 20 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=540 pi=516-539/3 luod=0'0 rops=1 crt=543'237 lcod 530'181 mlcod 0'0 active+recovering m=29] set_last_peering_reset 544
 -3611> 2017-02-14 09:24:07.772156 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=544 pi=516-539/3 luod=0'0 rops=1 crt=543'237 lcod 530'181 mlcod 0'0 active+recovering m=29] Clearing blocked outgoing recovery messages
 -3610> 2017-02-14 09:24:07.772164 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=544 pi=516-539/3 luod=0'0 rops=1 crt=543'237 lcod 530'181 mlcod 0'0 active+recovering m=29] Beginning to block outgoing recovery messages
 -3609> 2017-02-14 09:24:07.772173 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=544 pi=516-539/3 luod=0'0 rops=1 crt=543'237 lcod 530'181 mlcod 0'0 active+recovering m=29] state<Reset>: Reset advmap
 -3608> 2017-02-14 09:24:07.772185 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=544 pi=516-539/3 luod=0'0 rops=1 crt=543'237 lcod 530'181 mlcod 0'0 active+recovering m=29] _calc_past_interval_range: already have past intervals back to 518
 -3607> 2017-02-14 09:24:07.772194 7efe43704700 20 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=544 pi=516-539/3 luod=0'0 rops=1 crt=543'237 lcod 530'181 mlcod 0'0 active+recovering m=29] new interval newup [0,4] newacting [0,4]
 -3606> 2017-02-14 09:24:07.772202 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=544 pi=516-539/3 luod=0'0 rops=1 crt=543'237 lcod 530'181 mlcod 0'0 active+recovering m=29] state<Reset>: should restart peering, calling start_peering_interval again
 -3605> 2017-02-14 09:24:07.772211 7efe43704700 20 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [2,1] r=0 lpr=544 pi=516-539/3 luod=0'0 rops=1 crt=543'237 lcod 530'181 mlcod 0'0 active+recovering m=29] set_last_peering_reset 544
 -3604> 2017-02-14 09:24:07.772230 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [0,4] r=-1 lpr=544 pi=516-543/4 luod=0'0 rops=1 crt=543'237 lcod 530'181 active+recovering m=29] start_peering_interval: check_new_interval output: check_new_interval interval(540-543 up [2,1](2) acting [2,1](2)): not rw, up_thru 540 up_from 5 last_epoch_clean 518
 -3603> 2017-02-14 09:24:07.772238 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 540/540/540) [0,4] r=-1 lpr=544 pi=516-543/4 luod=0'0 rops=1 crt=543'237 lcod 530'181 active+recovering m=29]  noting past interval(540-543 up [2,1](2) acting [2,1](2) maybe_went_rw)
 -3602> 2017-02-14 09:24:07.772247 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 luod=0'0 rops=1 crt=543'237 lcod 530'181 active+recovering m=29]  up [2,1] -> [0,4], acting [2,1] -> [0,4], acting_primary 2 -> 0, up_primary 2 -> 0, role 0 -> -1, features acting 1152323339925389307 upacting 1152323339925389307
 -3601> 2017-02-14 09:24:07.772258 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 rops=1 crt=543'237 lcod 530'181 inactive m=29] clear_primary_state
 -3600> 2017-02-14 09:24:07.772267 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 rops=1 crt=543'237 lcod 530'181 inactive m=29] release_backoffs [6:88000000::::head,6:90000000::::head)
 -3599> 2017-02-14 09:24:07.772275 7efe43704700 20 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 rops=1 crt=543'237 lcod 530'181 inactive m=29] agent_stop
 -3598> 2017-02-14 09:24:07.772283 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 rops=1 crt=543'237 lcod 530'181 inactive m=29] on_change
 -3597> 2017-02-14 09:24:07.772289 7efe43704700 15 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 rops=1 crt=543'237 lcod 530'181 inactive m=29]  requeue_ops 
 -3596> 2017-02-14 09:24:07.772294 7efe43704700 15 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 rops=1 crt=543'237 lcod 530'181 inactive m=29]  requeue_ops 
 -3595> 2017-02-14 09:24:07.772299 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 rops=1 crt=543'237 lcod 530'181 inactive m=29] cancel_copy_ops
 -3594> 2017-02-14 09:24:07.772305 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 rops=1 crt=543'237 lcod 530'181 inactive m=29] cancel_flush_ops
 -3593> 2017-02-14 09:24:07.772311 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 rops=1 crt=543'237 lcod 530'181 inactive m=29] cancel_proxy_ops
 -3592> 2017-02-14 09:24:07.772317 7efe43704700 15 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 rops=1 crt=543'237 lcod 530'181 inactive m=29]  requeue_ops 
 -3591> 2017-02-14 09:24:07.772373 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 rops=1 crt=543'237 lcod 530'181 inactive m=29] on_change_cleanup
 -3587> 2017-02-14 09:24:07.772384 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 rops=1 crt=543'237 lcod 530'181 inactive m=29] on_change
 -3584> 2017-02-14 09:24:07.772393 7efe43704700 20 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 rops=1 crt=543'237 lcod 530'181 inactive m=29] exit NotTrimming
 -3583> 2017-02-14 09:24:07.772400 7efe43704700 20 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 rops=1 crt=543'237 lcod 530'181 inactive m=29] enter NotTrimming
 -3549> 2017-02-14 09:24:07.772681 7efe43704700 15 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 rops=1 crt=543'237 lcod 530'181 inactive NOTIFY m=29] clear_stats
 -3547> 2017-02-14 09:24:07.772691 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 rops=1 crt=543'237 lcod 530'181 inactive NOTIFY m=29] on_role_change
 -3545> 2017-02-14 09:24:07.772698 7efe43704700 15 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 rops=1 crt=543'237 lcod 530'181 inactive NOTIFY m=29]  requeue_ops 
 -3542> 2017-02-14 09:24:07.772704 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 rops=1 crt=543'237 lcod 530'181 inactive NOTIFY m=29] cancel_recovery
 -3540> 2017-02-14 09:24:07.772711 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 rops=1 crt=543'237 lcod 530'181 inactive NOTIFY m=29] clear_recovery_state
 -3537> 2017-02-14 09:24:07.772718 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 rops=1 crt=543'237 lcod 530'181 inactive NOTIFY m=29] finish_recovery_op MIN
 -3535> 2017-02-14 09:24:07.772724 7efe43704700 10 osd.2 544 finish_recovery_op pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] MIN dequeue=1 (3/3 rops)
 -3532> 2017-02-14 09:24:07.772731 7efe43704700 15 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29]  requeue_ops 
 -3531> 2017-02-14 09:24:07.772738 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] check_recovery_sources no source osds () went down
 -3527> 2017-02-14 09:24:07.772744 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] on_pool_change
 -3522> 2017-02-14 09:24:07.772752 7efe43704700 20 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] hit_set_clear
 -3519> 2017-02-14 09:24:07.772758 7efe43704700 20 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] agent_stop
 -3516> 2017-02-14 09:24:07.772771 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] handle_activate_map 
 -3515> 2017-02-14 09:24:07.772780 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] take_waiters
 -3512> 2017-02-14 09:24:07.772786 7efe43704700  5 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] exit Reset 0.000645 1 2017-02-14 09:24:07.772744
 -3511> 2017-02-14 09:24:07.772795 7efe43704700  5 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] enter Started
 -3509> 2017-02-14 09:24:07.772801 7efe43704700  5 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] enter Start
 -3505> 2017-02-14 09:24:07.772807 7efe43704700  1 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] state<Start>: transitioning to Stray
 -3503> 2017-02-14 09:24:07.772815 7efe43704700  5 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] exit Start 0.000013 0 0.000000
 -3502> 2017-02-14 09:24:07.772822 7efe43704700  5 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] enter Started/Stray
 -3500> 2017-02-14 09:24:07.772829 7efe43704700 20 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] handle_activate_map: Not dirtying info: last_persisted is 543 while current is 544
 -3495> 2017-02-14 09:24:07.772836 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] handle_peering_event: epoch_sent: 544 epoch_requested: 544 NullEvt
 -3459> 2017-02-14 09:24:07.772949 7efe4d7e8700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] handle_query query(info 0'0) from replica 0
 -2272> 2017-02-14 09:24:07.781050 7efe4870e700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] _committed_pushed_object pg has changed, not touching last_complete_ondisk
 -2270> 2017-02-14 09:24:07.781063 7efe4870e700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] _applied_recovered_object obc(6:8fe5e129:::benchmark_data_smithi046_16502_object4349:head rwstate(none n=0 w=0))
 -2269> 2017-02-14 09:24:07.781085 7efe4870e700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] flushed
 -2200> 2017-02-14 09:24:07.782252 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] handle_peering_event: epoch_sent: 544 epoch_requested: 544 MQuery from 0 query_epoch 544 query: query(info 0'0)
 -2196> 2017-02-14 09:24:07.782268 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] sending info
 -2144> 2017-02-14 09:24:07.782436 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] handle_peering_event: epoch_sent: 544 epoch_requested: 544 IntervalFlush
 -2141> 2017-02-14 09:24:07.782448 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] state<Started>: Ending blocked outgoing recovery messages
 -2137> 2017-02-14 09:24:07.782468 7efe43704700 10 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] handle_peering_event: epoch_sent: 544 epoch_requested: 544 FlushedEvt
 -2135> 2017-02-14 09:24:07.782479 7efe43704700 15 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29]  requeue_ops 
 -2131> 2017-02-14 09:24:07.782489 7efe43704700 -1 osd.2 pg_epoch: 544 pg[6.11( v 543'237 lc 530'182 (0'0,543'237] local-les=541 n=175 ec=516 les/c/f 541/518/0 544/544/544) [0,4] r=-1 lpr=544 pi=516-543/4 crt=543'237 lcod 530'181 inactive NOTIFY m=29] on_flushed: object 6:8fe5e129:::benchmark_data_smithi046_16502_object4349:head obc still alive

/a/sage-2017-02-14_06:55:13-rados-wip-pg-split-interval---basic-smithi/813266

also on another branch,

 -2295> 2017-02-14 11:56:29.826294 7fb1f1f88700  7 osd.4 pg_epoch: 438 pg[5.c( v 438'845 lc 386'49 (0'0,438'845] local-les=437 n=755 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 rops=3 crt=438'845 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] issue_repop rep_tid 2781 o 5:35f7ed7f:::benchmark_data_smithi012_19272_object720:head
 -2289> 2017-02-14 11:56:29.826688 7fb1f1f88700 10 osd.4 pg_epoch: 438 pg[5.c( v 438'845 lc 386'49 (0'0,438'845] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 rops=3 crt=438'845 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] append_log log((0'0,438'845], crt=438'845) [438'846 (386'46) delete   5:35f7ed7f:::benchmark_data_smithi012_19272_object720:head by client.5014.0:12822 2017-02-14 11:56:28.887417 0]
 -2286> 2017-02-14 11:56:29.827041 7fb1f1f88700 10 osd.4 pg_epoch: 438 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'845 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] add_log_entry 438'846 (386'46) delete   5:35f7ed7f:::benchmark_data_smithi012_19272_object720:head by client.5014.0:12822 2017-02-14 11:56:28.887417 0
 -2278> 2017-02-14 11:56:29.827385 7fb1f1f88700 20 osd.4 pg_epoch: 438 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] rollforward: entry=438'846 (386'46) delete   5:35f7ed7f:::benchmark_data_smithi012_19272_object720:head by client.5014.0:12822 2017-02-14 11:56:28.887417 0
 -1966> 2017-02-14 11:56:29.828308 7fb1f1f88700 10 osd.4 pg_epoch: 438 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] eval_repop repgather(0x560099ef2240 438'846 rep_tid=2781 committed?=0 applied?=0 r=0) wants=d
 -1825> 2017-02-14 11:56:29.828716 7fb1f478d700 10 osd.4 439 dequeue_op 0x560098b9a1c0 prio 63 cost 0 latency 0.885443 osd_op(client.5014.0:12849 5.8224c97c benchmark_data_smithi012_19272_object747 [delete] snapc 0=[] ondisk+write+known_if_redirected e438) v7 pg pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751]
 -1707> 2017-02-14 11:56:29.829064 7fb1f478d700 10 osd.4 pg_epoch: 438 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] handle_message: 0x560098b9a1c0
 -1675> 2017-02-14 11:56:29.829395 7fb1f478d700 20 osd.4 pg_epoch: 438 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] do_op: op osd_op(client.5014.0:12849 5.8224c97c benchmark_data_smithi012_19272_object747 [delete] snapc 0=[] ondisk+write+known_if_redirected e438) v7
 -1667> 2017-02-14 11:56:29.829742 7fb1f478d700 20 osd.4 pg_epoch: 438 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] op_has_sufficient_caps pool=5 (unique_pool_4 ) owner=0 need_read_cap=0 need_write_cap=1 classes=[] -> yes
 -1662> 2017-02-14 11:56:29.830073 7fb1f478d700 10 osd.4 pg_epoch: 438 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] do_op osd_op(client.5014.0:12849 5.8224c97c benchmark_data_smithi012_19272_object747 [delete] snapc 0=[] ondisk+write+known_if_redirected e438) v7 may_write -> write-ordered flags ondisk+write+known_if
_redirected
 -1621> 2017-02-14 11:56:29.830406 7fb1f478d700 10 osd.4 pg_epoch: 438 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] readable_with_acting: locs:0,4
 -1553> 2017-02-14 11:56:29.830787 7fb1f478d700 10 osd.4 pg_epoch: 438 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] get_object_context: found obc in cache: 0x56009a5e4300
 -1507> 2017-02-14 11:56:29.831238 7fb1f478d700 10 osd.4 pg_epoch: 438 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] get_object_context: 0x56009a5e4300 5:3e932441:::benchmark_data_smithi012_19272_object747:head rwstate(read n=1 w=0) oi: 5:3e932441:::benchmark_data_smithi012_19272_object747:head(386'49 client.5014.0:7
48 dirty|data_digest|omap_digest s 4194304 uv 49 dd ce718bfc od ffffffff alloc_hint [4194304 4194304 53]) ssc: 0x5600a3e02220 snapset: 0=[]:[]+head
 -1474> 2017-02-14 11:56:29.831574 7fb1f478d700 10 osd.4 pg_epoch: 438 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] find_object_context 5:3e932441:::benchmark_data_smithi012_19272_object747:head @head oi=5:3e932441:::benchmark_data_smithi012_19272_object747:head(386'49 client.5014.0:748 dirty|data_digest|omap_digest
 s 4194304 uv 49 dd ce718bfc od ffffffff alloc_hint [4194304 4194304 53])
 -1468> 2017-02-14 11:56:29.831922 7fb1f478d700 10 osd.4 pg_epoch: 438 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] readable_with_acting: locs:0,4
 -1415> 2017-02-14 11:56:29.832269 7fb1f478d700 25 osd.4 pg_epoch: 438 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] do_op oi 5:3e932441:::benchmark_data_smithi012_19272_object747:head(386'49 client.5014.0:748 dirty|data_digest|omap_digest s 4194304 uv 49 dd ce718bfc od ffffffff alloc_hint [4194304 4194304 53])
 -1386> 2017-02-14 11:56:29.832744 7fb1f478d700 20 osd.4 pg_epoch: 438 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] do_op waiting for rw locks 
 -1384> 2017-02-14 11:56:29.833099 7fb1fcf9e700 10 osd.4 pg_epoch: 438 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] null
 -1257> 2017-02-14 11:56:29.833459 7fb1f5f90700 10 osd.4 pg_epoch: 438 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] handle_advance_map [4,1]/[4,1] -- 4/4
 -1212> 2017-02-14 11:56:29.833876 7fb1f5f90700 10 osd.4 pg_epoch: 439 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] state<Started/Primary/Active>: Active advmap
 -1121> 2017-02-14 11:56:29.834272 7fb1f5f90700 10 osd.4 pg_epoch: 439 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] state<Started>: Started advmap
 -1078> 2017-02-14 11:56:29.834681 7fb1f5f90700 20 osd.4 pg_epoch: 439 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] new interval newup [4,1] newacting [4,1]
 -1019> 2017-02-14 11:56:29.835106 7fb1f5f90700 10 osd.4 pg_epoch: 439 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] state<Started>: should_restart_peering, transitioning to Reset
 -1017> 2017-02-14 11:56:29.835505 7fb1f5f90700  5 osd.4 pg_epoch: 439 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] exit Started/Primary/Active/WaitRemoteRecoveryReserved 4.684788 6 0.009034
 -1010> 2017-02-14 11:56:29.835909 7fb1f5f90700  5 osd.4 pg_epoch: 439 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active+recovery_wait+degraded m=751] exit Started/Primary/Active 5.083125 0 0.000000
 -1009> 2017-02-14 11:56:29.836296 7fb1f5f90700 20 osd.4 pg_epoch: 439 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active m=751] agent_stop
 -1008> 2017-02-14 11:56:29.836684 7fb1f5f90700  5 osd.4 pg_epoch: 439 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active m=751] exit Started/Primary 6.173646 0 0.000000
 -1007> 2017-02-14 11:56:29.837062 7fb1f5f90700 10 osd.4 pg_epoch: 439 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=438'845 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 386'45 active m=751] clear_primary_state
 -1006> 2017-02-14 11:56:29.837583 7fb1f5f90700 10 osd.4 pg_epoch: 439 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 436/436/436) [4,0] r=0 lpr=436 pi=383-435/3 luod=0'0 lua=438'845 rops=3 crt=438'846 lcod 386'46 mlcod 0'0 active m=751] release_backoffs [5:30000000::::head,5:40000000::::head)
...
  -494> 2017-02-14 11:56:29.839745 7fb1fcf9e700 10 osd.4 pg_epoch: 439 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 439/439/436) [4,1] r=0 lpr=439 pi=383-438/4 crt=438'846 lcod 386'46 mlcod 0'0 peering m=751] flushed
  -211> 2017-02-14 11:56:29.840922 7fb1f5f90700 10 osd.4 pg_epoch: 439 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 439/439/436) [4,1] r=0 lpr=439 pi=383-438/4 crt=438'846 lcod 386'46 mlcod 0'0 peering m=751] handle_peering_event: epoch_sent: 439 epoch_requested: 439 MNotifyRec from 0 notify: (query_epoch:439, epoch_sent:439, info:5.c( v 438'845 (0'0,438'845] local-les=437 n=755 ec=383 les/c/f 437/419/0 439/439/436)) features: 0xffddff8eea4fffb
  -207> 2017-02-14 11:56:29.840934 7fb1f5f90700  7 osd.4 pg_epoch: 439 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 439/439/436) [4,1] r=0 lpr=439 pi=383-438/4 crt=438'846 lcod 386'46 mlcod 0'0 peering m=751] state<Started/Primary>: handle_pg_notify from osd.0
  -199> 2017-02-14 11:56:29.840943 7fb1f5f90700 10 osd.4 pg_epoch: 439 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 439/439/436) [4,1] r=0 lpr=439 pi=383-438/4 crt=438'846 lcod 386'46 mlcod 0'0 peering m=751] state<Started/Primary>: pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 439/439/436) [4,1] r=0 lpr=439 pi=383-438/4 crt=438'846 lcod 386'46 mlcod 0'0 peering m=751] got dup osd.0 info 5.c( v 438'845 (0'0,438'845] local-les=437 n=755 ec=383 les/c/f 437/419/0 439/439/436), identical to ours
  -184> 2017-02-14 11:56:29.841000 7fb1f5f90700 10 osd.4 pg_epoch: 439 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 439/439/436) [4,1] r=0 lpr=439 pi=383-438/4 crt=438'846 lcod 386'46 mlcod 0'0 peering m=751] handle_peering_event: epoch_sent: 439 epoch_requested: 439 MNotifyRec from 1 notify: (query_epoch:439, epoch_sent:439, info:5.c( v 431'788 (0'0,431'788] local-les=402 n=788 ec=383 les/c/f 437/419/0 439/439/436)) features: 0xffddff8eea4fffb
  -181> 2017-02-14 11:56:29.841007 7fb1f5f90700  7 osd.4 pg_epoch: 439 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 439/439/436) [4,1] r=0 lpr=439 pi=383-438/4 crt=438'846 lcod 386'46 mlcod 0'0 peering m=751] state<Started/Primary>: handle_pg_notify from osd.1
  -180> 2017-02-14 11:56:29.841014 7fb1f5f90700 10 osd.4 pg_epoch: 439 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 439/439/436) [4,1] r=0 lpr=439 pi=383-438/4 crt=438'846 lcod 386'46 mlcod 0'0 peering m=751] state<Started/Primary>: pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 439/439/436) [4,1] r=0 lpr=439 pi=383-438/4 crt=438'846 lcod 386'46 mlcod 0'0 peering m=751] got dup osd.1 info 5.c( v 431'788 (0'0,431'788] local-les=402 n=788 ec=383 les/c/f 437/419/0 439/439/436), identical to ours
  -178> 2017-02-14 11:56:29.841026 7fb1f5f90700 10 osd.4 pg_epoch: 439 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 439/439/436) [4,1] r=0 lpr=439 pi=383-438/4 crt=438'846 lcod 386'46 mlcod 0'0 peering m=751] handle_peering_event: epoch_sent: 439 epoch_requested: 439 FlushedEvt
  -177> 2017-02-14 11:56:29.841033 7fb1f5f90700 15 osd.4 pg_epoch: 439 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 439/439/436) [4,1] r=0 lpr=439 pi=383-438/4 crt=438'846 lcod 386'46 mlcod 0'0 peering m=751]  requeue_ops 0x560098b9a1c0,0x56009cc48a00,0x56009cc4b700,0x56009cc4a800
  -175> 2017-02-14 11:56:29.841051 7fb1f5f90700 -1 osd.4 pg_epoch: 439 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 439/439/436) [4,1] r=0 lpr=439 pi=383-438/4 crt=438'846 lcod 386'46 mlcod 0'0 peering m=751] on_flushed: object 5:31d39dca:::benchmark_data_smithi012_19272_object744:head obc still alive
  -174> 2017-02-14 11:56:29.841064 7fb1f5f90700 -1 osd.4 pg_epoch: 439 pg[5.c( v 438'846 lc 386'49 (0'0,438'846] local-les=437 n=754 ec=383 les/c/f 437/419/0 439/439/436) [4,1] r=0 lpr=439 pi=383-438/4 crt=438'846 lcod 386'46 mlcod 0'0 peering m=751] on_flushed: object 5:3e932441:::benchmark_data_smithi012_19272_object747:head obc still alive

/a/sage-2017-02-14_07:00:43-rados-wip-sage-testing---basic-smithi/813611

Related issues

Related to Bug #18993: osd/PrimaryLogPG.cc: 9888: FAILED assert(object_contexts.empty()) Resolved 02/20/2017

History

#1 Updated by Samuel Just 2 months ago

  • Assignee set to Samuel Just

#2 Updated by Samuel Just 2 months ago

  • Status changed from New to Testing

#3 Updated by Samuel Just 2 months ago

  • Status changed from Testing to Need Review

#4 Updated by Sage Weil 2 months ago

  • Status changed from Need Review to Resolved

#5 Updated by Josh Durgin about 2 months ago

  • Related to Bug #18993: osd/PrimaryLogPG.cc: 9888: FAILED assert(object_contexts.empty()) added

Also available in: Atom PDF