Hi Oliver,
Thanks for your reply.
The problem could have been caused by crashing/flapping OSD's. The cluster is stable now, but lots of pg problems remain.
HEALTH_ERR 4 pgs degraded; 158 pgs inconsistent; 4 pgs stuck degraded; 1 pgs stuck inactive; 10 pgs stuck unclean; 4 pgs stuck undersized; 4 pgs undersized; recovery 1489/523934 objects degraded (0.284%); recovery 2620/523934 objects misplaced (0.500%); 158 scrub errors
Example: for pg 1.32 :
$ ceph health detail | grep "pg 1.32"
pg 1.32 is stuck inactive for 13260.118985, current state undersized+degraded+peered, last acting [6]
pg 1.32 is stuck unclean for 945560.550800, current state undersized+degraded+peered, last acting [6]
pg 1.32 is stuck undersized for 12855.304944, current state undersized+degraded+peered, last acting [6]
pg 1.32 is stuck degraded for 12855.305305, current state undersized+degraded+peered, last acting [6]
pg 1.32 is undersized+degraded+peered, acting [6]
$ ceph pg repair 1.32
instructing pg 1.32 on osd.6 to repair
$ ceph pg deep-scrub 1.32
Its odd that I never do see any log on osd.6 about scrubbing or repairing that pg (after waiting many hours). I attached "ceph pg query" and a grep of osd logs for that page. If there is a better way to provide large logs please let me know.
For reference the last mention of that pg in the logs is:
2016-04-30 09:24:44.703785 975b9350 20 osd.6 349418 kicking pg 1.32
2016-04-30 09:24:44.703880 975b9350 30 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] lock
2016-04-30 09:24:44.703785 975b9350 20 osd.6 349418 kicking pg 1.32
2016-04-30 09:24:44.703880 975b9350 30 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] lock
Suggestions appreciated,
Blade.
On Sat, Apr 30, 2016 at 9:31 AM, Blade Doyle <blade.doyle@xxxxxxxxx> wrote:
Blade.Thanks Much,Hi Ceph-Users,Help with how to resolve these would be appreciated.
2016-04-30 09:25:58.399634 9b809350 0 log_channel(cluster) log [INF] : 4.97 deep-scrub starts
2016-04-30 09:26:00.041962 93009350 0 -- 192.168.2.52:6800/6640 >> 192.168.2.32:0/3983425916 pipe(0x27406000 sd=111 :6800 s=0 pgs=0 cs=0 l=0 c=0x272da0a0).accept peer addr is really 192.168.2.32:0/3983425916 (socket is 192.168.2.32:38514/0)
2016-04-30 09:26:15.415883 9b809350 -1 log_channel(cluster) log [ERR] : 4.97 deep-scrub stat mismatch, got 284/282 objects, 0/0 clones, 145/145 dirty, 0/0 omap, 4/2 hit_set_archive, 137/137 whiteouts, 365855441/365855441 bytes,340/340 hit_set_archive bytes.
2016-04-30 09:26:15.415953 9b809350 -1 log_channel(cluster) log [ERR] : 4.97 deep-scrub 1 errors
2016-04-30 09:26:15.416425 9b809350 0 log_channel(cluster) log [INF] : 4.97 scrub starts
2016-04-30 09:26:15.682311 9b809350 -1 log_channel(cluster) log [ERR] : 4.97 scrub stat mismatch, got 284/282 objects, 0/0 clones, 145/145 dirty, 0/0 omap, 4/2 hit_set_archive, 137/137 whiteouts, 365855441/365855441 bytes,340/340 hit_set_archive bytes.
2016-04-30 09:26:15.682392 9b809350 -1 log_channel(cluster) log [ERR] : 4.97 scrub 1 errors
{
"state": "undersized+degraded+peered",
"snap_trimq": "[]",
"epoch": 350071,
"up": [
6
],
"acting": [
6
],
"actingbackfill": [
"6"
],
"info": {
"pgid": "1.32",
"last_update": "338815'7745",
"last_complete": "338815'7745",
"log_tail": "20981'4727",
"last_user_version": 99149,
"last_backfill": "MAX",
"purged_snaps": "[]",
"history": {
"epoch_created": 17,
"last_epoch_started": 349421,
"last_epoch_clean": 349491,
"last_epoch_split": 0,
"same_up_since": 349420,
"same_interval_since": 349490,
"same_primary_since": 349420,
"last_scrub": "338815'7745",
"last_scrub_stamp": "2016-04-21 22:05:56.984147",
"last_deep_scrub": "338815'7745",
"last_deep_scrub_stamp": "2016-04-21 22:05:56.984147",
"last_clean_scrub_stamp": "2016-04-21 22:05:56.984147"
},
"stats": {
"version": "338815'7745",
"reported_seq": "61243",
"reported_epoch": "350068",
"state": "undersized+degraded+peered",
"last_fresh": "2016-05-02 19:30:21.999749",
"last_change": "2016-05-02 17:10:46.953333",
"last_active": "2016-05-02 17:04:01.016156",
"last_peered": "2016-05-02 19:30:21.999749",
"last_clean": "2016-04-21 22:05:40.584862",
"last_became_active": "0.000000",
"last_became_peered": "0.000000",
"last_unstale": "2016-05-02 19:30:21.999749",
"last_undegraded": "2016-05-02 17:10:45.831094",
"last_fullsized": "2016-05-02 17:10:45.831094",
"mapping_epoch": 349418,
"log_start": "20981'4727",
"ondisk_log_start": "20981'4727",
"created": 17,
"last_epoch_clean": 349491,
"parent": "0.0",
"parent_split_bits": 0,
"last_scrub": "338815'7745",
"last_scrub_stamp": "2016-04-21 22:05:56.984147",
"last_deep_scrub": "338815'7745",
"last_deep_scrub_stamp": "2016-04-21 22:05:56.984147",
"last_clean_scrub_stamp": "2016-04-21 22:05:56.984147",
"log_size": 3018,
"ondisk_log_size": 3018,
"stats_invalid": "0",
"stat_sum": {
"num_bytes": 1093634830,
"num_objects": 435,
"num_object_clones": 0,
"num_object_copies": 870,
"num_objects_missing_on_primary": 0,
"num_objects_degraded": 435,
"num_objects_misplaced": 0,
"num_objects_unfound": 0,
"num_objects_dirty": 435,
"num_whiteouts": 0,
"num_read": 13971,
"num_read_kb": 4849705,
"num_write": 7699,
"num_write_kb": 7329440,
"num_scrub_errors": 0,
"num_shallow_scrub_errors": 0,
"num_deep_scrub_errors": 0,
"num_objects_recovered": 8312,
"num_bytes_recovered": 18718600924,
"num_keys_recovered": 0,
"num_objects_omap": 0,
"num_objects_hit_set_archive": 0,
"num_bytes_hit_set_archive": 0
},
"up": [
6
],
"acting": [
6
],
"blocked_by": [],
"up_primary": 6,
"acting_primary": 6
},
"empty": 0,
"dne": 0,
"incomplete": 0,
"last_epoch_started": 349421,
"hit_set_history": {
"current_last_update": "0'0",
"current_last_stamp": "0.000000",
"current_info": {
"begin": "0.000000",
"end": "0.000000",
"version": "0'0"
},
"history": []
}
},
"peer_info": [],
"recovery_state": [
{
"name": "Started\/Primary\/Active",
"enter_time": "2016-05-02 17:10:46.928233",
"might_have_unfound": [],
"recovery_progress": {
"backfill_targets": [],
"waiting_on_backfill": [],
"last_backfill_started": "0\/\/0\/\/-1",
"backfill_info": {
"begin": "0\/\/0\/\/-1",
"end": "0\/\/0\/\/-1",
"objects": []
},
"peer_backfill_info": [],
"backfills_in_flight": [],
"recovering": [],
"pg_backend": {
"pull_from_peer": [],
"pushing": []
}
},
"scrub": {
"scrubber.epoch_start": "0",
"scrubber.active": 0,
"scrubber.waiting_on": 0,
"scrubber.waiting_on_whom": []
}
},
{
"name": "Started",
"enter_time": "2016-05-02 17:10:45.830655"
}
],
"agent_state": {}
}
2016-04-30 09:24:36.570071 a20b9350 30 osd.6 pg_epoch: 349417 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349346 crt=338815'7743 lcod 0'0 mlcod 0'0 active+undersized+degraded MUST_DEEP_SCRUB MUST_SCRUB] lock 2016-04-30 09:24:36.570222 a20b9350 10 osd.6 pg_epoch: 349417 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349346 crt=338815'7743 lcod 0'0 mlcod 0'0 active+undersized+degraded MUST_DEEP_SCRUB MUST_SCRUB] handle_advance_map []/[] -- -1/-1 2016-04-30 09:24:36.570294 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349346 crt=338815'7743 lcod 0'0 mlcod 0'0 active+undersized+degraded MUST_DEEP_SCRUB MUST_SCRUB] state<Started/Primary/Active>: Active advmap 2016-04-30 09:24:36.570342 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349346 crt=338815'7743 lcod 0'0 mlcod 0'0 active+undersized+degraded MUST_DEEP_SCRUB MUST_SCRUB] state<Started>: Started advmap 2016-04-30 09:24:36.570385 a20b9350 20 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349346 crt=338815'7743 lcod 0'0 mlcod 0'0 active+undersized+degraded MUST_DEEP_SCRUB MUST_SCRUB] new interval newup [] newacting [] 2016-04-30 09:24:36.570426 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349346 crt=338815'7743 lcod 0'0 mlcod 0'0 active+undersized+degraded MUST_DEEP_SCRUB MUST_SCRUB] state<Started>: should_restart_peering, transitioning to Reset 2016-04-30 09:24:36.570470 a20b9350 5 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349346 crt=338815'7743 lcod 0'0 mlcod 0'0 active+undersized+degraded MUST_DEEP_SCRUB MUST_SCRUB] exit Started/Primary/Active/Clean 49948.216076 244 0.004963 2016-04-30 09:24:36.570525 a20b9350 5 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349346 crt=338815'7743 lcod 0'0 mlcod 0'0 active+undersized+degraded MUST_DEEP_SCRUB MUST_SCRUB] exit Started/Primary/Active 49949.841695 0 0.000000 2016-04-30 09:24:36.570577 a20b9350 20 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349346 crt=338815'7743 lcod 0'0 mlcod 0'0 active MUST_DEEP_SCRUB MUST_SCRUB] agent_stop 2016-04-30 09:24:36.570621 a20b9350 5 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349346 crt=338815'7743 lcod 0'0 mlcod 0'0 active MUST_DEEP_SCRUB MUST_SCRUB] exit Started/Primary 49950.921394 0 0.000000 2016-04-30 09:24:36.570667 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349346 crt=338815'7743 lcod 0'0 mlcod 0'0 active MUST_DEEP_SCRUB MUST_SCRUB] clear_primary_state 2016-04-30 09:24:36.570714 a20b9350 20 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349346 luod=0'0 crt=338815'7743 lcod 0'0 mlcod 0'0 active MUST_DEEP_SCRUB MUST_SCRUB] agent_stop 2016-04-30 09:24:36.570759 a20b9350 5 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349346 luod=0'0 crt=338815'7743 lcod 0'0 mlcod 0'0 active MUST_DEEP_SCRUB MUST_SCRUB] exit Started 49950.921839 0 0.000000 2016-04-30 09:24:36.570807 a20b9350 5 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349346 luod=0'0 crt=338815'7743 lcod 0'0 mlcod 0'0 active MUST_DEEP_SCRUB MUST_SCRUB] enter Reset 2016-04-30 09:24:36.570848 a20b9350 20 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349346 luod=0'0 crt=338815'7743 lcod 0'0 mlcod 0'0 active MUST_DEEP_SCRUB MUST_SCRUB] set_last_peering_reset 349418 2016-04-30 09:24:36.570889 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349418 luod=0'0 crt=338815'7743 lcod 0'0 mlcod 0'0 active MUST_DEEP_SCRUB MUST_SCRUB] Clearing blocked outgoing recovery messages 2016-04-30 09:24:36.570930 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349418 luod=0'0 crt=338815'7743 lcod 0'0 mlcod 0'0 active MUST_DEEP_SCRUB MUST_SCRUB] Not blocking outgoing recovery messages 2016-04-30 09:24:36.570972 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349418 luod=0'0 crt=338815'7743 lcod 0'0 mlcod 0'0 active MUST_DEEP_SCRUB MUST_SCRUB] state<Reset>: Reset advmap 2016-04-30 09:24:36.571019 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349418 luod=0'0 crt=338815'7743 lcod 0'0 mlcod 0'0 active MUST_DEEP_SCRUB MUST_SCRUB] _calc_past_interval_range start epoch 349347 >= end epoch 349346, nothing to do 2016-04-30 09:24:36.571064 a20b9350 20 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349418 luod=0'0 crt=338815'7743 lcod 0'0 mlcod 0'0 active MUST_DEEP_SCRUB MUST_SCRUB] new interval newup [] newacting [] 2016-04-30 09:24:36.571105 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349418 luod=0'0 crt=338815'7743 lcod 0'0 mlcod 0'0 active MUST_DEEP_SCRUB MUST_SCRUB] state<Reset>: should restart peering, calling start_peering_interval again 2016-04-30 09:24:36.571146 a20b9350 20 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349418 luod=0'0 crt=338815'7743 lcod 0'0 mlcod 0'0 active MUST_DEEP_SCRUB MUST_SCRUB] set_last_peering_reset 349418 2016-04-30 09:24:36.571222 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [] r=-1 lpr=349418 pi=349346-349417/1 luod=0'0 crt=338815'7743 lcod 0'0 active MUST_DEEP_SCRUB MUST_SCRUB] start_peering_interval: check_new_interval output: generate_past_intervals interval(349346-349417 up [6](6) acting [6](6)): not rw, up_thru 349415 up_from 349346 last_epoch_clean 349347 2016-04-30 09:24:36.571267 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349346/349346/349346) [] r=-1 lpr=349418 pi=349346-349417/1 luod=0'0 crt=338815'7743 lcod 0'0 active MUST_DEEP_SCRUB MUST_SCRUB] noting past interval(349346-349417 up [6](6) acting [6](6) maybe_went_rw) 2016-04-30 09:24:36.571312 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 luod=0'0 crt=338815'7743 lcod 0'0 active MUST_DEEP_SCRUB MUST_SCRUB] up [6] -> [], acting [6] -> [], acting_primary 6 -> -1, up_primary 6 -> -1, role 0 -> -1 2016-04-30 09:24:36.571359 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive MUST_DEEP_SCRUB MUST_SCRUB] clear_primary_state 2016-04-30 09:24:36.571399 a20b9350 20 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive MUST_DEEP_SCRUB MUST_SCRUB] agent_stop 2016-04-30 09:24:36.571438 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive MUST_DEEP_SCRUB MUST_SCRUB] on_change 2016-04-30 09:24:36.571475 a20b9350 15 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive MUST_DEEP_SCRUB MUST_SCRUB] requeue_ops 2016-04-30 09:24:36.571514 a20b9350 15 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive MUST_DEEP_SCRUB MUST_SCRUB] requeue_ops 2016-04-30 09:24:36.571556 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive] cancel_copy_ops 2016-04-30 09:24:36.571593 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive] cancel_flush_ops 2016-04-30 09:24:36.571629 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive] cancel_proxy_read_ops 2016-04-30 09:24:36.571669 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive] on_change_cleanup 2016-04-30 09:24:36.571758 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive] on_change 2016-04-30 09:24:36.571812 a20b9350 20 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive] exit NotTrimming 2016-04-30 09:24:36.571855 a20b9350 20 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive] enter NotTrimming 2016-04-30 09:24:36.571895 a20b9350 15 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] clear_stats 2016-04-30 09:24:36.571935 a20b9350 15 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] requeue_ops 2016-04-30 09:24:36.571971 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] on_role_change 2016-04-30 09:24:36.572007 a20b9350 15 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] requeue_ops 2016-04-30 09:24:36.572043 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] cancel_recovery 2016-04-30 09:24:36.572080 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] clear_recovery_state 2016-04-30 09:24:36.572122 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] check_recovery_sources no source osds () went down 2016-04-30 09:24:36.572171 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] handle_activate_map 2016-04-30 09:24:36.572217 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] update_heartbeat_peers 6,11 -> 2016-04-30 09:24:36.572261 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] take_waiters 2016-04-30 09:24:36.572304 a20b9350 5 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] exit Reset 0.001496 1 0.001875 2016-04-30 09:24:36.572359 a20b9350 5 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] enter Started 2016-04-30 09:24:36.572402 a20b9350 5 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] enter Start 2016-04-30 09:24:36.572441 a20b9350 1 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] state<Start>: transitioning to Stray 2016-04-30 09:24:36.572490 a20b9350 5 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] exit Start 0.000087 0 0.000000 2016-04-30 09:24:36.572539 a20b9350 5 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] enter Started/Stray 2016-04-30 09:24:36.572610 a20b9350 20 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] handle_activate_map: Not dirtying info: last_persisted is 349347 while current is 349418 2016-04-30 09:24:36.572657 a20b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] handle_peering_event: epoch_sent: 349418 epoch_requested: 349418 NullEvt 2016-04-30 09:24:36.572810 a20b9350 5 filestore(/var/lib/ceph/osd/ceph-6) queue_transactions existing osr(1.32 0xabf8de0)/0xabf8de0 2016-04-30 09:24:36.627573 af439350 5 filestore(/var/lib/ceph/osd/ceph-6) _journaled_ahead 0x270c6b40 seq 5427187 osr(1.32 0xabf8de0) 0x26f78140 2016-04-30 09:24:36.627589 af439350 5 filestore(/var/lib/ceph/osd/ceph-6) queue_op 0x270c6b40 seq 5427187 osr(1.32 0xabf8de0) 1069 bytes (queue has 50 ops and 62002 bytes) 2016-04-30 09:24:37.029862 a28b9350 5 osd.6 pg_epoch: 349418 pg[4.49( v 349397'96722 (258100'93713,349397'96722] local-les=349347 n=334 ec=25477 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349346 crt=347648'96716 lcod 348851'96720 mlcod 348851'96720 active+inconsistent] exit Started/Primary 49951.327937 0 0.000000 2016-04-30 09:24:37.030020 a28b9350 5 osd.6 pg_epoch: 349418 pg[4.49( v 349397'96722 (258100'93713,349397'96722] local-les=349347 n=334 ec=25477 les/c 349347/349347 349346/349346/349346) [6] r=0 lpr=349346 luod=0'0 crt=347648'96716 lcod 348851'96720 mlcod 0'0 active+inconsistent] exit Started 49951.328409 0 0.000000 2016-04-30 09:24:37.054812 ae439350 5 filestore(/var/lib/ceph/osd/ceph-6) _do_op 0x270c6b40 seq 5427187 osr(1.32 0xabf8de0)/0xabf8de0 start 2016-04-30 09:24:37.054854 ae439350 15 filestore(/var/lib/ceph/osd/ceph-6) _omap_setkeys 1.32_head/32//head//1 2016-04-30 09:24:37.223756 975b9350 20 osd.6 349418 kicking pg 1.32 2016-04-30 09:24:37.223772 975b9350 30 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] lock 2016-04-30 09:24:37.223846 975b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] on_shutdown 2016-04-30 09:24:37.223935 975b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] cancel_copy_ops 2016-04-30 09:24:37.224171 975b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] cancel_flush_ops 2016-04-30 09:24:37.224213 975b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] cancel_proxy_read_ops 2016-04-30 09:24:37.224259 975b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] on_change 2016-04-30 09:24:37.224314 975b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] clear_primary_state 2016-04-30 09:24:37.224366 975b9350 20 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] agent_stop 2016-04-30 09:24:37.224408 975b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] cancel_recovery 2016-04-30 09:24:37.224448 975b9350 10 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] clear_recovery_state 2016-04-30 09:24:37.235997 ae439350 20 filestore(/var/lib/ceph/osd/ceph-6) _omap_setkeys 1.32_head/32//head//1 = 0 2016-04-30 09:24:37.236104 ae439350 10 filestore(/var/lib/ceph/osd/ceph-6) _finish_op 0x270c6b40 seq 5427187 osr(1.32 0xabf8de0)/0xabf8de0 2016-04-30 09:24:37.236173 adc39350 30 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] lock 2016-04-30 09:24:41.328644 afc39350 20 journal do_write latency 0.065652 2016-04-30 09:24:41.328699 afc39350 20 journal do_write queueing finishers through seq 5427453 2016-04-30 09:24:41.328717 afc39350 10 journal queue_completions_thru seq 5427453 queueing seq 5427453 0x2bf93d00 lat 0.086251 2016-04-30 09:24:41.328764 afc39350 5 journal put_throttle finished 1 ops and 1098 bytes, now 0 ops and 0 bytes 2016-04-30 09:24:41.328783 afc39350 20 journal write_thread_entry going to sleep 2016-04-30 09:24:41.328769 af439350 5 filestore(/var/lib/ceph/osd/ceph-6) _journaled_ahead 0x2fe64a80 seq 5427453 osr(1.c 0x94bb200) 0x2a27200 2016-04-30 09:24:41.328809 af439350 5 filestore(/var/lib/ceph/osd/ceph-6) queue_op 0x2fe64a80 seq 5427453 osr(1.c 0x94bb200) 1084 bytes (queue has 50 ops and 62290 bytes) 2016-04-30 09:24:41.328828 af439350 10 filestore(/var/lib/ceph/osd/ceph-6) queueing ondisk 0x2e600b40 2016-04-30 09:24:44.703785 975b9350 20 osd.6 349418 kicking pg 1.32 2016-04-30 09:24:44.703880 975b9350 30 osd.6 pg_epoch: 349418 pg[1.32( v 338815'7745 (20981'4727,338815'7745] local-les=349347 n=435 ec=17 les/c 349347/349347 349418/349418/349418) [] r=-1 lpr=349418 pi=349346-349417/1 crt=338815'7743 lcod 0'0 inactive NOTIFY] lock
_______________________________________________ ceph-users mailing list ceph-users@xxxxxxxxxxxxxx http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
