Fwd: 70+ OSD are DOWN and not coming up

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Hi

This problem occurred somewhere between 16 - 18th May .  Before this cluster was healthy.

# As far as i remember correctly last thing i performed was cluster up gradation to 0.80-rc-1 and creating several cinder volumes after a day.

# The cluster is not too big , consists of 165 OSD , total capacity 450 TB , used capacity is very low.

# I tried osd map cache size = 75000 for a single osd (osd.58) .

Memory utilisation on this node spiked UP.
After monitoring for couple of hours , i found osd loading and decoding operation is not able to go beyond map epoch 289XXX  while the latest osd map epoch is 350946. OSD.58 is continuously trying but not able to cross epoch 289XXX.
This is the same problem with rest 32 OSDs , they are not able to cross the epoch number and repeating in the same loop.


Here are some output from osd.58 , for a specific epoch number where its getting stuccoed. 

[root at storage0106-ib ceph]# grep 289568 ceph-osd.58.log > /tmp/osd.58

[root at storage0106-ib tmp]# tail -100 osd.58
2014-05-25 15:10:41.222579 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[2.38c( empty local-les=289504 n=0 ec=1 les/c 289504/289504 289567/289567/289473) [72,2] r=-1 lpr=289568 pi=289471-289566/4 crt=0'0 inactive NOTIFY] handle_activate_map
2014-05-25 15:10:41.222628 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[2.38c( empty local-les=289504 n=0 ec=1 les/c 289504/289504 289567/289567/289473) [72,2] r=-1 lpr=289568 pi=289471-289566/4 crt=0'0 inactive NOTIFY] take_waiters
2014-05-25 15:10:41.222650 7fbc0b54c700 20 osd.58 pg_epoch: 289568 pg[2.38c( empty local-les=289504 n=0 ec=1 les/c 289504/289504 289567/289567/289473) [72,2] r=-1 lpr=289568 pi=289471-289566/4 crt=0'0 inactive NOTIFY] handle_activate_map: Not dirtying info: last_persisted is 289568 while current is 289568
2014-05-25 15:10:41.222665 7fbc0b54c700 10 osd.58 350946 advance_pg advanced by max 200 past min epoch 289568 ... will requeue pg[2.38c( empty local-les=289504 n=0 ec=1 les/c 289504/289504 289567/289567/289473) [72,2] r=-1 lpr=289568 pi=289471-289566/4 crt=0'0 inactive NOTIFY]
2014-05-25 15:10:41.222676 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[2.38c( empty local-les=289504 n=0 ec=1 les/c 289504/289504 289567/289567/289473) [72,2] r=-1 lpr=289568 pi=289471-289566/4 crt=0'0 inactive NOTIFY] null
2014-05-25 15:10:41.243297 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[0.1f4( empty local-les=289536 n=0 ec=1 les/c 289536/289536 289567/289567/289501) [37,110] r=-1 lpr=289568 pi=571-289566/9373 crt=0'0 inactive NOTIFY] handle_activate_map
2014-05-25 15:10:41.255742 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[0.1f4( empty local-les=289536 n=0 ec=1 les/c 289536/289536 289567/289567/289501) [37,110] r=-1 lpr=289568 pi=571-289566/9373 crt=0'0 inactive NOTIFY] take_waiters
2014-05-25 15:10:41.255773 7fbc0b54c700 20 osd.58 pg_epoch: 289568 pg[0.1f4( empty local-les=289536 n=0 ec=1 les/c 289536/289536 289567/289567/289501) [37,110] r=-1 lpr=289568 pi=571-289566/9373 crt=0'0 inactive NOTIFY] handle_activate_map: Not dirtying info: last_persisted is 289568 while current is 289568
2014-05-25 15:10:41.255788 7fbc0b54c700 10 osd.58 350946 advance_pg advanced by max 200 past min epoch 289568 ... will requeue pg[0.1f4( empty local-les=289536 n=0 ec=1 les/c 289536/289536 289567/289567/289501) [37,110] r=-1 lpr=289568 pi=571-289566/9373 crt=0'0 inactive NOTIFY]
2014-05-25 15:10:41.255799 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[0.1f4( empty local-les=289536 n=0 ec=1 les/c 289536/289536 289567/289567/289501) [37,110] r=-1 lpr=289568 pi=571-289566/9373 crt=0'0 inactive NOTIFY] null
2014-05-25 15:10:41.263083 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[2.71e( empty local-les=289536 n=0 ec=1 les/c 289536/289536 289567/289567/289535) [78,124] r=-1 lpr=289568 pi=625-289566/11022 crt=0'0 inactive NOTIFY] handle_activate_map
2014-05-25 15:10:41.277054 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[2.71e( empty local-les=289536 n=0 ec=1 les/c 289536/289536 289567/289567/289535) [78,124] r=-1 lpr=289568 pi=625-289566/11022 crt=0'0 inactive NOTIFY] take_waiters
2014-05-25 15:10:41.277094 7fbc0ab4b700 20 osd.58 pg_epoch: 289568 pg[2.71e( empty local-les=289536 n=0 ec=1 les/c 289536/289536 289567/289567/289535) [78,124] r=-1 lpr=289568 pi=625-289566/11022 crt=0'0 inactive NOTIFY] handle_activate_map: Not dirtying info: last_persisted is 289568 while current is 289568
2014-05-25 15:10:41.277109 7fbc0ab4b700 10 osd.58 350946 advance_pg advanced by max 200 past min epoch 289568 ... will requeue pg[2.71e( empty local-les=289536 n=0 ec=1 les/c 289536/289536 289567/289567/289535) [78,124] r=-1 lpr=289568 pi=625-289566/11022 crt=0'0 inactive NOTIFY]
2014-05-25 15:10:41.277121 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[2.71e( empty local-les=289536 n=0 ec=1 les/c 289536/289536 289567/289567/289535) [78,124] r=-1 lpr=289568 pi=625-289566/11022 crt=0'0 inactive NOTIFY] null
2014-05-25 15:10:41.282697 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[2.71d( empty local-les=289504 n=0 ec=1 les/c 289504/289504 289567/289567/288958) [38,2] r=-1 lpr=289568 pi=288954-289566/17 crt=0'0 inactive NOTIFY] handle_activate_map
2014-05-25 15:10:41.282753 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[2.71d( empty local-les=289504 n=0 ec=1 les/c 289504/289504 289567/289567/288958) [38,2] r=-1 lpr=289568 pi=288954-289566/17 crt=0'0 inactive NOTIFY] take_waiters
2014-05-25 15:10:41.282774 7fbc0b54c700 20 osd.58 pg_epoch: 289568 pg[2.71d( empty local-les=289504 n=0 ec=1 les/c 289504/289504 289567/289567/288958) [38,2] r=-1 lpr=289568 pi=288954-289566/17 crt=0'0 inactive NOTIFY] handle_activate_map: Not dirtying info: last_persisted is 289568 while current is 289568
2014-05-25 15:10:41.282789 7fbc0b54c700 10 osd.58 350946 advance_pg advanced by max 200 past min epoch 289568 ... will requeue pg[2.71d( empty local-les=289504 n=0 ec=1 les/c 289504/289504 289567/289567/288958) [38,2] r=-1 lpr=289568 pi=288954-289566/17 crt=0'0 inactive NOTIFY]
2014-05-25 15:10:41.282800 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[2.71d( empty local-les=289504 n=0 ec=1 les/c 289504/289504 289567/289567/288958) [38,2] r=-1 lpr=289568 pi=288954-289566/17 crt=0'0 inactive NOTIFY] null
2014-05-25 15:10:41.302274 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[2.f9( empty local-les=289561 n=0 ec=1 les/c 289561/289561 289567/289567/289567) [79,21] r=-1 lpr=289568 pi=289560-289566/1 crt=0'0 inactive NOTIFY] handle_activate_map
2014-05-25 15:10:41.302328 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[2.f9( empty local-les=289561 n=0 ec=1 les/c 289561/289561 289567/289567/289567) [79,21] r=-1 lpr=289568 pi=289560-289566/1 crt=0'0 inactive NOTIFY] take_waiters
2014-05-25 15:10:41.302350 7fbc0ab4b700 20 osd.58 pg_epoch: 289568 pg[2.f9( empty local-les=289561 n=0 ec=1 les/c 289561/289561 289567/289567/289567) [79,21] r=-1 lpr=289568 pi=289560-289566/1 crt=0'0 inactive NOTIFY] handle_activate_map: Not dirtying info: last_persisted is 289568 while current is 289568
2014-05-25 15:10:41.302365 7fbc0ab4b700 10 osd.58 350946 advance_pg advanced by max 200 past min epoch 289568 ... will requeue pg[2.f9( empty local-les=289561 n=0 ec=1 les/c 289561/289561 289567/289567/289567) [79,21] r=-1 lpr=289568 pi=289560-289566/1 crt=0'0 inactive NOTIFY]
2014-05-25 15:10:41.302376 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[2.f9( empty local-les=289561 n=0 ec=1 les/c 289561/289561 289567/289567/289567) [79,21] r=-1 lpr=289568 pi=289560-289566/1 crt=0'0 inactive NOTIFY] null
2014-05-25 15:10:41.340166 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[2.626( empty local-les=289415 n=0 ec=1 les/c 289415/289415 289567/289567/289414) [66,41] r=-1 lpr=289568 pi=124449-289566/5588 crt=0'0 inactive NOTIFY] handle_activate_map
2014-05-25 15:10:41.343261 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[0.6c( empty local-les=289454 n=0 ec=1 les/c 289454/289454 289567/289567/289567) [38,55] r=-1 lpr=289568 pi=289453-289566/1 crt=0'0 inactive NOTIFY] handle_activate_map
2014-05-25 15:10:41.343304 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[0.6c( empty local-les=289454 n=0 ec=1 les/c 289454/289454 289567/289567/289567) [38,55] r=-1 lpr=289568 pi=289453-289566/1 crt=0'0 inactive NOTIFY] take_waiters
2014-05-25 15:10:41.343325 7fbc0ab4b700 20 osd.58 pg_epoch: 289568 pg[0.6c( empty local-les=289454 n=0 ec=1 les/c 289454/289454 289567/289567/289567) [38,55] r=-1 lpr=289568 pi=289453-289566/1 crt=0'0 inactive NOTIFY] handle_activate_map: Not dirtying info: last_persisted is 289568 while current is 289568
2014-05-25 15:10:41.343339 7fbc0ab4b700 10 osd.58 350946 advance_pg advanced by max 200 past min epoch 289568 ... will requeue pg[0.6c( empty local-les=289454 n=0 ec=1 les/c 289454/289454 289567/289567/289567) [38,55] r=-1 lpr=289568 pi=289453-289566/1 crt=0'0 inactive NOTIFY]
2014-05-25 15:10:41.343351 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[0.6c( empty local-les=289454 n=0 ec=1 les/c 289454/289454 289567/289567/289567) [38,55] r=-1 lpr=289568 pi=289453-289566/1 crt=0'0 inactive NOTIFY] null
2014-05-25 15:10:41.347767 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[2.626( empty local-les=289415 n=0 ec=1 les/c 289415/289415 289567/289567/289414) [66,41] r=-1 lpr=289568 pi=124449-289566/5588 crt=0'0 inactive NOTIFY] take_waiters
2014-05-25 15:10:41.347800 7fbc0b54c700 20 osd.58 pg_epoch: 289568 pg[2.626( empty local-les=289415 n=0 ec=1 les/c 289415/289415 289567/289567/289414) [66,41] r=-1 lpr=289568 pi=124449-289566/5588 crt=0'0 inactive NOTIFY] handle_activate_map: Not dirtying info: last_persisted is 289568 while current is 289568
2014-05-25 15:10:41.347815 7fbc0b54c700 10 osd.58 350946 advance_pg advanced by max 200 past min epoch 289568 ... will requeue pg[2.626( empty local-les=289415 n=0 ec=1 les/c 289415/289415 289567/289567/289414) [66,41] r=-1 lpr=289568 pi=124449-289566/5588 crt=0'0 inactive NOTIFY]
2014-05-25 15:10:41.347828 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[2.626( empty local-les=289415 n=0 ec=1 les/c 289415/289415 289567/289567/289414) [66,41] r=-1 lpr=289568 pi=124449-289566/5588 crt=0'0 inactive NOTIFY] null
2014-05-25 15:10:41.363524 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[0.3b5( empty local-les=289538 n=0 ec=1 les/c 289538/289541 289567/289567/289567) [89,129] r=-1 lpr=289568 pi=289535-289566/1 crt=0'0 inactive NOTIFY] handle_activate_map
2014-05-25 15:10:41.363556 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[0.3b5( empty local-les=289538 n=0 ec=1 les/c 289538/289541 289567/289567/289567) [89,129] r=-1 lpr=289568 pi=289535-289566/1 crt=0'0 inactive NOTIFY] take_waiters
2014-05-25 15:10:41.365664 7fbc0ab4b700 20 osd.58 pg_epoch: 289568 pg[0.3b5( empty local-les=289538 n=0 ec=1 les/c 289538/289541 289567/289567/289567) [89,129] r=-1 lpr=289568 pi=289535-289566/1 crt=0'0 inactive NOTIFY] handle_activate_map: Not dirtying info: last_persisted is 289568 while current is 289568
2014-05-25 15:10:41.365680 7fbc0ab4b700 10 osd.58 350946 advance_pg advanced by max 200 past min epoch 289568 ... will requeue pg[0.3b5( empty local-les=289538 n=0 ec=1 les/c 289538/289541 289567/289567/289567) [89,129] r=-1 lpr=289568 pi=289535-289566/1 crt=0'0 inactive NOTIFY]
2014-05-25 15:10:41.365691 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[0.3b5( empty local-les=289538 n=0 ec=1 les/c 289538/289541 289567/289567/289567) [89,129] r=-1 lpr=289568 pi=289535-289566/1 crt=0'0 inactive NOTIFY] null
2014-05-25 15:10:41.396342 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[2.604( empty local-les=289514 n=0 ec=1 les/c 289514/289514 289567/289567/289513) [3,109] r=-1 lpr=289568 pi=161020-289566/4775 crt=0'0 inactive NOTIFY] handle_activate_map
2014-05-25 15:10:41.402783 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[2.604( empty local-les=289514 n=0 ec=1 les/c 289514/289514 289567/289567/289513) [3,109] r=-1 lpr=289568 pi=161020-289566/4775 crt=0'0 inactive NOTIFY] take_waiters
2014-05-25 15:10:41.402816 7fbc0b54c700 20 osd.58 pg_epoch: 289568 pg[2.604( empty local-les=289514 n=0 ec=1 les/c 289514/289514 289567/289567/289513) [3,109] r=-1 lpr=289568 pi=161020-289566/4775 crt=0'0 inactive NOTIFY] handle_activate_map: Not dirtying info: last_persisted is 289568 while current is 289568
2014-05-25 15:10:41.402831 7fbc0b54c700 10 osd.58 350946 advance_pg advanced by max 200 past min epoch 289568 ... will requeue pg[2.604( empty local-les=289514 n=0 ec=1 les/c 289514/289514 289567/289567/289513) [3,109] r=-1 lpr=289568 pi=161020-289566/4775 crt=0'0 inactive NOTIFY]
2014-05-25 15:10:41.402842 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[2.604( empty local-les=289514 n=0 ec=1 les/c 289514/289514 289567/289567/289513) [3,109] r=-1 lpr=289568 pi=161020-289566/4775 crt=0'0 inactive NOTIFY] null
2014-05-25 15:10:41.405597 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[0.21d( empty local-les=289521 n=0 ec=1 les/c 289521/289521 289567/289567/286195) [77,137] r=-1 lpr=289568 pi=286192-289566/77 crt=0'0 inactive NOTIFY] handle_activate_map
2014-05-25 15:10:41.405733 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[0.21d( empty local-les=289521 n=0 ec=1 les/c 289521/289521 289567/289567/286195) [77,137] r=-1 lpr=289568 pi=286192-289566/77 crt=0'0 inactive NOTIFY] take_waiters
2014-05-25 15:10:41.405750 7fbc0ab4b700 20 osd.58 pg_epoch: 289568 pg[0.21d( empty local-les=289521 n=0 ec=1 les/c 289521/289521 289567/289567/286195) [77,137] r=-1 lpr=289568 pi=286192-289566/77 crt=0'0 inactive NOTIFY] handle_activate_map: Not dirtying info: last_persisted is 289568 while current is 289568
2014-05-25 15:10:41.405764 7fbc0ab4b700 10 osd.58 350946 advance_pg advanced by max 200 past min epoch 289568 ... will requeue pg[0.21d( empty local-les=289521 n=0 ec=1 les/c 289521/289521 289567/289567/286195) [77,137] r=-1 lpr=289568 pi=286192-289566/77 crt=0'0 inactive NOTIFY]
2014-05-25 15:10:41.405775 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[0.21d( empty local-les=289521 n=0 ec=1 les/c 289521/289521 289567/289567/286195) [77,137] r=-1 lpr=289568 pi=286192-289566/77 crt=0'0 inactive NOTIFY] null
2014-05-25 15:10:41.426717 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[2.782( empty local-les=289344 n=0 ec=1 les/c 289344/289344 289567/289567/289343) [97,38] r=-1 lpr=289568 pi=289340-289566/2 crt=0'0 inactive NOTIFY] handle_activate_map
2014-05-25 15:10:41.426757 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[2.782( empty local-les=289344 n=0 ec=1 les/c 289344/289344 289567/289567/289343) [97,38] r=-1 lpr=289568 pi=289340-289566/2 crt=0'0 inactive NOTIFY] take_waiters
2014-05-25 15:10:41.426772 7fbc0b54c700 20 osd.58 pg_epoch: 289568 pg[2.782( empty local-les=289344 n=0 ec=1 les/c 289344/289344 289567/289567/289343) [97,38] r=-1 lpr=289568 pi=289340-289566/2 crt=0'0 inactive NOTIFY] handle_activate_map: Not dirtying info: last_persisted is 289568 while current is 289568
2014-05-25 15:10:41.426786 7fbc0b54c700 10 osd.58 350946 advance_pg advanced by max 200 past min epoch 289568 ... will requeue pg[2.782( empty local-les=289344 n=0 ec=1 les/c 289344/289344 289567/289567/289343) [97,38] r=-1 lpr=289568 pi=289340-289566/2 crt=0'0 inactive NOTIFY]
2014-05-25 15:10:41.426797 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[2.782( empty local-les=289344 n=0 ec=1 les/c 289344/289344 289567/289567/289343) [97,38] r=-1 lpr=289568 pi=289340-289566/2 crt=0'0 inactive NOTIFY] null
2014-05-25 15:10:41.449454 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[2.7b2( empty local-les=289491 n=0 ec=1 les/c 289491/289491 289567/289567/289567) [32,60] r=-1 lpr=289568 pi=289490-289566/1 crt=0'0 inactive NOTIFY] handle_activate_map
2014-05-25 15:10:41.449509 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[2.7b2( empty local-les=289491 n=0 ec=1 les/c 289491/289491 289567/289567/289567) [32,60] r=-1 lpr=289568 pi=289490-289566/1 crt=0'0 inactive NOTIFY] take_waiters
2014-05-25 15:10:41.449526 7fbc0b54c700 20 osd.58 pg_epoch: 289568 pg[2.7b2( empty local-les=289491 n=0 ec=1 les/c 289491/289491 289567/289567/289567) [32,60] r=-1 lpr=289568 pi=289490-289566/1 crt=0'0 inactive NOTIFY] handle_activate_map: Not dirtying info: last_persisted is 289568 while current is 289568
2014-05-25 15:10:41.449547 7fbc0b54c700 10 osd.58 350946 advance_pg advanced by max 200 past min epoch 289568 ... will requeue pg[2.7b2( empty local-les=289491 n=0 ec=1 les/c 289491/289491 289567/289567/289567) [32,60] r=-1 lpr=289568 pi=289490-289566/1 crt=0'0 inactive NOTIFY]
2014-05-25 15:10:41.449559 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[2.7b2( empty local-les=289491 n=0 ec=1 les/c 289491/289491 289567/289567/289567) [32,60] r=-1 lpr=289568 pi=289490-289566/1 crt=0'0 inactive NOTIFY] null
2014-05-25 15:10:41.468461 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[0.1d0( empty local-les=289490 n=0 ec=1 les/c 289490/289490 289567/289567/289481) [107,101] r=-1 lpr=289568 pi=289479-289566/4 crt=0'0 inactive NOTIFY] handle_activate_map
2014-05-25 15:10:41.468511 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[0.1d0( empty local-les=289490 n=0 ec=1 les/c 289490/289490 289567/289567/289481) [107,101] r=-1 lpr=289568 pi=289479-289566/4 crt=0'0 inactive NOTIFY] take_waiters
2014-05-25 15:10:41.468533 7fbc0ab4b700 20 osd.58 pg_epoch: 289568 pg[0.1d0( empty local-les=289490 n=0 ec=1 les/c 289490/289490 289567/289567/289481) [107,101] r=-1 lpr=289568 pi=289479-289566/4 crt=0'0 inactive NOTIFY] handle_activate_map: Not dirtying info: last_persisted is 289568 while current is 289568
2014-05-25 15:10:41.468560 7fbc0ab4b700 10 osd.58 350946 advance_pg advanced by max 200 past min epoch 289568 ... will requeue pg[0.1d0( empty local-les=289490 n=0 ec=1 les/c 289490/289490 289567/289567/289481) [107,101] r=-1 lpr=289568 pi=289479-289566/4 crt=0'0 inactive NOTIFY]
2014-05-25 15:10:41.468573 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[0.1d0( empty local-les=289490 n=0 ec=1 les/c 289490/289490 289567/289567/289481) [107,101] r=-1 lpr=289568 pi=289479-289566/4 crt=0'0 inactive NOTIFY] null
2014-05-25 15:10:41.495508 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[2.71d( empty local-les=289504 n=0 ec=1 les/c 289504/289504 289567/289567/288958) [38,2] r=-1 lpr=289568 pi=288954-289566/17 crt=0'0 inactive NOTIFY] handle_activate_map
2014-05-25 15:10:41.495594 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[2.71d( empty local-les=289504 n=0 ec=1 les/c 289504/289504 289567/289567/288958) [38,2] r=-1 lpr=289568 pi=288954-289566/17 crt=0'0 inactive NOTIFY] take_waiters
2014-05-25 15:10:41.495618 7fbc0b54c700 20 osd.58 pg_epoch: 289568 pg[2.71d( empty local-les=289504 n=0 ec=1 les/c 289504/289504 289567/289567/288958) [38,2] r=-1 lpr=289568 pi=288954-289566/17 crt=0'0 inactive NOTIFY] handle_activate_map: Not dirtying info: last_persisted is 289568 while current is 289568
2014-05-25 15:10:41.495633 7fbc0b54c700 10 osd.58 350946 advance_pg advanced by max 200 past min epoch 289568 ... will requeue pg[2.71d( empty local-les=289504 n=0 ec=1 les/c 289504/289504 289567/289567/288958) [38,2] r=-1 lpr=289568 pi=288954-289566/17 crt=0'0 inactive NOTIFY]
2014-05-25 15:10:41.495645 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[2.71d( empty local-les=289504 n=0 ec=1 les/c 289504/289504 289567/289567/288958) [38,2] r=-1 lpr=289568 pi=288954-289566/17 crt=0'0 inactive NOTIFY] null
2014-05-25 15:10:41.508936 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[0.512( empty local-les=289554 n=0 ec=1 les/c 289554/289554 289567/289567/289567) [61,70] r=-1 lpr=289568 pi=289553-289566/1 crt=0'0 inactive NOTIFY] handle_activate_map
2014-05-25 15:10:41.508975 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[0.512( empty local-les=289554 n=0 ec=1 les/c 289554/289554 289567/289567/289567) [61,70] r=-1 lpr=289568 pi=289553-289566/1 crt=0'0 inactive NOTIFY] take_waiters
2014-05-25 15:10:41.508991 7fbc0ab4b700 20 osd.58 pg_epoch: 289568 pg[0.512( empty local-les=289554 n=0 ec=1 les/c 289554/289554 289567/289567/289567) [61,70] r=-1 lpr=289568 pi=289553-289566/1 crt=0'0 inactive NOTIFY] handle_activate_map: Not dirtying info: last_persisted is 289568 while current is 289568
2014-05-25 15:10:41.509005 7fbc0ab4b700 10 osd.58 350946 advance_pg advanced by max 200 past min epoch 289568 ... will requeue pg[0.512( empty local-les=289554 n=0 ec=1 les/c 289554/289554 289567/289567/289567) [61,70] r=-1 lpr=289568 pi=289553-289566/1 crt=0'0 inactive NOTIFY]
2014-05-25 15:10:41.509016 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[0.512( empty local-les=289554 n=0 ec=1 les/c 289554/289554 289567/289567/289567) [61,70] r=-1 lpr=289568 pi=289553-289566/1 crt=0'0 inactive NOTIFY] null
2014-05-25 15:10:41.541973 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[0.1ee( empty local-les=289331 n=0 ec=1 les/c 289331/289331 289567/289567/289567) [146,108] r=-1 lpr=289568 pi=289330-289566/1 crt=0'0 inactive NOTIFY] handle_activate_map
2014-05-25 15:10:41.542031 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[0.1ee( empty local-les=289331 n=0 ec=1 les/c 289331/289331 289567/289567/289567) [146,108] r=-1 lpr=289568 pi=289330-289566/1 crt=0'0 inactive NOTIFY] take_waiters
2014-05-25 15:10:41.542049 7fbc0ab4b700 20 osd.58 pg_epoch: 289568 pg[0.1ee( empty local-les=289331 n=0 ec=1 les/c 289331/289331 289567/289567/289567) [146,108] r=-1 lpr=289568 pi=289330-289566/1 crt=0'0 inactive NOTIFY] handle_activate_map: Not dirtying info: last_persisted is 289568 while current is 289568
2014-05-25 15:10:41.542064 7fbc0ab4b700 10 osd.58 350946 advance_pg advanced by max 200 past min epoch 289568 ... will requeue pg[0.1ee( empty local-les=289331 n=0 ec=1 les/c 289331/289331 289567/289567/289567) [146,108] r=-1 lpr=289568 pi=289330-289566/1 crt=0'0 inactive NOTIFY]
2014-05-25 15:10:41.542075 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[0.1ee( empty local-les=289331 n=0 ec=1 les/c 289331/289331 289567/289567/289567) [146,108] r=-1 lpr=289568 pi=289330-289566/1 crt=0'0 inactive NOTIFY] null
2014-05-25 15:10:41.553850 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[3.7( v 289523'6912 (193506'3911,289523'6912] local-les=289417 n=5 ec=71845 les/c 289417/289417 289567/289567/289567) [152,85] r=-1 lpr=289568 pi=289416-289566/1 crt=286267'6814 lcod 0'0 inactive NOTIFY] handle_activate_map
2014-05-25 15:10:41.553892 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[3.7( v 289523'6912 (193506'3911,289523'6912] local-les=289417 n=5 ec=71845 les/c 289417/289417 289567/289567/289567) [152,85] r=-1 lpr=289568 pi=289416-289566/1 crt=286267'6814 lcod 0'0 inactive NOTIFY] take_waiters
2014-05-25 15:10:41.553915 7fbc0b54c700 20 osd.58 pg_epoch: 289568 pg[3.7( v 289523'6912 (193506'3911,289523'6912] local-les=289417 n=5 ec=71845 les/c 289417/289417 289567/289567/289567) [152,85] r=-1 lpr=289568 pi=289416-289566/1 crt=286267'6814 lcod 0'0 inactive NOTIFY] handle_activate_map: Not dirtying info: last_persisted is 289568 while current is 289568
2014-05-25 15:10:41.553930 7fbc0b54c700 10 osd.58 350946 advance_pg advanced by max 200 past min epoch 289568 ... will requeue pg[3.7( v 289523'6912 (193506'3911,289523'6912] local-les=289417 n=5 ec=71845 les/c 289417/289417 289567/289567/289567) [152,85] r=-1 lpr=289568 pi=289416-289566/1 crt=286267'6814 lcod 0'0 inactive NOTIFY]
2014-05-25 15:10:41.553949 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[3.7( v 289523'6912 (193506'3911,289523'6912] local-les=289417 n=5 ec=71845 les/c 289417/289417 289567/289567/289567) [152,85] r=-1 lpr=289568 pi=289416-289566/1 crt=286267'6814 lcod 0'0 inactive NOTIFY] null
2014-05-25 15:10:41.578314 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[0.1d8( empty local-les=289535 n=0 ec=1 les/c 289535/289535 289567/289567/289534) [46,47] r=-1 lpr=289568 pi=629-289566/8210 crt=0'0 inactive NOTIFY] handle_activate_map
2014-05-25 15:10:41.589983 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[0.1d8( empty local-les=289535 n=0 ec=1 les/c 289535/289535 289567/289567/289534) [46,47] r=-1 lpr=289568 pi=629-289566/8210 crt=0'0 inactive NOTIFY] take_waiters
2014-05-25 15:10:41.590025 7fbc0ab4b700 20 osd.58 pg_epoch: 289568 pg[0.1d8( empty local-les=289535 n=0 ec=1 les/c 289535/289535 289567/289567/289534) [46,47] r=-1 lpr=289568 pi=629-289566/8210 crt=0'0 inactive NOTIFY] handle_activate_map: Not dirtying info: last_persisted is 289568 while current is 289568
2014-05-25 15:10:41.590042 7fbc0ab4b700 10 osd.58 350946 advance_pg advanced by max 200 past min epoch 289568 ... will requeue pg[0.1d8( empty local-les=289535 n=0 ec=1 les/c 289535/289535 289567/289567/289534) [46,47] r=-1 lpr=289568 pi=629-289566/8210 crt=0'0 inactive NOTIFY]
2014-05-25 15:10:41.590055 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[0.1d8( empty local-les=289535 n=0 ec=1 les/c 289535/289535 289567/289567/289534) [46,47] r=-1 lpr=289568 pi=629-289566/8210 crt=0'0 inactive NOTIFY] null
2014-05-25 15:10:41.594791 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[0.185( empty local-les=289526 n=0 ec=1 les/c 289526/289526 289567/289567/289502) [121,89] r=-1 lpr=289568 pi=492-289566/9900 crt=0'0 inactive NOTIFY] handle_activate_map
2014-05-25 15:10:41.607898 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[0.185( empty local-les=289526 n=0 ec=1 les/c 289526/289526 289567/289567/289502) [121,89] r=-1 lpr=289568 pi=492-289566/9900 crt=0'0 inactive NOTIFY] take_waiters
2014-05-25 15:10:41.607931 7fbc0b54c700 20 osd.58 pg_epoch: 289568 pg[0.185( empty local-les=289526 n=0 ec=1 les/c 289526/289526 289567/289567/289502) [121,89] r=-1 lpr=289568 pi=492-289566/9900 crt=0'0 inactive NOTIFY] handle_activate_map: Not dirtying info: last_persisted is 289568 while current is 289568
2014-05-25 15:10:41.607946 7fbc0b54c700 10 osd.58 350946 advance_pg advanced by max 200 past min epoch 289568 ... will requeue pg[0.185( empty local-les=289526 n=0 ec=1 les/c 289526/289526 289567/289567/289502) [121,89] r=-1 lpr=289568 pi=492-289566/9900 crt=0'0 inactive NOTIFY]
2014-05-25 15:10:41.607959 7fbc0b54c700 10 osd.58 pg_epoch: 289568 pg[0.185( empty local-les=289526 n=0 ec=1 les/c 289526/289526 289567/289567/289502) [121,89] r=-1 lpr=289568 pi=492-289566/9900 crt=0'0 inactive NOTIFY] null
2014-05-25 15:10:41.614492 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[2.35d( empty local-les=289560 n=0 ec=1 les/c 289560/289560 289567/289567/289559) [86,89] r=-1 lpr=289568 pi=289555-289566/2 crt=0'0 inactive NOTIFY] handle_activate_map
2014-05-25 15:10:41.614528 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[2.35d( empty local-les=289560 n=0 ec=1 les/c 289560/289560 289567/289567/289559) [86,89] r=-1 lpr=289568 pi=289555-289566/2 crt=0'0 inactive NOTIFY] take_waiters
2014-05-25 15:10:41.614548 7fbc0ab4b700 20 osd.58 pg_epoch: 289568 pg[2.35d( empty local-les=289560 n=0 ec=1 les/c 289560/289560 289567/289567/289559) [86,89] r=-1 lpr=289568 pi=289555-289566/2 crt=0'0 inactive NOTIFY] handle_activate_map: Not dirtying info: last_persisted is 289568 while current is 289568
2014-05-25 15:10:41.614574 7fbc0ab4b700 10 osd.58 350946 advance_pg advanced by max 200 past min epoch 289568 ... will requeue pg[2.35d( empty local-les=289560 n=0 ec=1 les/c 289560/289560 289567/289567/289559) [86,89] r=-1 lpr=289568 pi=289555-289566/2 crt=0'0 inactive NOTIFY]
2014-05-25 15:10:41.614586 7fbc0ab4b700 10 osd.58 pg_epoch: 289568 pg[2.35d( empty local-les=289560 n=0 ec=1 les/c 289560/289560 289567/289567/289559) [86,89] r=-1 lpr=289568 pi=289555-289566/2 crt=0'0 inactive NOTIFY] null
[root at storage0106-ib tmp]#






- Karan Singh -

> From: Sage Weil <sage at inktank.com>
> Subject: Re: 70+ OSD are DOWN and not coming up
> Date: 25 May 2014 01:22:13 GMT+3
> To: Karan Singh <karan.singh at csc.fi>
> Cc: Ceph Community <ceph-community at lists.ceph.com>
> 
> On Sun, 25 May 2014, Karan Singh wrote:
>> Hello Sage 
>> 
>> i tried your procedure for this problem. Its been over 72 hours the
>> problematic OSDs are still trying loading and decoding the correct OSD map
>> epoch. All the 32 OSDS have the same problem . OSD service is started , but
>> OSD is down in cluster and they are still performing loading and decoding
>> operation.
>> 
>> To troubleshoot this issue , i have kept debug osd = 20 , and till now all
>> these OSDS have generated 7 TB of logs ( I do not have space problem for
>> logs as logs are kept on a 60TB common NFS share ).
>> 
>> Now after comparing the logs , i found that loading and decoding operation
>> is repeating itself , its not at all reaching to the Final correct OSD map
>> epoch. Here are some OSD logs for your reference.
>> 
>> 
>> http://pastebin.com/aSBY4XYm
>> 
>> 
>> 
>> [root at storage0106-ib ceph]# tail ceph-osd.58.log
>> 2014-05-25 00:18:16.756357 7fbfa35b7700 20 osd.58 350946 get_map 289768 -
> 
> In this case the PG is looking back ~60000 maps.  I'm confused how it got 
> into this state, but setting that aside for the moment, if your maps 
> aren't too large (your cluster isn't huge so that seems possible), you can 
> set 'osd map cache size = 75000' so that the OSD only loads these into 
> memory once.  Note that this will eat a significant amount of RAM, so you 
> may need to do this one OSD at a time.  Which might be a good idea anyway 
> to test that this works on a single OSD.
> 
> Was the cluster healthy before this all started?  What actually happened 
> to get things into this state?
> 
> sage
> 
> 
> 
>> loading and decoding 0x10f16200
>> 2014-05-25 00:18:16.756464 7fbfa2bb6700 20 osd.58 350946 get_map 289569 -
>> loading and decoding 0x10f15e00
>> 2014-05-25 00:18:16.756457 7fbfa35b7700 10 osd.58 pg_epoch: 289568 pg[2.429(
>> empty local-les=289539 n=0 ec=1 les/c 289539/289539 289567/289567/289538)
>> [52,65] r=-1 lpr=289568 pi=288989-289566/12 crt=0'0 inactive NOTIFY]
>> handle_activate_map
>> 2014-05-25 00:18:16.756518 7fbfa35b7700 10 osd.58 pg_epoch: 289568 pg[2.429(
>> empty local-les=289539 n=0 ec=1 les/c 289539/289539 289567/289567/289538)
>> [52,65] r=-1 lpr=289568 pi=288989-289566/12 crt=0'0 inactive NOTIFY]
>> take_waiters
>> 2014-05-25 00:18:16.756536 7fbfa35b7700 20 osd.58 pg_epoch: 289568 pg[2.429(
>> empty local-les=289539 n=0 ec=1 les/c 289539/289539 289567/289567/289538)
>> [52,65] r=-1 lpr=289568 pi=288989-289566/12 crt=0'0 inactive NOTIFY]
>> handle_activate_map: Not dirtying info: last_persisted is 289568 while
>> current is 289568
>> 2014-05-25 00:18:16.756556 7fbfa35b7700 10 osd.58 350946 advance_pg advanced
>> by max 200 past min epoch 289568 ... will requeue pg[2.429( empty
>> local-les=289539 n=0 ec=1 les/c 289539/289539 289567/289567/289538) [52,65]
>> r=-1 lpr=289568 pi=288989-289566/12 crt=0'0 inactive NOTIFY]
>> 2014-05-25 00:18:16.756580 7fbfa35b7700 10 osd.58 pg_epoch: 289568 pg[2.429(
>> empty local-les=289539 n=0 ec=1 les/c 289539/289539 289567/289567/289538)
>> [52,65] r=-1 lpr=289568 pi=288989-289566/12 crt=0'0 inactive NOTIFY] null
>> 2014-05-25 00:18:16.756599 7fbfa35b7700 10 log is not dirty
>> 2014-05-25 00:18:16.756600 7fbfa2bb6700 20 osd.58 350946 get_map 289570 -
>> loading and decoding 0x10f15e00
>> 2014-05-25 00:18:16.756695 7fbfa2bb6700 20 osd.58 350946 get_map 289571 -
>> loading and decoding 0x10f15e00
>> 
>> 
>> 
>> [root at storage0102-ib ceph]# tail ceph-osd.7.log
>> 2014-05-25 00:07:07.547447 7f7d1649b700 20 osd.7 350946 get_map 299068 -
>> loading and decoding 0x35ec200
>> 2014-05-25 00:07:07.547542 7f7d1649b700 20 osd.7 350946 get_map 299069 -
>> loading and decoding 0x35ec200
>> 2014-05-25 00:07:07.547636 7f7d1649b700 20 osd.7 350946 get_map 299070 -
>> loading and decoding 0x35ec200
>> 2014-05-25 00:07:07.547730 7f7d1649b700 20 osd.7 350946 get_map 299071 -
>> loading and decoding 0x35ec200
>> 2014-05-25 00:07:07.547825 7f7d1649b700 20 osd.7 350946 get_map 299072 -
>> loading and decoding 0x35ec200
>> 2014-05-25 00:07:07.547920 7f7d1649b700 20 osd.7 350946 get_map 299073 -
>> loading and decoding 0x35ec200
>> 2014-05-25 00:07:07.548014 7f7d1649b700 20 osd.7 350946 get_map 299074 -
>> loading and decoding 0x35ec200
>> 2014-05-25 00:07:07.548116 7f7d1649b700 20 osd.7 350946 get_map 299075 -
>> loading and decoding 0x35ec200
>> 2014-05-25 00:07:07.548211 7f7d1649b700 20 osd.7 350946 get_map 299076 -
>> loading and decoding 0x35ec200
>> 2014-05-25 00:07:07.548305 7f7d1649b700 20 osd.7 350946 get_map 299077 -
>> loading and decoding 0x35ec200
>> [root at storage0102-ib ceph]# tail ceph-osd.7.log
>> 2014-05-25 00:07:08.764574 7f7d1649b700 20 osd.7 350946 get_map 299070 -
>> loading and decoding 0x35ec200
>> 2014-05-25 00:07:08.764565 7f7d15a9a700 10 osd.7 pg_epoch: 298887 pg[0.64a(
>> empty local-les=298850 n=0 ec=1 les/c 298850/298850 298887/298887/298887)
>> [113,86] r=-1 lpr=298887 pi=298849-298886/1 crt=0'0 inactive NOTIFY]
>> handle_activate_map
>> 2014-05-25 00:07:08.764609 7f7d15a9a700 10 osd.7 pg_epoch: 298887 pg[0.64a(
>> empty local-les=298850 n=0 ec=1 les/c 298850/298850 298887/298887/298887)
>> [113,86] r=-1 lpr=298887 pi=298849-298886/1 crt=0'0 inactive NOTIFY]
>> take_waiters
>> 2014-05-25 00:07:08.764630 7f7d15a9a700 20 osd.7 pg_epoch: 298887 pg[0.64a(
>> empty local-les=298850 n=0 ec=1 les/c 298850/298850 298887/298887/298887)
>> [113,86] r=-1 lpr=298887 pi=298849-298886/1 crt=0'0 inactive NOTIFY]
>> handle_activate_map: Not dirtying info: last_persisted is 298887 while
>> current is 298887
>> 2014-05-25 00:07:08.764643 7f7d15a9a700 10 osd.7 350946 advance_pg advanced
>> by max 200 past min epoch 298887 ... will requeue pg[0.64a( empty
>> local-les=298850 n=0 ec=1 les/c 298850/298850 298887/298887/298887) [113,86]
>> r=-1 lpr=298887 pi=298849-298886/1 crt=0'0 inactive NOTIFY]
>> 2014-05-25 00:07:08.764654 7f7d15a9a700 10 osd.7 pg_epoch: 298887 pg[0.64a(
>> empty local-les=298850 n=0 ec=1 les/c 298850/298850 298887/298887/298887)
>> [113,86] r=-1 lpr=298887 pi=298849-298886/1 crt=0'0 inactive NOTIFY] null
>> 2014-05-25 00:07:08.764675 7f7d15a9a700 10 log is not dirty
>> 2014-05-25 00:07:08.764712 7f7d1649b700 20 osd.7 350946 get_map 299071 -
>> loading and decoding 0x35ec200
>> 2014-05-25 00:07:08.764814 7f7d1649b700 20 osd.7 350946 get_map 299072 -
>> loading and decoding 0x35ec200
>> 2014-05-25 00:07:08.764915 7f7d1649b700 20 osd.7 350946 get_map 299073 -
>> loading and decoding 0x35ec200
>> 
>> 
>> 
>> 
>> 2014-05-25 00:16:44.291343 7f38c9551700 20 osd.93 350946 get_map 118210 -
>> loading and decoding 0x35e2c00
>> 2014-05-25 00:16:44.294767 7f38c8d50700 10 osd.93 pg_epoch: 118065 pg[2.752(
>> empty local-les=118029 n=0 ec=1 les/c 118029/118029 118065/118065/117839)
>> [14,126] r=-1 lpr=118065 pi=529-118064/6419 crt=0'0 inactive NOTIFY]
>> take_waiters
>> 2014-05-25 00:16:44.294829 7f38c8d50700 20 osd.93 pg_epoch: 118065 pg[2.752(
>> empty local-les=118029 n=0 ec=1 les/c 118029/118029 118065/118065/117839)
>> [14,126] r=-1 lpr=118065 pi=529-118064/6419 crt=0'0 inactive NOTIFY]
>> handle_activate_map: Not dirtying info: last_persisted is 118065 while
>> current is 118065
>> 2014-05-25 00:16:44.294920 7f38c8d50700 10 osd.93 350946 advance_pg advanced
>> by max 200 past min epoch 118065 ... will requeue pg[2.752( empty
>> local-les=118029 n=0 ec=1 les/c 118029/118029 118065/118065/117839) [14,126]
>> r=-1 lpr=118065 pi=529-118064/6419 crt=0'0 inactive NOTIFY]
>> 2014-05-25 00:16:44.294929 7f38c8d50700 10 osd.93 pg_epoch: 118065 pg[2.752(
>> empty local-les=118029 n=0 ec=1 les/c 118029/118029 118065/118065/117839)
>> [14,126] r=-1 lpr=118065 pi=529-118064/6419 crt=0'0 inactive NOTIFY] null
>> 2014-05-25 00:16:44.294954 7f38c8d50700 10 log is not dirty
>> 2014-05-25 00:16:44.295162 7f38c9551700 20 osd.93 350946 get_map 118211 -
>> loading and decoding 0x35e2c00
>> 2014-05-25 00:16:44.295205 7f38c9551700 20 osd.93 350946 get_map 118212 -
>> loading and decoding 0x35e2c00
>> 2014-05-25 00:16:44.295242 7f38c9551700 20 osd.93 350946 get_map 118213 -
>> loading and decoding 0x35e2c00
>> 2014-05-25 00:16:44.295277 7f38c9551700 20 osd.93 350946 get_map 118214 -
>> loading and decoding 0x35e2c00
>> 2014-05-25 00:16:44.295312 7f38c9551700 20 osd.93 350946 get_map 118215 -
>> loading and decoding 0x35e2c00
>> 
>> 
>> 
>> Can you suggest what next can be done here for these 32 OSDS , your support
>> will be highly appreciated to make cluster healthy again.
>> 
>> 
>> - Karan -
>> 
>> On 22 May 2014, at 20:08, Karan Singh <karan.singh at csc.fi> wrote:
>> 
>>      Hello Sage
>> *  I have followed your advice  that you have mentioned below  , but
>>    still OSDS are doing coding and decoding  and  cluster is
>>    unhealthy.
>> 
>> [root at storage0112-ib ceph]# ceph -s
>>     cluster 009d3518-e60d-4f74-a26d-c08c1976263c
>>      health HEALTH_WARN 1709 pgs degraded; 275 pgs incomplete; 52 pgs
>> stale; 275 pgs stuck inactive; 52 pgs stuck stale; 3143 pgs stuck
>> unclean; recovery 543/3642 objects degraded (14.909%); 54/165 in osds
>> are down; noup,nodown,noout flag(s) set
>>      monmap e4: 4 mons at{storage0101-ib=192.168.100.101:6789/0,storage0110-ib=192.168.100.110:6789/
>> 0,storage0114-ib=192.168.100.114:6789/0,storage0115-ib=192.168.100.115:6789
>> /0}, election epoch 22, quorum 0,1,2,3
>> storage0101-ib,storage0110-ib,storage0114-ib,storage0115-ib
>>      mdsmap e163: 1/1/1 up {0=storage0102=up:active}
>>      osdmap e358481: 165 osds: 111 up, 165 in
>>             flags noup,nodown,noout
>>       pgmap v606405: 4544 pgs, 6 pools, 6101 MB data, 1214 objects
>>             3493 GB used, 357 TB / 361 TB avail
>>             543/3642 objects degraded (14.909%)
>>                    6 stale+active+degraded+remapped
>>                 1390 active+clean
>>                   11 stale+incomplete
>>                   21 stale+active+remapped
>>                  600 active+degraded+remapped
>>                  214 incomplete
>>                 1138 active+remapped
>>                    2 stale+active+degraded
>>                    1 stale+remapped+incomplete
>>                 1101 active+degraded
>>                   11 stale+active+clean
>>                   49 remapped+incomplete
>> 
>> 
>> *  I have tried restarting those OSDs which were not running OR were
>>    dead , but they are now throwing a new error while starting up.
>>    (http://pastebin.com/v8F0v2Jz)
>> 
>> 1. [root at storage0107-ib ceph]# service ceph start osd
>> 2. === osd.106 ===
>> 3. Starting Ceph osd.106 on storage0107-ib...already running
>> 4. === osd.143 ===
>> 5. Starting Ceph osd.143 on storage0107-ib...already running
>> 6. === osd.59 ===
>> 7. Starting Ceph osd.59 on storage0107-ib...already running
>> 8. === osd.94 ===
>> 9. Starting Ceph osd.94 on storage0107-ib...already running
>> 10. === osd.119 ===
>> 11. Starting Ceph osd.119 on storage0107-ib...already running
>> 12. === osd.82 ===
>> 13. failed: 'timeout 30 /usr/bin/ceph -c /etc/ceph/ceph.conf
>>    --name=osd.82 --keyring=/var/lib/ceph/osd/ceph-82/keyring osd
>>    crush create-or-move -- 82 2.73 host=storage0107-ib root=default'
>> 
>> 
>> After a continuous attempt of restarting them ,  it gets restarts
>> (usually after 6-7 manual attempts)
>> 
>> Can you advice me on this new error , there is absolutely no
>> communication problem between all the cluster nodes , even no resource
>> crunch. 
>> 
>> 1. failed: 'timeout 30 /usr/bin/ceph -c /etc/ceph/ceph.conf
>>    --name=osd.82 --keyring=/var/lib/ceph/osd/ceph-82/keyring osd
>>    crush create-or-move -- 82 2.73 host=storage0107-ib root=default'
>> 
>> I have applied a crontab which will do ?service ceph start? every 30
>> minutes , Since OSD service is not getting started logs are not
>> getting created , no i don?t have any idea whats going on here.
>> 
>> *  For other osds coding and decoding operations is going on , i am
>>    still waiting so that each osd reaches a correct osd map eopoc 
>> 
>> 
>> I will keep you posted with the status , but please help in getting
>> this new error troubleshooted.
>> 
>> 
>> Regards
>> Karan
>> 
>> 
>> 
>> 
>> On 22 May 2014, at 10:26, Craig Lewis <clewis at centraldesktop.com>
>> wrote:
>> 
>>      On 5/21/14 21:15 , Sage Weil wrote:
>> 
>> On Wed, 21 May 2014, Craig Lewis wrote:
>> 
>> If you do this over IRC, can you please post a summary to the mailling
>> list? 
>> 
>> I believe I'm having this issue as well.
>> 
>> In the other case, we found that some of the OSDs were behind processing 
>> maps (by several thousand epochs).  The trick here to give them a chance 
>> to catch up is
>> 
>> ceph osd set noup
>> ceph osd set nodown
>> ceph osd set noout
>> 
>> and wait for them to stop spinning on the CPU.  You can check which map 
>> each OSD is on with
>> 
>> ceph daemon osd.NNN status
>> 
>> to see which epoch they are on and compare that to
>> 
>> ceph osd stat
>> 
>> Once they are within 100 or less epochs,
>> 
>> ceph osd unset noup
>> 
>> and let them all start up.
>> 
>> We haven't determined whether the original problem was caused by this or 
>> the other way around; we'll see once they are all caught up.
>> 
>> sage
>> 
>> 
>> I was seeing the CPU spinning too, so I think it is the same
>> issue.  Thanks for the explanation!  I've been pulling my hair
>> out for weeks. 
>> 
>> 
>> I can give you a data point for the "how".  My problems started
>> with a kswapd problem on 12.04.04 (kernel 3.5.0-46-generic
>> #70~precise1-Ubuntu).  kswapd was consuming 100% CPU, and it was
>> blocking the ceph-osd processes.  Once I prevented kswapd from
>> doing that, my OSDs couldn't recover.  noout and nodown didn't
>> help; the OSDs would suicide and restart.
>> 
>> 
>> Upgrading to Ubuntu 14.04 seems to have helped.  The cluster
>> isn't all clear yet, but it's getting better.  The cluster is
>> finally healthy after 2 weeks of incomplete and stale.  It's
>> still unresponsive, but it's making progress.  I am still seeing
>> OSD's consuming 100% CPU, but only the OSDs that are actively
>> deep-scrubing.  Once the deep-scrub finishes, the OSD starts
>> behaving again.  They seem to be slowly getting better, which
>> matches up with your explanation.
>> 
>> 
>> I'll go ahead at set noup.  I don't think it's necessary at this
>> point, but it's not going to hurt.
>> 
>> I'm running Emperor, and looks like osd status isn't supported. 
>> Not a big deal though.  Deep-scrub has made it through half of
>> the PGs in the last 36 hours, so I'll just watch for another day
>> or two.  This is a slave cluster, so I have that luxury.
>> 
>> 
>> 
>> 
>> 
>> 
>> 
>> --
>> 
>> Craig Lewis
>> Senior Systems Engineer
>> Office +1.714.602.1309
>> Email clewis at centraldesktop.com
>> 
>> Central Desktop. Work together in ways you never thought
>> possible.
>> Connect with us   Website  |  Twitter  |  Facebook  |  LinkedIn
>>  |  Blog
>> 
>> _______________________________________________
>> ceph-users mailing list
>> ceph-users at lists.ceph.com
>> http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ceph.com/pipermail/ceph-users-ceph.com/attachments/20140525/fb4122f0/attachment.htm>


[Index of Archives]     [Information on CEPH]     [Linux Filesystem Development]     [Ceph Development]     [Ceph Large]     [Ceph Dev]     [Linux USB Development]     [Video for Linux]     [Linux Audio Users]     [Yosemite News]     [Linux Kernel]     [Linux SCSI]     [xfs]


  Powered by Linux