Project

General

Profile

Bug #11616

Thrasher: recovery never completes

Added by David Zafman almost 9 years ago. Updated over 8 years ago.

Status:
Can't reproduce
Priority:
Urgent
Assignee:
-
Category:
-
Target version:
-
% Done:

0%

Source:
other
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

I'm able to look at the machines directly because teuthology hasn't cleaned up the nodes even though it has timed the test out.

ubuntu@teuthology:/a/dzafman-2015-05-12_08:43:26-rados-wip-10809-11135-10290---basic-multi/887732

The thrasher is attempting to do recovery with 3 of 6 OSDs out and some PGs remapped.

cluster 4ad7add3-85ca-4687-bb65-3be5e122bf60
health HEALTH_WARN
15 pgs backfill
14 pgs backfill_toofull
1 pgs backfilling
5 pgs degraded
5 pgs stuck degraded
5 pgs stuck inactive
16 pgs stuck unclean
5 pgs stuck undersized
5 pgs undersized
24 requests are blocked > 32 sec
recovery 2/98 objects degraded (2.041%)
recovery 14/98 objects misplaced (14.286%)
pool rbd pg_num 154 > pgp_num 124
pool unique_pool_0 pg_num 206 > pgp_num 146
mon.a has mon_osd_down_out_interval set to 0
monmap e1: 3 mons at {a=10.214.131.27:6789/0,b=10.214.132.27:6789/0,c=10.214.131.27:6790/0}
election epoch 6, quorum 0,1,2 a,b,c
osdmap e1071: 6 osds: 6 up, 3 in; 16 remapped pgs
pgmap v27774: 360 pgs, 2 pools, 123 MB data, 46 objects
787 MB used, 1304 GB / 1374 GB avail
2/98 objects degraded (2.041%)
14/98 objects misplaced (14.286%)
344 active+clean
9 active+remapped+wait_backfill+backfill_toofull
5 undersized+degraded+remapped+wait_backfill+backfill_toofull+peered
1 active+remapped+backfilling
1 active+remapped+wait_backfill

$ ceph pg dump | grep -v active+clean
dumped all in format plain
version 27829
stamp 2015-05-13 11:40:25.192811
last_osdmap_epoch 1071
last_pg_scan 1022
full_ratio 0.95
nearfull_ratio 0.85
pg_stat objects mip degr misp unf bytes log disklog state state_stamp v reported up up_primary acting acting_primary last_scrub scrub_stamp last_deep_scrub deep_scrub_stamp
1.ac 0 0 0 0 0 0 188 188 active+remapped+wait_backfill+backfill_toofull 2015-05-12 20:03:59.825490 902'369 1070:535 [5,0] 5 [0,4] 0 902'369 2015-05-12 19:59:39.619795 0'0 2015-05-12 19:30:28.789203
1.a0 0 0 0 0 0 0 111 111 active+remapped+wait_backfill+backfill_toofull 2015-05-12 20:03:59.824730 861'295 1070:233 [0,5] 0 [0,2] 0 861'295 2015-05-12 19:58:20.019156 0'0 2015-05-12 19:30:28.789161
1.89 0 0 0 0 0 0 94 94 active+remapped+wait_backfill+backfill_toofull 2015-05-12 20:03:48.736503 649'229 1067:288 [5,1] 5 [5,2] 5 649'229 2015-05-12 19:56:18.364293 0'0 2015-05-12 19:30:28.789192
1.7e 0 0 0 0 0 0 22 22 active+remapped+wait_backfill+backfill_toofull 2015-05-12 20:03:59.807621 457'212 1070:197 [5,0] 5 [2,4] 2 457'212 2015-05-12 19:58:50.609703 0'0 2015-05-12 19:30:28.789207
1.7c 0 0 0 0 0 0 177 177 active+remapped+wait_backfill+backfill_toofull 2015-05-12 20:03:50.936601 818'391 1069:504 [0,1] 0 [0,2] 0 818'391 2015-05-12 19:57:08.906200 0'0 2015-05-12 19:30:28.789203
1.77 0 0 0 0 0 0 66 66 undersized+degraded+remapped+wait_backfill+backfill_toofull+peered 2015-05-12 20:03:59.807011 982'394 1070:352 [1,0] 1 [2] 2 982'394 2015-05-12 20:02:19.860252 0'0 2015-05-12 19:30:28.789178
1.67 1 0 1 1 0 2212479 75 75 undersized+degraded+remapped+wait_backfill+backfill_toofull+peered 2015-05-12 20:03:59.817333 924'275 1070:267 [0,5] 0 [0] 0 796'271 2015-05-12 19:56:51.267580 0'0 2015-05-12 19:30:28.789178
1.5c 0 0 0 0 0 0 40 40 active+remapped+wait_backfill+backfill_toofull 2015-05-12 20:03:59.806368 153'254 1070:449 [5,1] 5 [2,4] 2 153'254 2015-05-12 19:56:54.587089 0'0 2015-05-12 19:30:28.789203
1.5a 2 0 0 4 0 3646498 67 67 active+remapped+wait_backfill 2015-05-12 20:03:38.038441 984'247 1060:139 [5,0] 5 [5,2] 5 730'211 2015-05-12 19:56:05.579441 0'0 2015-05-12 19:30:28.789195
1.4c 0 0 0 0 0 0 92 92 undersized+degraded+remapped+wait_backfill+backfill_toofull+peered 2015-05-12 20:03:59.805793 979'453 1070:545 [0,1] 0 [2] 2 979'453 2015-05-12 20:02:17.334981 0'0 2015-05-12 19:30:28.789203
1.4a 0 0 0 0 0 1974553 106 106 undersized+degraded+remapped+wait_backfill+backfill_toofull+peered 2015-05-12 20:03:59.805460 988'443 1070:384 [1,0] 1 [2] 2 988'443 2015-05-12 20:02:16.334811 0'0 2015-05-12 19:30:28.789195
1.3c 0 0 0 0 0 0 160 160 active+remapped+wait_backfill+backfill_toofull 2015-05-12 20:03:50.928960 959'392 1069:520 [5,1] 5 [5,2] 5 959'392 2015-05-12 20:01:21.707562 0'0 2015-05-12 19:30:28.789203
1.28 1 0 1 1 0 2109751 160 160 undersized+degraded+remapped+wait_backfill+backfill_toofull+peered 2015-05-12 20:03:49.828794 958'476 1068:604 [5,0] 5 [5] 5 958'476 2015-05-12 20:00:57.702081 0'0 2015-05-12 19:30:28.789189
1.20 2 0 0 4 0 3844669 128 128 active+remapped+wait_backfill+backfill_toofull 2015-05-12 20:03:59.833581 1023'312 1070:246 [0,5] 0 [0,2] 0 861'295 2015-05-12 19:57:40.016401 0'0 2015-05-12 19:30:28.789161
0.1c 0 0 0 0 0 0 0 0 active+remapped+wait_backfill+backfill_toofull 2015-05-12 20:03:59.831561 0'0 1070:64 [5,0] 5 [0,1] 0 0'0 2015-05-12 20:00:35.741357 0'0 2015-05-12 19:30:13.595554
1.8 2 0 0 4 0 6299472 195 195 active+remapped+backfilling 2015-05-12 20:03:41.322014 979'320 1063:247 [5,1] 5 [5,4] 5 979'320 2015-05-12 20:02:03.717363 0'0 2015-05-12 19:30:28.789189
...

