3 Dec
2019
3 Dec
'19
7:36 a.m.
Hi all,
I am backporting the async recovery feature to Hammer :( --- this is
a sad story, but we can't upgrade to Luminous or other new version in
our product envs.
the teuthology tests catch an osd crash error after backport
https://github.com/ceph/ceph/pull/19811
But I have reproduced it with master branch code, the detail are
described as below:
code version: master branch with latest commit
656c8e8049c2c1acd363143c842c2edf1fe09b64
config of vstart:
[client.vstart.sh]
num mon = 1
num osd = 5
num mds = 0
num mgr = 1
num rgw = 0
config of osd/mon/mgr:
[osd]
osd_async_recovery_min_cost = 0 # only add this one, others are
default with vstart
vstart command:
MON=1 OSD=5 MDS=0 MGR=1 RGW=0 ../src/vstart.sh --debug --new -X
--localhost --bluestore --without-dashboard
pool info:
pool 1 'rbd' replicated size 3 min_size 1 crush_rule 0 object_hash
rjenkins pg_num 256 pgp_num 256 autoscale_mode off last_change 31
flags hashpspool,selfmanaged_snaps stripe_width 0 application rbd
osd log:
2019-12-02T09:32:28.779+0000 7f8ff8c82700 5 osd.2 pg_epoch: 783
pg[1.c2( v 657'1488 (0'0,657'1488] local-lis/les=0/0 n=13 ec=25/25
lis/c=0/449 les/c/f=0/450/0 sis=783) [2,1,0] r=0 lpr=783
pi=[449,783)/1 crt=657'1488 mlcod 0'0 unknown mbc={}] enter
Started/Primary
2019-12-02T09:32:28.779+0000 7f8ff8c82700 5 osd.2 pg_epoch: 783
pg[1.c2( v 657'1488 (0'0,657'1488] local-lis/les=0/0 n=13 ec=25/25
lis/c=0/449 les/c/f=0/450/0 sis=783) [2,1,0] r=0 lpr=783
pi=[449,783)/1 crt=657'1488 mlcod 0'0 creating mbc={}] enter
Started/Primary/Peering ### pg state is creating
2019-12-02T09:32:28.779+0000 7f8ff8c82700 5 osd.2 pg_epoch: 783
pg[1.c2( v 657'1488 (0'0,657'1488] local-lis/les=0/0 n=13 ec=25/25
lis/c=0/449 les/c/f=0/450/0 sis=783) [2,1,0] r=0 lpr=783
pi=[449,783)/1 crt=657'1488 mlcod 0'0 creating+peering mbc={}] enter
Started/Primary/Peering/GetInfo ### pg state is
creating+peering
Reproduce steps:
1. create a pool, wait for active+clean
2. writes to rbd image with fio or other tool during steps below
3. ceph osd reweight 2 0.1
4. wait several minutes, make sure pg are moved to other osd(grep
"on_removal" osd.2.log)
5. ceph osd reweight 2 1
6. wait several minutes, make sure pg are moved back to original
osd.2(grep "_make_pg" osd.2.log)
7. find a up_primary pg(such as 1.c2 in my log) on osd.2 which was
moved out/back during steps 3~6, and it should enter in async
recovering after step 6
8. wait for pg becomes active+clean, then you can find it had become
to creating+peering state.
the root reason may be:
1. after step 6, osd.0 will be async recovery target in pg 1.c2, and
pg will be created after reweight to 1
2. after pg->init the local_les=0/history.les=450
2019-12-02T09:21:47.991+0000 7f8ff8c82700 10 osd.2 543 _make_pg 1.c2
2019-12-02T09:21:47.991+0000 7f8ff8c82700 10 osd.2 pg_epoch: 543
pg[1.c2( DNE empty local-lis/les=0/0 n=0 ec=0/0 lis/c=0/0
les/c/f=0/0/0 sis=0) [] r=-1 lpr=0 crt=0'0 unknown mbc={}] init role 0
up [2,1,0] acting [2,1,0] history ec=25/25 lis/c=449/449
les/c/f=450/450/0 sis=543 pruub=14.367934206s past_intervals
([449,542] all_participants=0,1,3 intervals=([449,542] acting 0,1,3))
2019-12-02T09:21:47.991+0000 7f8ff8c82700 20 osd.2 pg_epoch: 543
pg[1.c2( empty local-lis/les=0/0 n=0 ec=25/25 lis/c=449/449
les/c/f=450/450/0 sis=543 pruub=14.367934206s) [2,1,0] r=0 lpr=0
pi=[449,543)/1 crt=0'0 mlcod 0'0 unknown mbc={}] on_new_interval
2019-12-02T09:21:48.063+0000 7f8ff8c82700 20 osd.2 pg_epoch: 543
pg[1.c2( empty local-lis/les=0/0 n=0 ec=25/25 lis/c=449/449
les/c/f=450/450/0 sis=543) [2,1,0] r=0 lpr=543 pi=[449,543)/1 crt=0'0
mlcod 0'0 peering mbc={}] choose_async_recovery_replicated result
want=[0,1] async_recovery=2
2019-12-02T09:21:48.983+0000 7f8ff8c82700 20 osd.2 pg_epoch: 544
pg[1.c2( empty local-lis/les=0/0 n=0 ec=25/25 lis/c=449/449
les/c/f=450/450/0 sis=543) [2,1,0] r=0 lpr=544 pi=[449,543)/1 crt=0'0
mlcod 0'0 unknown mbc={}] new interval newup [2,1,0] newacting [0,1]
## osd.2 is async recovery target in pg 1.c2
acting_primary osd.0 log:
2019-12-02T09:21:49.195+0000 7f2f01060700 20 osd.0 pg_epoch: 544
pg[1.c2( v 542'940 (0'0,542'940] local-lis/les=449/450 n=13 ec=25/25
lis/c=449/449 les/c/f=450/450/0 sis=544) [2,1,0]/[0,1] r=0 lpr=544
pi=[449,544)/1 crt=542'940 lcod 542'939 mlcod 0'0 remapped+peering
mbc={}] choose_async_recovery_replicated result want=[0,1]
async_recovery=2
3. when repop is coming to osd.2 of pg 1.c2, the append_log func will
find local_les(=0) != history.les(=450), and it will use local_les as
new history.les, then history.les become 0
void PeeringState::append_log(
const vector<pg_log_entry_t>& logv,
eversion_t trim_to,
eversion_t roll_forward_to,
ObjectStore::Transaction &t,
bool transaction_applied,
bool async)
{
/* The primary has sent an info updating the history, but it may not
* have arrived yet. We want to make sure that we cannot remember this
* write without remembering that it happened in an interval which went
* active in epoch history.last_epoch_started.
*/
if (info.last_epoch_started != info.history.last_epoch_started) {
info.history.last_epoch_started = info.last_epoch_started;
}
...
}
4. when the async recovery of osd.2 in pg 1.c2 is over, it will change
to acting_primary, pg state will be set to PG_STATE_CREATING
PeeringState::Primary::Primary(my_context ctx)
: my_base(ctx),
NamedState(context< PeeringMachine >().state_history,
"Started/Primary")
{
context< PeeringMachine >().log_enter(state_name);
DECLARE_LOCALS;
ceph_assert(ps->want_acting.empty());
// set CREATING bit until we have peered for the first time.
if (ps->info.history.last_epoch_started == 0) {
ps->state_set(PG_STATE_CREATING);
...
}
So my question is that, this PG_STATE_CREATING state after async
recovery is expected or not?
if it is, I guess this creating state may result in osd crash, if
acting_primary is changed during creating+peering state, the process
may be:
1. osd.2 report pg stats to mon
2. mon will add this pg to creating_pgs/creating_pgs_by_osd_epoch
void PGMap::stat_pg_add(const pg_t &pgid, const pg_stat_t &s,
bool sameosds)
{
auto pool = pgid.pool();
pg_sum.add(s);
num_pg++;
num_pg_by_state[s.state]++;
num_pg_by_pool_state[pgid.pool()][s.state]++;
num_pg_by_pool[pool]++;
if ((s.state & PG_STATE_CREATING) &&
s.parent_split_bits == 0) {
creating_pgs.insert(pgid);
if (s.acting_primary >= 0) {
creating_pgs_by_osd_epoch[s.acting_primary][s.mapping_epoch].insert(pgid);
}
}
...
}
3. when the acting_primary change to a new one, the new acting_primary
will receive a MOSDPGCreate/MOSDPGCreate2 msg with a very old pg
created epoch(the real created epoch is 5)
4. the new acting_primary will get_osdmap by pg created epoch, this
map is trimmed long time ago, then osd will crash at:
void OSD::build_initial_pg_history(
spg_t pgid,
epoch_t created,
utime_t created_stamp,
pg_history_t *h,
PastIntervals *pi)
{
dout(10) << __func__ << " " << pgid << " created
" << created << dendl;
*h = pg_history_t(created, created_stamp);
OSDMapRef lastmap = service.get_map(created);
...
}
OSDMapRef get_map(epoch_t e) {
OSDMapRef ret(try_get_map(e));
ceph_assert(ret); // crash here because map is trimmed
return ret;
}
I got a related issue here: https://tracker.ceph.com/issues/14592 osd
crashes when handling a stale pg-create message (hammer) ,
but I'm not sure they are same reason or not.
Thanks for your attention, welcome to ask me for more detail.