Dear devs,
First of all I would like to bow my head at your great effort! Even if
ceph did not reach prime time status yet it is already extremely
powerful and fairly stable to the point we have deployed it in live
environment (still backing up of course).
I have played with ceph extensively to put it different failed modes and
it recovers in most cases without major issues. However when I was
adding up OSDs I have got 2 PGs stuck in creating mode and does not
matter what I have done (changing CRUSH, restarting OSDs in order to get
ceph to move data around) they still there. So instead of using
scientific blindfold method I decided to dig deeper. So here we go
(please disregard stuck active+remapped as it is part of another problem):
[root@gamma tmp]# ceph -s
2012-04-20 12:40:45.294969 pg v625626: 600 pgs: 2 creating, 586
active+clean, 12 active+remapped; 253 GB data, 767 GB used, 1292 GB /
2145 GB avail
2012-04-20 12:40:45.299426 mds e457: 1/1/1 up {0=2=up:active}, 2
up:standby
2012-04-20 12:40:45.299549 osd e6022: 6 osds: 6 up, 6 in
2012-04-20 12:40:45.299856 log 2012-04-20 12:26:43.988716 mds.0
172.16.64.202:6802/21363 1 : [DBG] reconnect by client.13897
172.16.64.10:0/1319861516 after 0.101633
2012-04-20 12:40:45.300160 mon e1: 3 mons at
{0=172.16.64.200:6789/0,1=172.16.64.201:6789/0,2=172.16.64.202:6789/0}
[root@gamma tmp]# ceph pg dump | grep creating
2.1p3 0 0 0 0 0 0 0
creating 0.000000 0'0 0'0 [] [] 0'0
0.000000
1.1p3 0 0 0 0 0 0 0
creating 0.000000 0'0 0'0 [] [] 0'0
0.000000
My understanding is that p3 means that PG creating on osd.3 . I've tried
to stop and restart osd.3 - no banana. So I went to more dramatic
option: lose osd.3 . Completely destroyed osd.3 and rebuilt it from
scratch. osd.3 came back again with exactly the same PGs in creating
mode - makes me think that that osd.3 is not responsible for this.
[root@gamma tmp]# ceph osd dump
dumped osdmap epoch 6022
epoch 6022
fsid 7719f573-4c48-4852-a27f-51c7a3fe1c1e
created 2012-03-31 04:47:12.130128
modifed 2012-04-20 12:26:56.406193
flags
pool 0 'data' rep size 3 crush_ruleset 0 object_hash rjenkins pg_num 192
pgp_num 192 lpg_num 2 lpgp_num 2 last_change 1137 owner 0
crash_replay_interval 45
pool 1 'metadata' rep size 3 crush_ruleset 1 object_hash rjenkins pg_num
192 pgp_num 192 lpg_num 2 lpgp_num 2 last_change 1160 owner 0
pool 2 'rbd' rep size 3 crush_ruleset 2 object_hash rjenkins pg_num 192
pgp_num 192 lpg_num 2 lpgp_num 2 last_change 1141 owner 0
max_osd 6
osd.0 up in weight 1 up_from 6001 up_thru 6018 down_at 6000
last_clean_interval [5980,5996) 172.16.64.200:6804/23046
172.16.64.200:6805/23046 172.16.64.200:6806/23046 exists,up
osd.1 up in weight 1 up_from 5998 up_thru 6017 down_at 5997
last_clean_interval [5992,5996) 172.16.64.201:6804/27598
172.16.64.201:6805/27598 172.16.64.201:6806/27598 exists,up
osd.2 up in weight 1 up_from 5998 up_thru 6019 down_at 5997
last_clean_interval [5978,5996) 172.16.64.202:6804/21457
172.16.64.202:6805/21457 172.16.64.202:6806/21457 exists,up
osd.3 up in weight 1 up_from 5972 up_thru 6017 down_at 5970
last_clean_interval [5884,5969) lost_at 1163 172.16.64.203:6800/10614
172.16.64.203:6801/10614 172.16.64.203:6802/10614 exists,up
osd.4 up in weight 1 up_from 5995 up_thru 6017 down_at 5988
last_clean_interval [5898,5987) 172.16.64.204:6800/16357
172.16.64.204:6801/16357 172.16.64.204:6802/16357 exists,up
osd.5 up in weight 1 up_from 5984 up_thru 6021 down_at 5982
last_clean_interval [5921,5981) 172.16.64.205:6800/11346
172.16.64.205:6801/11346 172.16.64.205:6803/11346 exists,up
pg_temp 0.25 [0,1,4]
pg_temp 0.33 [0,1,5]
pg_temp 0.3e [1,0,4]
pg_temp 0.48 [1,0,4]
pg_temp 1.24 [0,1,4]
pg_temp 1.32 [0,1,5]
pg_temp 1.3d [1,0,4]
pg_temp 1.47 [1,0,2]
pg_temp 2.23 [0,1,4]
pg_temp 2.31 [0,1,5]
pg_temp 2.3c [1,0,4]
pg_temp 2.46 [1,0,4]
blacklist 172.16.64.202:6800/19544 expires 2012-04-20 12:45:43.842394
blacklist 172.16.64.200:6800/22946 expires 2012-04-20 12:50:17.341910
blacklist 172.16.64.201:6803/27504 expires 2012-04-20 12:50:20.102205
Then I have attempted to find out what's going on with 2.1p3:
[root@delta ceph]# ceph pg 2.1p3 query
at this point nothing did happen - it just sits there. At least it seems
so but in reality:
[root@delta ceph]# ceph -s
2012-04-20 12:49:50.322103 pg v625936: 600 pgs: 2 creating, 4 stale,
400 active+degraded, 3 stale+peering, 174 stale+active+degraded, 1
down+remapped+peering, 4 active+degraded+remapped, 1
stale+remapped+peering, 3 stale+active+replay+degraded, 8
stale+active+degraded+remapped; 253 GB data, 768 GB used, 1292 GB / 2145
GB avail; 138289/230205 degraded (60.072%)
2012-04-20 12:49:50.326769 mds e457: 1/1/1 up {0=2=up:active}, 2
up:standby
2012-04-20 12:49:50.326886 osd e6042: 6 osds: 1 up, 6 in
2012-04-20 12:49:50.327226 log 2012-04-20 12:49:16.732954 mon.0
172.16.64.200:6789/0 35 : [INF] osd.4 172.16.64.204:6800/16357 failed
(by osd.5 172.16.64.205:6800/11346)
2012-04-20 12:49:50.327497 mon e1: 3 mons at
{0=172.16.64.200:6789/0,1=172.16.64.201:6789/0,2=172.16.64.202:6789/0}
So as you can see 5 out of 6 OSDs crashed. Restarting all crashed OSDs
manually gets ceph back on the feet without any damage - minute later
everything runs as nothing happened and it is good time to see the logs.
In particular osd.3 log:
2012-04-20 12:47:38.944653 aadd6b40 --OSD::tracker-- seq: 56, time:
2012-04-20 12:47:38.944641, event: started pg_info(1 pgs e6026) v1
2012-04-20 12:47:38.965044 aadd6b40 --OSD::tracker-- seq: 57, time:
2012-04-20 12:47:38.965017, event: waiting_for_osdmap pg_info(1 pgs
e6025) v1
2012-04-20 12:47:38.965098 aadd6b40 --OSD::tracker-- seq: 57, time:
2012-04-20 12:47:38.965086, event: started pg_info(1 pgs e6025) v1
2012-04-20 12:47:38.965179 aadd6b40 --OSD::tracker-- seq: 58, time:
2012-04-20 12:47:38.965165, event: waiting_for_osdmap pg_log(1.8 epoch
6026 query_epoch 6026) v2
2012-04-20 12:47:38.965215 aadd6b40 --OSD::tracker-- seq: 58, time:
2012-04-20 12:47:38.965202, event: started pg_log(1.8 epoch 6026
query_epoch 6026) v2
2012-04-20 12:47:38.965421 aadd6b40 --OSD::tracker-- seq: 59, time:
2012-04-20 12:47:38.965408, event: waiting_for_osdmap pg_info(1 pgs
e6026) v1
2012-04-20 12:47:38.965461 aadd6b40 --OSD::tracker-- seq: 59, time:
2012-04-20 12:47:38.965449, event: started pg_info(1 pgs e6026) v1
2012-04-20 12:47:38.990427 ab5d7b40 --OSD::tracker-- seq: 60, time:
2012-04-20 12:47:38.990388, event: waiting_for_osdmap
osd_pg_create(pg1.1p3,619; pg2.1p3,1141; ) v2
2012-04-20 12:47:38.990592 aadd6b40 --OSD::tracker-- seq: 61, time:
2012-04-20 12:47:38.990579, event: waiting_for_osdmap pg_info(1 pgs
e6026) v1
2012-04-20 12:47:38.994296 aadd6b40 --OSD::tracker-- seq: 61, time:
2012-04-20 12:47:38.993072, event: started pg_info(1 pgs e6026) v1
2012-04-20 12:47:39.077303 ab5d7b40 --OSD::tracker-- seq: 60, time:
2012-04-20 12:47:39.077276, event: started osd_pg_create(pg1.1p3,619;
pg2.1p3,1141; ) v2
2012-04-20 12:47:54.546810 ab5d7b40 --OSD::tracker-- seq: 62, time:
2012-04-20 12:47:54.546770, event: waiting_for_osdmap
osd_op(client.13891.0:90331 rb.0.1.000000000b40 [write 3661824~4096]
2.1f179073) v4
osd/OSD.cc: In function 'PG* OSD::_lookup_lock_pg(pg_t)' thread a65cdb40
time 2012-04-20 12:47:54.562370
osd/OSD.cc: 1162: FAILED assert(pg_map.count(pgid))
ceph version 0.45 (commit:0aea1cb1df5c3e5ab783ca6f2ed7649823b613c5)
1: /usr/bin/ceph-osd() [0x81f3b04]
2: (OSD::do_command(Connection*, unsigned long long,
std::vector<std::string, std::allocator<std::string> >&,
ceph::buffer::list&)+0x1381) [0x8202b21]
3: (OSD::CommandWQ::_process(OSD::Command*)+0x51) [0x823ac71]
4: (ThreadPool::WorkQueue<OSD::Command>::_void_process(void*)+0x18)
[0x8224758]
5: (ThreadPool::worker()+0x42d) [0x82f8ddd]
6: (ThreadPool::WorkThread::entry()+0x1f) [0x822559f]
7: (Thread::_entry_func(void*)+0x10) [0x82f3140]
8: (()+0x6cd3) [0x6e0cd3]
9: (clone()+0x5e) [0xa3ca2e]
ceph version 0.45 (commit:0aea1cb1df5c3e5ab783ca6f2ed7649823b613c5)
1: /usr/bin/ceph-osd() [0x81f3b04]
2: (OSD::do_command(Connection*, unsigned long long,
std::vector<std::string, std::allocator<std::string> >&,
ceph::buffer::list&)+0x1381) [0x8202b21]
3: (OSD::CommandWQ::_process(OSD::Command*)+0x51) [0x823ac71]
4: (ThreadPool::WorkQueue<OSD::Command>::_void_process(void*)+0x18)
[0x8224758]
5: (ThreadPool::worker()+0x42d) [0x82f8ddd]
6: (ThreadPool::WorkThread::entry()+0x1f) [0x822559f]
7: (Thread::_entry_func(void*)+0x10) [0x82f3140]
8: (()+0x6cd3) [0x6e0cd3]
9: (clone()+0x5e) [0xa3ca2e]
*** Caught signal (Aborted) **
in thread a65cdb40
ceph version 0.45 (commit:0aea1cb1df5c3e5ab783ca6f2ed7649823b613c5)
1: /usr/bin/ceph-osd() [0x83754db]
2: [0x8c0400]
3: [0x8c0416]
4: (gsignal()+0x4f) [0x97898f]
5: (abort()+0x175) [0x97a2d5]
6: (__gnu_cxx::__verbose_terminate_handler()+0x14d) [0x7a754d]
7: (()+0xb02c4) [0x7a52c4]
8: (()+0xb0300) [0x7a5300]
9: (()+0xb044f) [0x7a544f]
10: (ceph::__ceph_assert_fail(char const*, char const*, int, char
const*)+0x255) [0x8300715]
11: /usr/bin/ceph-osd() [0x81f3b04]
12: (OSD::do_command(Connection*, unsigned long long,
std::vector<std::string, std::allocator<std::string> >&,
ceph::buffer::list&)+0x1381) [0x8202b21]
13: (OSD::CommandWQ::_process(OSD::Command*)+0x51) [0x823ac71]
14: (ThreadPool::WorkQueue<OSD::Command>::_void_process(void*)+0x18)
[0x8224758]
15: (ThreadPool::worker()+0x42d) [0x82f8ddd]
16: (ThreadPool::WorkThread::entry()+0x1f) [0x822559f]
17: (Thread::_entry_func(void*)+0x10) [0x82f3140]
18: (()+0x6cd3) [0x6e0cd3]
19: (clone()+0x5e) [0xa3ca2e]
So there's couple of things to note:
1. At 2012-04-20 12:47:39.077303 osd started creating PGs in question
2. At 2012-04-20 12:47:54.546810 we got FAILED assert(pg_map.count(pgid))
And at this point I guess it is over to you guys as I do not have any
idea why this assert fails. If you point me in right direction I would
be eternally grateful! :)
Regards,
Vladimir
--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