$ df -h
Filesystem Size Used Avail Use% Mounted on
/dev/sda1 451G 21G 408G 5% /
udev 3.9G 12K 3.9G 1% /dev
tmpfs 797M 292K 797M 1% /run
none 5.0M 0 5.0M 0% /run/lock
none 3.9G 0 3.9G 0% /run/shm
/dev/sdd 459G 269M 435G 1% /var/lib/ceph/osd/ceph-0
/dev/sdb 459G 240M 435G 1% /var/lib/ceph/osd/ceph-1
/dev/sdc 459G 192M 435G 1% /var/lib/ceph/osd/ceph-2

$ df -h
Filesystem Size Used Avail Use% Mounted on
/dev/sda1 451G 21G 407G 5% /
udev 3.9G 12K 3.9G 1% /dev
tmpfs 1.6G 292K 1.6G 1% /run
none 5.0M 0 5.0M 0% /run/lock
none 3.9G 0 3.9G 0% /run/shm
/dev/sdd 459G 179M 435G 1% /var/lib/ceph/osd/ceph-3
/dev/sdb 459G 188M 435G 1% /var/lib/ceph/osd/ceph-4
/dev/sdc 459G 280M 435G 1% /var/lib/ceph/osd/ceph-5

$ grep "thrasher\|recovery to complete" teuthology.log | tail
2015-05-12T20:02:56.661 INFO:tasks.thrashosds.thrasher:Reweighting osd 5 to 0.466828207213
2015-05-12T20:03:02.461 INFO:tasks.thrashosds.thrasher:in_osds: [0, 5, 2, 1] out_osds: [3, 4] dead_osds: [4] live_osds: [5, 1, 2, 3, 0]
2015-05-12T20:03:02.462 INFO:tasks.thrashosds.thrasher:choose_action: min_in 3 min_out 0 min_live 2 min_dead 0
2015-05-12T20:03:02.462 INFO:tasks.thrashosds.thrasher:Removing osd 2, in_osds are: [0, 5, 2, 1]
2015-05-12T20:03:08.685 INFO:tasks.thrashosds.thrasher:in_osds: [0, 5, 1] out_osds: [3, 4, 2] dead_osds: [4] live_osds: [5, 1, 2, 3, 0]
2015-05-12T20:03:08.685 INFO:tasks.thrashosds.thrasher:choose_action: min_in 3 min_out 0 min_live 2 min_dead 0
2015-05-12T20:03:08.685 INFO:tasks.thrashosds.thrasher:Reviving osd 4
2015-05-12T20:03:18.946 INFO:tasks.thrashosds.thrasher:in_osds: [0, 5, 1] out_osds: [3, 4, 2] dead_osds: [] live_osds: [5, 1, 2, 3, 0, 4]
2015-05-12T20:03:22.739 INFO:tasks.ceph.ceph_manager:waiting for recovery to complete
2015-05-12T20:24:08.020 INFO:tasks.thrashosds.thrasher:Traceback (most recent call last):

This line from the log makes me nervous. What if there was a race, but we shouldn't have ignored
2015-05-12 20:04:00.931028 7ff4a34ac700 10 osd.0 pg_epoch: 1071 pg[1.ac( v 902'369 (77'181,902'369] local-les=1054 n=0 ec=6 les/c 1054/1021 1053/1053/1034) [5,0]/[0,4] r=0 lpr=1053 pi=1011-1052/7 bft=5 crt=0'0 lcod 0'0 mlcod 0'0 active+remapped+wait_backfill+backfill_toofull snaptrimq=[222~1,224~1]] recovery raced and were queued twice, ignoring!

/* TODO: I think this case is broken and will make do_recovery()
 * unhappy since we're returning false */
dout(10) << "recovery raced and were queued twice, ignoring!" << dendl;
return false;
}

History

#1 Updated by David Zafman almost 9 years ago

#2 Updated by Samuel Just almost 9 years ago

  • Priority changed from Normal to Urgent

#3 Updated by Samuel Just over 8 years ago

  • Status changed from New to Can't reproduce

Also available in: Atom PDF