Re: PGs stuck in creating state

[Vladimir Bashkirtsev <vladimir@bashkirtsev.com>]

On 08/05/12 01:26, Sage Weil wrote:
> On Mon, 7 May 2012, Vladimir Bashkirtsev wrote:
>> On 20/04/12 14:41, Sage Weil wrote:
>>> On Fri, 20 Apr 2012, Vladimir Bashkirtsev wrote:
>>>> 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
>>> Sigh.. this is exactly the problem I noticed last week that prompted the
>>> 'localized pgs' email.  I'm working on patches to remove this
>>> functionality entirely as we speak, since it's a broken design in several
>>> ways.
>>>
>>> Once you restart your osds (be sure to control-c that 'ceph' command
>>> first), you should be able to wipe out those bad pgs with
>>>
>>> 	ceph osd pool disable_lpgs<poolname>   --yes-i-really-mean-it
>>>
>>> This is in current master, and will be included in 0.46.
>> Have upgraded to 0.46, done disable_lpgs on all pools - still no banana. Other
>> ideas?
> The stray pg entries will get zapped by v0.47.  The 'disable_lpgs' will
> only prevent new ones from getting created<0.47.
>
> sage
0.47 on board and problem has gone!
>
>
>>> Alternatively, you can just ignore those pgs for the time being.  They
>>> are completely harmless as long as you can tolerate the ceph -s/ceph
>>> health noise.  v0.47 should silently zap them all on upgrade.
>>>
>>> sage
>>>
>>>> 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@vger.kernel.org
>>>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>>>
>>>>
>> --
>> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
>> the body of a message to majordomo@vger.kernel.org
>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>
>>