Wido, I've not done any changes from the default settings. There are no firewalls between the ceph cluster members and I do not see a great deal of network related errors either. There is a tiny amount of TX errors on the network interface, which accounts to 0.0001% of the total packets.
Regarding the debug_ms , do I set this on ceph-mon side or on all osds or both?
Thanks
Regarding the debug_ms , do I set this on ceph-mon side or on all osds or both?
Thanks
From: "Wido den Hollander" <wido@xxxxxxxx>
To: ceph-users@xxxxxxxxxxxxxx
Sent: Friday, 14 November, 2014 12:30:02 PM
Subject: Re: Giant osd problems - loss of IO
On 14-11-14 13:26, Andrei Mikhailovsky wrote:
> Hello guys,
>
> Since upgrading my cluster to Giant from the previous stable release I
> started having massive problems with client IO. I've done the upgrade 2
> weeks ago and since then the IO on my ceph cluster has been unavailable
> 3 times already.
>
> Quick info on my storage cluster - 3 mons, 2 osd servers, 17 osds, 4
> ssds for journals. All running Giant release from ceph repos on Ubuntu
> 12.04 with the latest updates.
>
> Every time I experience a very similar problem. Two out of 17 osds are
> shown as down even though the corresponding ceph-osd processes are
> running. Somehow, the down-ing of two osds brings down the IO in the
> cluster. This has not happened before upgrading to Giant. It seems that
> everytime different osds go down, but it happens on the same osd server.
> The latest one happened tonight. The ceph -s showed the following:
>
> root@arh-ibstorage1-ib:~# ceph -s
> cluster 51e9f641-372e-44ec-92a4-b9fe55cbf9fe
> health HEALTH_WARN 1001 pgs degraded; 150 pgs down; 150 pgs
> peering; 1 pgs recovering; 41 pgs recovery_wait; 1001 pgs stuck
> degraded; 150 pgs stuck inactive; 1151 pgs stuck unclean; 967 pgs stuck
> undersized; 967 pgs undersized; 203 requests are blocked > 32 sec;
> recovery 661954/5994334 objects degraded (11.043%); 10/2997167 unfound
> (0.000%); 2/17 in osds are down; noout flag(s) set
> monmap e11: 3 mons at
> {arh-cloud13-ib=192.168.168.13:6789/0,arh-ibstorage1-ib=192.168.168.200:6789/0,arh-ibstorage2-ib=192.168.168.201:6789/0},
> election epoch 66832, quorum 0,1,2
> arh-cloud13-ib,arh-ibstorage1-ib,arh-ibstorage2-ib
> mdsmap e2709: 1/1/1 up {0=arh-ibstorage2-ib=up:active}, 1 up:standby
> osdmap e64374: 17 osds: 15 up, 17 in
> flags noout
> pgmap v39540041: 4412 pgs, 17 pools, 10245 GB data, 2926 kobjects
> 20570 GB used, 26853 GB / 47423 GB avail
> 661954/5994334 objects degraded (11.043%); 10/2997167
> unfound (0.000%)
> 1 active+recovering+undersized+degraded
> 3261 active+clean
> 34 active+recovery_wait+degraded
> 959 active+undersized+degraded
> 7 active+recovery_wait+undersized+degraded
> 150 down+peering
> client io 0 B/s rd, 13805 B/s wr, 4 op/s
>
>
> "ceph osd tree" shows:
>
> root@arh-ibstorage1-ib:~# ceph osd tree
> # id weight type name up/down reweight
> -10 1.8 root uk-ssd
> -9 1.8 datacenter ldex-ssd
> -12 1.8 room ldex-dc3-ssd
> -14 1.8 row row-a-ssd
> -8 1.8 rack ldex-rack-a5-ssd
> -6 0.9 host arh-ibstorage1-ib-ssd
> -7 0.9 host arh-ibstorage2-ib-ssd
> -1 46.41 root uk
> -5 46.41 datacenter ldex
> -11 46.41 room ldex-dc3
> -13 46.41 row row-a
> -4 46.41 rack ldex-rack-a5
> -2 24.57 host arh-ibstorage1-ib
> 1 2.73 osd.1 up 1
> 3 2.73 osd.3 up 1
> 5 2.73 osd.5 up 1
> 6 2.73 osd.6 up 1
> 7 2.73 osd.7 up 1
> 8 2.73 osd.8 up 1
> 4 2.73 osd.4 up 1
> 0 2.73 osd.0 up 1
> 2 2.73 osd.2 up 1
> -3 21.84 host arh-ibstorage2-ib
> 9 2.73 osd.9 up 1
> 10 2.73 osd.10 up 1
> 11 2.73 osd.11 up 1
> 12 2.73 osd.12 down 1
> 13 2.73 osd.13 up 1
> 14 2.73 osd.14 up 1
> 15 2.73 osd.15 up 1
> 16 2.73 osd.16 down 1
>
>
> From the ceph -s it seems that some PGs were down and peering. There was
> no change in the ceph -s output for over an hour. The client IO activity
> ground to a halt and all vms became unresponsive and eventually crashed.
> The cluster was unusable until I have manually stopped osd.12 and osd.16
> and restarted them again. This has solved the problem.
>
> Previously this has happened about four days ago with osds 11 and 15 and
> it also happened about 10 days ago with different osds. So, having lost
> the storage IO three times in the last two weeks is a big deal.
>
> Looking at the ceph logs I've discovered that since performing the
> upgrade I have seen a far more messages reporting osds being down.
> Different osds are reported as being down and they come back up after
> about 5-30 seconds, perform recovery and the cluster is back to normal
> (apart from the three tiimes which actually brought the cluster io down).
>
> Furthermore, about a few minutes before osd.12 and osd.16 went down,
> I've seen 2 PGs are being deep scrubbed while osd.7 was reported down by
> 3 peers:
>
>
>
> 2014-11-13 20:55:36.608502 mon.0 192.168.168.13:6789/0 1210074 : cluster
> [INF] pgmap v39509396: 4412 pgs: 4410 active+clean, 2
> active+clean+scrubbing+deep; 10245 GB data, 20570 GB used, 26853 GB /
> 47423 GB avail; 10005 kB/s rd, 3486 kB/s wr, 310 op/s
> 2014-11-13 20:56:10.056933 mon.0 192.168.168.13:6789/0 1210209 : cluster
> [INF] pgmap v39509409: 4412 pgs: 3380 active+clean, 2
> active+clean+scrubbing+deep, 1030 active+undersized+degraded; 10245 GB
> data, 20570 GB used, 26853 GB / 47423 GB avail; 112 kB/s rd, 122 kB/s
> wr, 37 op/s; 662204/5994308 objects degraded (11.047%)
> 2014-11-13 20:56:10.073317 mon.0 192.168.168.13:6789/0 1210210 : cluster
> [INF] osd.7 192.168.168.200:6838/26321 boot
> 2014-11-13 20:56:10.073461 mon.0 192.168.168.13:6789/0 1210211 : cluster
> [INF] osd.3 192.168.168.200:6818/26170 boot
> 2014-11-13 20:56:10.074415 mon.0 192.168.168.13:6789/0 1210212 : cluster
> [INF] osdmap e64099: 17 osds: 17 up, 17 in
> 2014-11-13 20:56:10.109650 mon.0 192.168.168.13:6789/0 1210213 : cluster
> [INF] pgmap v39509410: 4412 pgs: 3380 active+clean, 2
> active+clean+scrubbing+deep, 1030 active+undersized+degraded; 10245 GB
> data, 20570 GB used, 26853 GB / 47423 GB avail; 97137 B/s rd, 220 kB/s
> wr, 36 op/s; 662204/5994308 objects degraded (11.047%)
> 2014-11-13 20:56:11.082817 mon.0 192.168.168.13:6789/0 1210214 : cluster
> [INF] osdmap e64100: 17 osds: 17 up, 17 in
> 2014-11-13 20:56:11.741135 mon.1 192.168.168.200:6789/0 520573 : cluster
> [INF] mon.arh-ibstorage1-ib calling new monitor election
> 2014-11-13 20:56:11.744641 mon.2 192.168.168.201:6789/0 521421 : cluster
> [INF] mon.arh-ibstorage2-ib calling new monitor election
> 2014-11-13 20:56:11.745988 mon.0 192.168.168.13:6789/0 1210248 : cluster
> [INF] mon.arh-cloud13-ib calling new monitor election
> 2014-11-13 20:56:11.754388 mon.0 192.168.168.13:6789/0 1210249 : cluster
> [INF] mon.arh-cloud13-ib@0 won leader election with quorum 0,1,2
> 2014-11-13 20:56:11.763975 mon.0 192.168.168.13:6789/0 1210250 : cluster
> [INF] monmap e11: 3 mons at
> {arh-cloud13-ib=192.168.168.13:6789/0,arh-ibstorage1-ib=192.168.168.200:6789/0,arh-ibstorage2-ib=192.168.168.201:6789/0}
> 2014-11-13 20:56:11.764069 mon.0 192.168.168.13:6789/0 1210251 : cluster
> [INF] pgmap v39509411: 4412 pgs: 3380 active+clean, 2
> active+clean+scrubbing+deep, 1030 active+undersized+degraded; 10245 GB
> data, 20570 GB used, 26853 GB / 47423 GB avail; 662204/5994308 objects
> degraded (11.047%)
> 2014-11-13 20:56:11.764147 mon.0 192.168.168.13:6789/0 1210252 : cluster
> [INF] mdsmap e2705: 1/1/1 up {0=arh-ibstorage2-ib=up:active}, 1 up:standby
> 2014-11-13 20:56:11.764283 mon.0 192.168.168.13:6789/0 1210253 : cluster
> [INF] osdmap e64100: 17 osds: 17 up, 17 in
> 2014-11-13 20:56:11.764859 mon.0 192.168.168.13:6789/0 1210257 : cluster
> [INF] osd.7 192.168.168.200:6838/26321 failed (3 reports from 3 peers
> after 32.005619 >= grace 25.962628)
> 2014-11-13 20:56:12.721171 mon.0 192.168.168.13:6789/0 1210262 : cluster
> [INF] osdmap e64101: 17 osds: 16 up, 17 in
> 2014-11-13 20:56:13.294162 mon.0 192.168.168.13:6789/0 1210263 : cluster
> [INF] pgmap v39509413: 4412 pgs: 3380 active+clean, 2
> active+clean+scrubbing+deep, 1030 active+undersized+degraded; 10245 GB
> data, 20570 GB used, 26853 GB / 47423 GB avail; 1150 kB/s rd, 561 kB/s
> wr, 193 op/s; 662204/5994308 objects degraded (11.047%)
> 2014-11-13 20:56:14.325109 mon.0 192.168.168.13:6789/0 1210264 : cluster
> [INF] osdmap e64102: 17 osds: 16 up, 17 in
> 2014-11-13 20:56:14.357819 mon.0 192.168.168.13:6789/0 1210265 : cluster
> [INF] pgmap v39509414: 4412 pgs: 3380 active+clean, 2
> active+clean+scrubbing+deep, 1030 active+undersized+degraded; 10245 GB
> data, 20570 GB used, 26853 GB / 47423 GB avail; 662204/5994308 objects
> degraded (11.047%)
> 2014-11-13 20:56:15.442751 mon.0 192.168.168.13:6789/0 1210266 : cluster
> [INF] pgmap v39509415: 4412 pgs: 3685 active+clean, 2
> active+clean+scrubbing+deep, 18 active+recovery_wait+degraded, 707
> active+undersized+degraded; 10245 GB data, 20570 GB used, 26853 GB /
> 47423 GB avail; 28730 kB/s rd, 1087 kB/s wr, 590 op/s; 466784/5994308
> objects degraded (7.787%); 499 MB/s, 3 keys/s, 237 objects/s recovering
> 2014-11-13 20:56:16.364658 mon.0 192.168.168.13:6789/0 1210268 : cluster
> [INF] osd.7 192.168.168.200:6838/26321 boot
> 2014-11-13 20:56:16.366310 mon.0 192.168.168.13:6789/0 1210269 : cluster
> [INF] osdmap e64103: 17 osds: 17 up, 17 in
> 2014-11-13 20:56:16.380120 mon.0 192.168.168.13:6789/0 1210270 : cluster
> [INF] pgmap v39509416: 4412 pgs: 3685 active+clean, 2
> active+clean+scrubbing+deep, 18 active+recovery_wait+degraded, 707
> active+undersized+degraded; 10245 GB data, 20570 GB used, 26853 GB /
> 47423 GB avail; 33165 kB/s rd, 1255 kB/s wr, 682 op/s; 466784/5994308
> objects degraded (7.787%); 576 MB/s, 3 keys/s, 274 objects/s recovering
> 2014-11-13 20:56:17.400859 mon.0 192.168.168.13:6789/0 1210271 : cluster
> [INF] osdmap e64104: 17 osds: 17 up, 17 in
>
>
>
> So, for the next 20 seconds it was scrubbing until ceph reported that
> osd12 and osd16 reported being down:
>
>
>
> 2014-11-13 20:56:36.712346 mon.0 192.168.168.13:6789/0 1210327 : cluster
> [INF] osd.12 192.168.168.201:6810/10278 failed (11 reports from 9 peers
> after 24.080479 >= grace 23.026948)
> 2014-11-13 20:56:36.771124 mon.0 192.168.168.13:6789/0 1210330 : cluster
> [INF] osd.15 192.168.168.201:6801/4482 failed (10 reports from 8 peers
> after 24.118287 >= grace 23.285583)
> 2014-11-13 20:56:37.920306 mon.0 192.168.168.13:6789/0 1210345 : cluster
> [INF] pgmap v39509434: 4412 pgs: 122 peering, 4085 active+clean, 2
> active+clean+scrubbing+deep, 2 active+degraded, 16
> active+recovery_wait+degraded, 185 active+undersized+degraded; 10245 GB
> data, 20570 GB used, 26853 GB / 47423 GB avail; 13943 B/s rd, 506 kB/s
> wr, 86 op/s; 118552/5994302 objects degraded (1.978%); 666 kB/s, 0
> objects/s recovering
> 2014-11-13 20:56:37.963713 mon.0 192.168.168.13:6789/0 1210346 : cluster
> [INF] osdmap e64106: 17 osds: 15 up, 17 in
> 2014-11-13 20:56:38.458852 mon.0 192.168.168.13:6789/0 1210347 : cluster
> [INF] pgmap v39509435: 4412 pgs: 377 stale+active+clean, 122 peering,
> 3708 active+clean, 119 stale+active+undersized+degraded, 2
> active+clean+scrubbing+deep, 2 active+degraded, 16
> active+recovery_wait+degraded, 66 active+undersized+degraded; 10245 GB
> data, 20570 GB used, 26853 GB / 47423 GB avail; 20510 B/s rd, 430 kB/s
> wr, 76 op/s; 118552/5994302 objects degraded (1.978%)
> 2014-11-13 20:56:39.195535 mon.0 192.168.168.13:6789/0 1210349 : cluster
> [INF] osdmap e64107: 17 osds: 15 up, 17 in
> 2014-11-13 20:56:39.231384 mon.0 192.168.168.13:6789/0 1210350 : cluster
> [INF] pgmap v39509436: 4412 pgs: 377 stale+active+clean, 122 peering,
> 3708 active+clean, 119 stale+active+undersized+degraded, 2
> active+clean+scrubbing+deep, 2 active+degraded, 16
> active+recovery_wait+degraded, 66 active+undersized+degraded; 10245 GB
> data, 20570 GB used, 26853 GB / 47423 GB avail; 118552/5994302 objects
> degraded (1.978%)
> 2014-11-13 20:56:41.883606 mon.0 192.168.168.13:6789/0 1210352 : cluster
> [INF] pgmap v39509437: 4412 pgs: 377 stale+active+clean, 122 peering,
> 3708 active+clean, 119 stale+active+undersized+degraded, 2
> active+clean+scrubbing+deep, 1 active+degraded, 17
> active+recovery_wait+degraded, 66 active+undersized+degraded; 10245 GB
> data, 20570 GB used, 26853 GB / 47423 GB avail; 14341 B/s rd, 144 kB/s
> wr, 5 op/s; 118552/5994302 objects degraded (1.978%)
> 2014-11-13 20:56:43.617030 mon.0 192.168.168.13:6789/0 1210359 : cluster
> [INF] pgmap v39509438: 4412 pgs: 377 stale+active+clean, 122 peering,
> 3708 active+clean, 119 stale+active+undersized+degraded, 2
> active+clean+scrubbing+deep, 1 active+degraded, 17
> active+recovery_wait+degraded, 66 active+undersized+degraded; 10245 GB
> data, 20570 GB used, 26853 GB / 47423 GB avail; 718 kB/s rd, 215 kB/s
> wr, 46 op/s; 118552/5994302 objects degraded (1.978%)
> 2014-11-13 20:56:45.408475 mon.0 192.168.168.13:6789/0 1210365 : cluster
> [INF] pgmap v39509439: 4412 pgs: 46 peering, 3218 active+clean, 1
> active+clean+scrubbing+deep, 1 active+degraded, 12
> active+recovery_wait+degraded, 1007 active+undersized+degraded, 1
> active+recovery_wait+undersized+degraded, 126 down+peering; 10245 GB
> data, 20570 GB used, 26853 GB / 47423 GB avail; 1853 kB/s wr, 300 op/s;
> 696740/5994304 objects degraded (11.623%); 8/2997152 unfound (0.000%)
> 2014-11-13 20:56:46.517294 mon.0 192.168.168.13:6789/0 1210366 : cluster
> [INF] pgmap v39509440: 4412 pgs: 46 peering, 3222 active+clean, 1
> active+clean+scrubbing+deep, 9 active+recovery_wait+degraded, 1007
> active+undersized+degraded, 1 active+recovery_wait+undersized+degraded,
> 126 down+peering; 10245 GB data, 20570 GB used, 26853 GB / 47423 GB
> avail; 2242 kB/s wr, 358 op/s; 696737/5994304 objects degraded
> (11.623%); 8/2997152 unfound (0.000%)
>
>
>
> From this point on the client IO went down from an average of about 500
> op/s to 10-20 op/s. All vms started having hang tasks shortly after that
> and eventually most of them crashed. A few more seconds passed, the
> status changed to:
>
> 2014-11-13 20:59:19.857378 mon.0 192.168.168.13:6789/0 1210590 : cluster
> [INF] pgmap v39509547: 4412 pgs: 1
> active+recovering+undersized+degraded, 3268 active+clean, 19
> active+degraded, 7 active+recovery_wait+degraded, 959
> active+undersized+degraded, 7 active+recovery_wait+undersized+degraded,
> 150 down+peering, 1 active+recovering+degraded; 10245 GB data, 20570 GB
> used, 26853 GB / 47423 GB avail; 0 B/s rd, 546 kB/s wr, 103 op/s;
> 661943/5994302 objects degraded (11.043%); 10/2997151 unfound (0.000%);
> 53620 kB/s, 1 keys/s, 13 objects/s recovering
>
>
> And pretty much stayed like that for over an hour without changing much.
> The IO was still unavailable.
>
> Looking at the logs of the osds that were shown down, I don't really see
> much apart from some slow requests prior to the osds being reported down:
>
>
> 2014-11-13 20:56:10.315696 7fd9645be700 0 log_channel(default) log
> [WRN] : slow request 31.043640 seconds old, received at 2014-11-13
> 20:55:39.271942: osd_op(client.46407343.0
> :3839273 rbd_data.1f0a392ae8944a.0000000000000621 [set-alloc-hint
> object_size 4194304 write_size 4194304,write 3526656~4096] 5.9fe0f0f2
> ack+ondisk+write e64096) currently waiti
> ng for subops from 1
> 2014-11-13 20:56:10.467380 7fd941a75700 -1 osd.12 64099 heartbeat_check:
> no reply from osd.4 since back 2014-11-13 20:55:35.958627 front
> 2014-11-13 20:55:35.958627 (cutoff 2014
> -11-13 20:55:50.467379)
> 2014-11-13 20:56:10.467389 7fd941a75700 -1 osd.12 64099 heartbeat_check:
> no reply from osd.5 since back 2014-11-13 20:55:38.259184 front
> 2014-11-13 20:55:35.958627 (cutoff 2014
> -11-13 20:55:50.467379)
> 2014-11-13 20:56:10.467409 7fd941a75700 -1 osd.12 64099 heartbeat_check:
> no reply from osd.6 since back 2014-11-13 20:55:35.958627 front
> 2014-11-13 20:55:35.958627 (cutoff 2014
> -11-13 20:55:50.467379)
> 2014-11-13 20:56:10.467427 7fd941a75700 -1 osd.12 64099 heartbeat_check:
> no reply from osd.8 since back 2014-11-13 20:55:35.958627 front
> 2014-11-13 20:55:35.958627 (cutoff 2014
> -11-13 20:55:50.467379)
> 2014-11-13 20:56:10.967963 7fd941a75700 -1 osd.12 64099 heartbeat_check:
> no reply from osd.4 since back 2014-11-13 20:55:35.958627 front
> 2014-11-13 20:55:35.958627 (cutoff 2014
> -11-13 20:55:50.967962)
> 2014-11-13 20:56:10.967971 7fd941a75700 -1 osd.12 64099 heartbeat_check:
> no reply from osd.5 since back 2014-11-13 20:55:38.259184 front
> 2014-11-13 20:55:35.958627 (cutoff 2014
> -11-13 20:55:50.967962)
> 2014-11-13 20:56:10.967978 7fd941a75700 -1 osd.12 64099 heartbeat_check:
> no reply from osd.6 since back 2014-11-13 20:55:35.958627 front
> 2014-11-13 20:55:35.958627 (cutoff 2014
> -11-13 20:55:50.967962)
> 2014-11-13 20:56:10.967984 7fd941a75700 -1 osd.12 64099 heartbeat_check:
> no reply from osd.8 since back 2014-11-13 20:55:35.958627 front
> 2014-11-13 20:55:35.958627 (cutoff 2014
> -11-13 20:55:50.967962)
> 2014-11-13 20:56:11.317046 7fd9645be700 -1 osd.12 64100 heartbeat_check:
> no reply from osd.4 since back 2014-11-13 20:55:35.958627 front
> 2014-11-13 20:55:35.958627 (cutoff 2014-11-13 20:55:51.317043)
> 2014-11-13 20:56:11.317057 7fd9645be700 -1 osd.12 64100 heartbeat_check:
> no reply from osd.5 since back 2014-11-13 20:55:38.259184 front
> 2014-11-13 20:55:35.958627 (cutoff 2014-11-13 20:55:51.317043)
> 2014-11-13 20:56:11.317064 7fd9645be700 -1 osd.12 64100 heartbeat_check:
> no reply from osd.6 since back 2014-11-13 20:55:35.958627 front
> 2014-11-13 20:56:10.967590 (cutoff 2014-11-13 20:55:51.317043)
> 2014-11-13 20:56:11.317070 7fd9645be700 -1 osd.12 64100 heartbeat_check:
> no reply from osd.8 since back 2014-11-13 20:55:38.259184 front
> 2014-11-13 20:55:35.958627 (cutoff 2014-11-13 20:55:51.317043)
> 2014-11-13 20:56:11.317167 7fd9645be700 0 log_channel(default) log
> [WRN] : 17 slow requests, 7 included below; oldest blocked for >
> 32.285501 secs
> 2014-11-13 20:56:11.317173 7fd9645be700 0 log_channel(default) log
> [WRN] : slow request 32.285501 seconds old, received at 2014-11-13
> 20:55:39.031582: osd_op(client.46379104.0:182402
> rbd_data.2c26ec1333ab105.000000000000015a [stat,set-alloc-hint
> object_size 4194304 write_size 4194304,write 3956736~1024] 5.e9450c8d
> ack+ondisk+write e64096) currently waiting for subops from 4
> 2014-11-13 20:56:11.317179 7fd9645be700 0 log_channel(default) log
> [WRN] : slow request 32.047721 seconds old, received at 2014-11-13
> 20:55:39.269362: osd_op(client.46407343.0:3839258
> rbd_data.1f0a392ae8944a.0000000000000621 [set-alloc-hint object_size
> 4194304 write_size 4194304,write 1568768~8192] 5.9fe0f0f2
> ack+ondisk+write e64096) currently waiting for subops from 1
> 2014-11-13 20:56:11.317183 7fd9645be700 0 log_channel(default) log
> [WRN] : slow request 32.047396 seconds old, received at 2014-11-13
> 20:55:39.269687: osd_op(client.46407343.0:3839259
> rbd_data.1f0a392ae8944a.0000000000000621 [set-alloc-hint object_size
> 4194304 write_size 4194304,write 1773568~4096] 5.9fe0f0f2
> ack+ondisk+write e64096) currently waiting for subops from 1
> 2014-11-13 20:56:11.317187 7fd9645be700 0 log_channel(default) log
> [WRN] : slow request 32.047229 seconds old, received at 2014-11-13
> 20:55:39.269854: osd_op(client.46407343.0:3839260
> rbd_data.1f0a392ae8944a.0000000000000621 [set-alloc-hint object_size
> 4194304 write_size 4194304,write 1921024~4096] 5.9fe0f0f2
> ack+ondisk+write e64096) currently waiting for subops from 1
> 2014-11-13 20:56:11.317232 7fd9645be700 0 log_channel(default) log
> [WRN] : slow request 32.047069 seconds old, received at 2014-11-13
> 20:55:39.270014: osd_op(client.46407343.0:3839261
> rbd_data.1f0a392ae8944a.0000000000000621 [set-alloc-hint object_size
> 4194304 write_size 4194304,write 1949696~4096] 5.9fe0f0f2
> ack+ondisk+write e64096) currently waiting for subops from 1
> 2014-11-13 20:56:37.954923 7fd92c055700 0 -- 192.168.168.201:6812/10278
>>> 192.168.168.200:6820/56026102 pipe(0x2b369b00 sd=381 :6812 s=2
> pgs=205156 cs=1 l=0 c=0x1b29d420).fault with nothing to send, going to
> standby
> 2014-11-13 20:56:37.955547 7fd92bb50700 0 -- 192.168.168.201:6812/10278
>>> 192.168.168.200:6810/72026170 pipe(0x2ad35580 sd=238 :6812 s=2
> pgs=141844 cs=1 l=0 c=0xf33c420).fault with nothing to send, going to
> standby
> 2014-11-13 20:56:37.956392 7fd935deb700 0 -- 192.168.168.201:6812/10278
>>> 192.168.168.200:6807/70026130 pipe(0x2e2268c0 sd=408 :6812 s=2
> pgs=278536 cs=1 l=0 c=0x142f7420).fault with nothing to send, going to
> standby
> 2014-11-13 20:56:37.956695 7fd93e86d700 0 -- 192.168.168.201:6812/10278
>>> 192.168.168.200:6849/1026289 pipe(0x29b4c840 sd=129 :41140 s=2
> pgs=591 cs=1 l=0 c=0x29b58b00).fault with nothing to send, going to standby
> 2014-11-13 20:56:37.958245 7fd93e56a700 0 -- 192.168.168.201:6812/10278
>>> 192.168.168.200:6803/1026306 pipe(0x29bb7600 sd=154 :43005 s=2
> pgs=117 cs=1 l=0 c=0x29be4840).fault with nothing to send, going to standby
> 2014-11-13 20:56:37.969506 7fd93e368700 0 -- 192.168.168.201:6812/10278
>>> 192.168.168.200:6824/26238 pipe(0x29c98600 sd=146 :60953 s=2 pgs=148
> cs=1 l=0 c=0x29cd0840).fault with nothing to send, going to standby
> 2014-11-13 20:56:37.969620 7fd92a439700 0 -- 192.168.168.201:6812/10278
>>> 192.168.168.201:6848/26784 pipe(0x2c5fcb00 sd=231 :42835 s=2
> pgs=151539 cs=7 l=0 c=0x13c32580).fault with nothing to send, going to
> standby
> 2014-11-13 20:56:37.971391 7fd925df3700 0 -- 192.168.168.201:6812/10278
>>> 192.168.168.200:6831/62026114 pipe(0x2d93edc0 sd=21 :6812 s=2
> pgs=196755 cs=1 l=0 c=0x173c82c0).fault with nothing to send, going to
> standby
> 2014-11-13 20:56:37.980660 7fd93e267700 0 -- 192.168.168.201:6812/10278
>>> 192.168.168.200:6821/18026333 pipe(0x2a13c2c0 sd=122 :41160 s=2
> pgs=37077 cs=1 l=0 c=0x2a9ffdc0).fault with nothing to send, going to
> standby
>
>
>
> This was the last log entry for osd.12 until It has been restarted hours
> later. A very similar picture is in the logs of osd.16. Pretty much
> identical.
>
> Does anyone have any idea what is causing these problems with Giant
> release? How do I fix them as it is currently very unstable for a
> production ready release.
>
The heartbeat cutoffs are odd. Are you sure there are no firewalls in
place there or any other TCP settings?
Did you change any settings regarding the heartbeats inside Ceph or are
they all at their defaults?
Have you tried to run with debug_ms set to 10 for example. That might
show you more.
Wido
> Many thanks for your help
>
> Andrei
>
>
>
>
>
> _______________________________________________
> ceph-users mailing list
> ceph-users@xxxxxxxxxxxxxx
> http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
>
--
Wido den Hollander
42on B.V.
Phone: +31 (0)20 700 9902
Skype: contact42on
_______________________________________________
ceph-users mailing list
ceph-users@xxxxxxxxxxxxxx
http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
To: ceph-users@xxxxxxxxxxxxxx
Sent: Friday, 14 November, 2014 12:30:02 PM
Subject: Re: Giant osd problems - loss of IO
On 14-11-14 13:26, Andrei Mikhailovsky wrote:
> Hello guys,
>
> Since upgrading my cluster to Giant from the previous stable release I
> started having massive problems with client IO. I've done the upgrade 2
> weeks ago and since then the IO on my ceph cluster has been unavailable
> 3 times already.
>
> Quick info on my storage cluster - 3 mons, 2 osd servers, 17 osds, 4
> ssds for journals. All running Giant release from ceph repos on Ubuntu
> 12.04 with the latest updates.
>
> Every time I experience a very similar problem. Two out of 17 osds are
> shown as down even though the corresponding ceph-osd processes are
> running. Somehow, the down-ing of two osds brings down the IO in the
> cluster. This has not happened before upgrading to Giant. It seems that
> everytime different osds go down, but it happens on the same osd server.
> The latest one happened tonight. The ceph -s showed the following:
>
> root@arh-ibstorage1-ib:~# ceph -s
> cluster 51e9f641-372e-44ec-92a4-b9fe55cbf9fe
> health HEALTH_WARN 1001 pgs degraded; 150 pgs down; 150 pgs
> peering; 1 pgs recovering; 41 pgs recovery_wait; 1001 pgs stuck
> degraded; 150 pgs stuck inactive; 1151 pgs stuck unclean; 967 pgs stuck
> undersized; 967 pgs undersized; 203 requests are blocked > 32 sec;
> recovery 661954/5994334 objects degraded (11.043%); 10/2997167 unfound
> (0.000%); 2/17 in osds are down; noout flag(s) set
> monmap e11: 3 mons at
> {arh-cloud13-ib=192.168.168.13:6789/0,arh-ibstorage1-ib=192.168.168.200:6789/0,arh-ibstorage2-ib=192.168.168.201:6789/0},
> election epoch 66832, quorum 0,1,2
> arh-cloud13-ib,arh-ibstorage1-ib,arh-ibstorage2-ib
> mdsmap e2709: 1/1/1 up {0=arh-ibstorage2-ib=up:active}, 1 up:standby
> osdmap e64374: 17 osds: 15 up, 17 in
> flags noout
> pgmap v39540041: 4412 pgs, 17 pools, 10245 GB data, 2926 kobjects
> 20570 GB used, 26853 GB / 47423 GB avail
> 661954/5994334 objects degraded (11.043%); 10/2997167
> unfound (0.000%)
> 1 active+recovering+undersized+degraded
> 3261 active+clean
> 34 active+recovery_wait+degraded
> 959 active+undersized+degraded
> 7 active+recovery_wait+undersized+degraded
> 150 down+peering
> client io 0 B/s rd, 13805 B/s wr, 4 op/s
>
>
> "ceph osd tree" shows:
>
> root@arh-ibstorage1-ib:~# ceph osd tree
> # id weight type name up/down reweight
> -10 1.8 root uk-ssd
> -9 1.8 datacenter ldex-ssd
> -12 1.8 room ldex-dc3-ssd
> -14 1.8 row row-a-ssd
> -8 1.8 rack ldex-rack-a5-ssd
> -6 0.9 host arh-ibstorage1-ib-ssd
> -7 0.9 host arh-ibstorage2-ib-ssd
> -1 46.41 root uk
> -5 46.41 datacenter ldex
> -11 46.41 room ldex-dc3
> -13 46.41 row row-a
> -4 46.41 rack ldex-rack-a5
> -2 24.57 host arh-ibstorage1-ib
> 1 2.73 osd.1 up 1
> 3 2.73 osd.3 up 1
> 5 2.73 osd.5 up 1
> 6 2.73 osd.6 up 1
> 7 2.73 osd.7 up 1
> 8 2.73 osd.8 up 1
> 4 2.73 osd.4 up 1
> 0 2.73 osd.0 up 1
> 2 2.73 osd.2 up 1
> -3 21.84 host arh-ibstorage2-ib
> 9 2.73 osd.9 up 1
> 10 2.73 osd.10 up 1
> 11 2.73 osd.11 up 1
> 12 2.73 osd.12 down 1
> 13 2.73 osd.13 up 1
> 14 2.73 osd.14 up 1
> 15 2.73 osd.15 up 1
> 16 2.73 osd.16 down 1
>
>
> From the ceph -s it seems that some PGs were down and peering. There was
> no change in the ceph -s output for over an hour. The client IO activity
> ground to a halt and all vms became unresponsive and eventually crashed.
> The cluster was unusable until I have manually stopped osd.12 and osd.16
> and restarted them again. This has solved the problem.
>
> Previously this has happened about four days ago with osds 11 and 15 and
> it also happened about 10 days ago with different osds. So, having lost
> the storage IO three times in the last two weeks is a big deal.
>
> Looking at the ceph logs I've discovered that since performing the
> upgrade I have seen a far more messages reporting osds being down.
> Different osds are reported as being down and they come back up after
> about 5-30 seconds, perform recovery and the cluster is back to normal
> (apart from the three tiimes which actually brought the cluster io down).
>
> Furthermore, about a few minutes before osd.12 and osd.16 went down,
> I've seen 2 PGs are being deep scrubbed while osd.7 was reported down by
> 3 peers:
>
>
>
> 2014-11-13 20:55:36.608502 mon.0 192.168.168.13:6789/0 1210074 : cluster
> [INF] pgmap v39509396: 4412 pgs: 4410 active+clean, 2
> active+clean+scrubbing+deep; 10245 GB data, 20570 GB used, 26853 GB /
> 47423 GB avail; 10005 kB/s rd, 3486 kB/s wr, 310 op/s
> 2014-11-13 20:56:10.056933 mon.0 192.168.168.13:6789/0 1210209 : cluster
> [INF] pgmap v39509409: 4412 pgs: 3380 active+clean, 2
> active+clean+scrubbing+deep, 1030 active+undersized+degraded; 10245 GB
> data, 20570 GB used, 26853 GB / 47423 GB avail; 112 kB/s rd, 122 kB/s
> wr, 37 op/s; 662204/5994308 objects degraded (11.047%)
> 2014-11-13 20:56:10.073317 mon.0 192.168.168.13:6789/0 1210210 : cluster
> [INF] osd.7 192.168.168.200:6838/26321 boot
> 2014-11-13 20:56:10.073461 mon.0 192.168.168.13:6789/0 1210211 : cluster
> [INF] osd.3 192.168.168.200:6818/26170 boot
> 2014-11-13 20:56:10.074415 mon.0 192.168.168.13:6789/0 1210212 : cluster
> [INF] osdmap e64099: 17 osds: 17 up, 17 in
> 2014-11-13 20:56:10.109650 mon.0 192.168.168.13:6789/0 1210213 : cluster
> [INF] pgmap v39509410: 4412 pgs: 3380 active+clean, 2
> active+clean+scrubbing+deep, 1030 active+undersized+degraded; 10245 GB
> data, 20570 GB used, 26853 GB / 47423 GB avail; 97137 B/s rd, 220 kB/s
> wr, 36 op/s; 662204/5994308 objects degraded (11.047%)
> 2014-11-13 20:56:11.082817 mon.0 192.168.168.13:6789/0 1210214 : cluster
> [INF] osdmap e64100: 17 osds: 17 up, 17 in
> 2014-11-13 20:56:11.741135 mon.1 192.168.168.200:6789/0 520573 : cluster
> [INF] mon.arh-ibstorage1-ib calling new monitor election
> 2014-11-13 20:56:11.744641 mon.2 192.168.168.201:6789/0 521421 : cluster
> [INF] mon.arh-ibstorage2-ib calling new monitor election
> 2014-11-13 20:56:11.745988 mon.0 192.168.168.13:6789/0 1210248 : cluster
> [INF] mon.arh-cloud13-ib calling new monitor election
> 2014-11-13 20:56:11.754388 mon.0 192.168.168.13:6789/0 1210249 : cluster
> [INF] mon.arh-cloud13-ib@0 won leader election with quorum 0,1,2
> 2014-11-13 20:56:11.763975 mon.0 192.168.168.13:6789/0 1210250 : cluster
> [INF] monmap e11: 3 mons at
> {arh-cloud13-ib=192.168.168.13:6789/0,arh-ibstorage1-ib=192.168.168.200:6789/0,arh-ibstorage2-ib=192.168.168.201:6789/0}
> 2014-11-13 20:56:11.764069 mon.0 192.168.168.13:6789/0 1210251 : cluster
> [INF] pgmap v39509411: 4412 pgs: 3380 active+clean, 2
> active+clean+scrubbing+deep, 1030 active+undersized+degraded; 10245 GB
> data, 20570 GB used, 26853 GB / 47423 GB avail; 662204/5994308 objects
> degraded (11.047%)
> 2014-11-13 20:56:11.764147 mon.0 192.168.168.13:6789/0 1210252 : cluster
> [INF] mdsmap e2705: 1/1/1 up {0=arh-ibstorage2-ib=up:active}, 1 up:standby
> 2014-11-13 20:56:11.764283 mon.0 192.168.168.13:6789/0 1210253 : cluster
> [INF] osdmap e64100: 17 osds: 17 up, 17 in
> 2014-11-13 20:56:11.764859 mon.0 192.168.168.13:6789/0 1210257 : cluster
> [INF] osd.7 192.168.168.200:6838/26321 failed (3 reports from 3 peers
> after 32.005619 >= grace 25.962628)
> 2014-11-13 20:56:12.721171 mon.0 192.168.168.13:6789/0 1210262 : cluster
> [INF] osdmap e64101: 17 osds: 16 up, 17 in
> 2014-11-13 20:56:13.294162 mon.0 192.168.168.13:6789/0 1210263 : cluster
> [INF] pgmap v39509413: 4412 pgs: 3380 active+clean, 2
> active+clean+scrubbing+deep, 1030 active+undersized+degraded; 10245 GB
> data, 20570 GB used, 26853 GB / 47423 GB avail; 1150 kB/s rd, 561 kB/s
> wr, 193 op/s; 662204/5994308 objects degraded (11.047%)
> 2014-11-13 20:56:14.325109 mon.0 192.168.168.13:6789/0 1210264 : cluster
> [INF] osdmap e64102: 17 osds: 16 up, 17 in
> 2014-11-13 20:56:14.357819 mon.0 192.168.168.13:6789/0 1210265 : cluster
> [INF] pgmap v39509414: 4412 pgs: 3380 active+clean, 2
> active+clean+scrubbing+deep, 1030 active+undersized+degraded; 10245 GB
> data, 20570 GB used, 26853 GB / 47423 GB avail; 662204/5994308 objects
> degraded (11.047%)
> 2014-11-13 20:56:15.442751 mon.0 192.168.168.13:6789/0 1210266 : cluster
> [INF] pgmap v39509415: 4412 pgs: 3685 active+clean, 2
> active+clean+scrubbing+deep, 18 active+recovery_wait+degraded, 707
> active+undersized+degraded; 10245 GB data, 20570 GB used, 26853 GB /
> 47423 GB avail; 28730 kB/s rd, 1087 kB/s wr, 590 op/s; 466784/5994308
> objects degraded (7.787%); 499 MB/s, 3 keys/s, 237 objects/s recovering
> 2014-11-13 20:56:16.364658 mon.0 192.168.168.13:6789/0 1210268 : cluster
> [INF] osd.7 192.168.168.200:6838/26321 boot
> 2014-11-13 20:56:16.366310 mon.0 192.168.168.13:6789/0 1210269 : cluster
> [INF] osdmap e64103: 17 osds: 17 up, 17 in
> 2014-11-13 20:56:16.380120 mon.0 192.168.168.13:6789/0 1210270 : cluster
> [INF] pgmap v39509416: 4412 pgs: 3685 active+clean, 2
> active+clean+scrubbing+deep, 18 active+recovery_wait+degraded, 707
> active+undersized+degraded; 10245 GB data, 20570 GB used, 26853 GB /
> 47423 GB avail; 33165 kB/s rd, 1255 kB/s wr, 682 op/s; 466784/5994308
> objects degraded (7.787%); 576 MB/s, 3 keys/s, 274 objects/s recovering
> 2014-11-13 20:56:17.400859 mon.0 192.168.168.13:6789/0 1210271 : cluster
> [INF] osdmap e64104: 17 osds: 17 up, 17 in
>
>
>
> So, for the next 20 seconds it was scrubbing until ceph reported that
> osd12 and osd16 reported being down:
>
>
>
> 2014-11-13 20:56:36.712346 mon.0 192.168.168.13:6789/0 1210327 : cluster
> [INF] osd.12 192.168.168.201:6810/10278 failed (11 reports from 9 peers
> after 24.080479 >= grace 23.026948)
> 2014-11-13 20:56:36.771124 mon.0 192.168.168.13:6789/0 1210330 : cluster
> [INF] osd.15 192.168.168.201:6801/4482 failed (10 reports from 8 peers
> after 24.118287 >= grace 23.285583)
> 2014-11-13 20:56:37.920306 mon.0 192.168.168.13:6789/0 1210345 : cluster
> [INF] pgmap v39509434: 4412 pgs: 122 peering, 4085 active+clean, 2
> active+clean+scrubbing+deep, 2 active+degraded, 16
> active+recovery_wait+degraded, 185 active+undersized+degraded; 10245 GB
> data, 20570 GB used, 26853 GB / 47423 GB avail; 13943 B/s rd, 506 kB/s
> wr, 86 op/s; 118552/5994302 objects degraded (1.978%); 666 kB/s, 0
> objects/s recovering
> 2014-11-13 20:56:37.963713 mon.0 192.168.168.13:6789/0 1210346 : cluster
> [INF] osdmap e64106: 17 osds: 15 up, 17 in
> 2014-11-13 20:56:38.458852 mon.0 192.168.168.13:6789/0 1210347 : cluster
> [INF] pgmap v39509435: 4412 pgs: 377 stale+active+clean, 122 peering,
> 3708 active+clean, 119 stale+active+undersized+degraded, 2
> active+clean+scrubbing+deep, 2 active+degraded, 16
> active+recovery_wait+degraded, 66 active+undersized+degraded; 10245 GB
> data, 20570 GB used, 26853 GB / 47423 GB avail; 20510 B/s rd, 430 kB/s
> wr, 76 op/s; 118552/5994302 objects degraded (1.978%)
> 2014-11-13 20:56:39.195535 mon.0 192.168.168.13:6789/0 1210349 : cluster
> [INF] osdmap e64107: 17 osds: 15 up, 17 in
> 2014-11-13 20:56:39.231384 mon.0 192.168.168.13:6789/0 1210350 : cluster
> [INF] pgmap v39509436: 4412 pgs: 377 stale+active+clean, 122 peering,
> 3708 active+clean, 119 stale+active+undersized+degraded, 2
> active+clean+scrubbing+deep, 2 active+degraded, 16
> active+recovery_wait+degraded, 66 active+undersized+degraded; 10245 GB
> data, 20570 GB used, 26853 GB / 47423 GB avail; 118552/5994302 objects
> degraded (1.978%)
> 2014-11-13 20:56:41.883606 mon.0 192.168.168.13:6789/0 1210352 : cluster
> [INF] pgmap v39509437: 4412 pgs: 377 stale+active+clean, 122 peering,
> 3708 active+clean, 119 stale+active+undersized+degraded, 2
> active+clean+scrubbing+deep, 1 active+degraded, 17
> active+recovery_wait+degraded, 66 active+undersized+degraded; 10245 GB
> data, 20570 GB used, 26853 GB / 47423 GB avail; 14341 B/s rd, 144 kB/s
> wr, 5 op/s; 118552/5994302 objects degraded (1.978%)
> 2014-11-13 20:56:43.617030 mon.0 192.168.168.13:6789/0 1210359 : cluster
> [INF] pgmap v39509438: 4412 pgs: 377 stale+active+clean, 122 peering,
> 3708 active+clean, 119 stale+active+undersized+degraded, 2
> active+clean+scrubbing+deep, 1 active+degraded, 17
> active+recovery_wait+degraded, 66 active+undersized+degraded; 10245 GB
> data, 20570 GB used, 26853 GB / 47423 GB avail; 718 kB/s rd, 215 kB/s
> wr, 46 op/s; 118552/5994302 objects degraded (1.978%)
> 2014-11-13 20:56:45.408475 mon.0 192.168.168.13:6789/0 1210365 : cluster
> [INF] pgmap v39509439: 4412 pgs: 46 peering, 3218 active+clean, 1
> active+clean+scrubbing+deep, 1 active+degraded, 12
> active+recovery_wait+degraded, 1007 active+undersized+degraded, 1
> active+recovery_wait+undersized+degraded, 126 down+peering; 10245 GB
> data, 20570 GB used, 26853 GB / 47423 GB avail; 1853 kB/s wr, 300 op/s;
> 696740/5994304 objects degraded (11.623%); 8/2997152 unfound (0.000%)
> 2014-11-13 20:56:46.517294 mon.0 192.168.168.13:6789/0 1210366 : cluster
> [INF] pgmap v39509440: 4412 pgs: 46 peering, 3222 active+clean, 1
> active+clean+scrubbing+deep, 9 active+recovery_wait+degraded, 1007
> active+undersized+degraded, 1 active+recovery_wait+undersized+degraded,
> 126 down+peering; 10245 GB data, 20570 GB used, 26853 GB / 47423 GB
> avail; 2242 kB/s wr, 358 op/s; 696737/5994304 objects degraded
> (11.623%); 8/2997152 unfound (0.000%)
>
>
>
> From this point on the client IO went down from an average of about 500
> op/s to 10-20 op/s. All vms started having hang tasks shortly after that
> and eventually most of them crashed. A few more seconds passed, the
> status changed to:
>
> 2014-11-13 20:59:19.857378 mon.0 192.168.168.13:6789/0 1210590 : cluster
> [INF] pgmap v39509547: 4412 pgs: 1
> active+recovering+undersized+degraded, 3268 active+clean, 19
> active+degraded, 7 active+recovery_wait+degraded, 959
> active+undersized+degraded, 7 active+recovery_wait+undersized+degraded,
> 150 down+peering, 1 active+recovering+degraded; 10245 GB data, 20570 GB
> used, 26853 GB / 47423 GB avail; 0 B/s rd, 546 kB/s wr, 103 op/s;
> 661943/5994302 objects degraded (11.043%); 10/2997151 unfound (0.000%);
> 53620 kB/s, 1 keys/s, 13 objects/s recovering
>
>
> And pretty much stayed like that for over an hour without changing much.
> The IO was still unavailable.
>
> Looking at the logs of the osds that were shown down, I don't really see
> much apart from some slow requests prior to the osds being reported down:
>
>
> 2014-11-13 20:56:10.315696 7fd9645be700 0 log_channel(default) log
> [WRN] : slow request 31.043640 seconds old, received at 2014-11-13
> 20:55:39.271942: osd_op(client.46407343.0
> :3839273 rbd_data.1f0a392ae8944a.0000000000000621 [set-alloc-hint
> object_size 4194304 write_size 4194304,write 3526656~4096] 5.9fe0f0f2
> ack+ondisk+write e64096) currently waiti
> ng for subops from 1
> 2014-11-13 20:56:10.467380 7fd941a75700 -1 osd.12 64099 heartbeat_check:
> no reply from osd.4 since back 2014-11-13 20:55:35.958627 front
> 2014-11-13 20:55:35.958627 (cutoff 2014
> -11-13 20:55:50.467379)
> 2014-11-13 20:56:10.467389 7fd941a75700 -1 osd.12 64099 heartbeat_check:
> no reply from osd.5 since back 2014-11-13 20:55:38.259184 front
> 2014-11-13 20:55:35.958627 (cutoff 2014
> -11-13 20:55:50.467379)
> 2014-11-13 20:56:10.467409 7fd941a75700 -1 osd.12 64099 heartbeat_check:
> no reply from osd.6 since back 2014-11-13 20:55:35.958627 front
> 2014-11-13 20:55:35.958627 (cutoff 2014
> -11-13 20:55:50.467379)
> 2014-11-13 20:56:10.467427 7fd941a75700 -1 osd.12 64099 heartbeat_check:
> no reply from osd.8 since back 2014-11-13 20:55:35.958627 front
> 2014-11-13 20:55:35.958627 (cutoff 2014
> -11-13 20:55:50.467379)
> 2014-11-13 20:56:10.967963 7fd941a75700 -1 osd.12 64099 heartbeat_check:
> no reply from osd.4 since back 2014-11-13 20:55:35.958627 front
> 2014-11-13 20:55:35.958627 (cutoff 2014
> -11-13 20:55:50.967962)
> 2014-11-13 20:56:10.967971 7fd941a75700 -1 osd.12 64099 heartbeat_check:
> no reply from osd.5 since back 2014-11-13 20:55:38.259184 front
> 2014-11-13 20:55:35.958627 (cutoff 2014
> -11-13 20:55:50.967962)
> 2014-11-13 20:56:10.967978 7fd941a75700 -1 osd.12 64099 heartbeat_check:
> no reply from osd.6 since back 2014-11-13 20:55:35.958627 front
> 2014-11-13 20:55:35.958627 (cutoff 2014
> -11-13 20:55:50.967962)
> 2014-11-13 20:56:10.967984 7fd941a75700 -1 osd.12 64099 heartbeat_check:
> no reply from osd.8 since back 2014-11-13 20:55:35.958627 front
> 2014-11-13 20:55:35.958627 (cutoff 2014
> -11-13 20:55:50.967962)
> 2014-11-13 20:56:11.317046 7fd9645be700 -1 osd.12 64100 heartbeat_check:
> no reply from osd.4 since back 2014-11-13 20:55:35.958627 front
> 2014-11-13 20:55:35.958627 (cutoff 2014-11-13 20:55:51.317043)
> 2014-11-13 20:56:11.317057 7fd9645be700 -1 osd.12 64100 heartbeat_check:
> no reply from osd.5 since back 2014-11-13 20:55:38.259184 front
> 2014-11-13 20:55:35.958627 (cutoff 2014-11-13 20:55:51.317043)
> 2014-11-13 20:56:11.317064 7fd9645be700 -1 osd.12 64100 heartbeat_check:
> no reply from osd.6 since back 2014-11-13 20:55:35.958627 front
> 2014-11-13 20:56:10.967590 (cutoff 2014-11-13 20:55:51.317043)
> 2014-11-13 20:56:11.317070 7fd9645be700 -1 osd.12 64100 heartbeat_check:
> no reply from osd.8 since back 2014-11-13 20:55:38.259184 front
> 2014-11-13 20:55:35.958627 (cutoff 2014-11-13 20:55:51.317043)
> 2014-11-13 20:56:11.317167 7fd9645be700 0 log_channel(default) log
> [WRN] : 17 slow requests, 7 included below; oldest blocked for >
> 32.285501 secs
> 2014-11-13 20:56:11.317173 7fd9645be700 0 log_channel(default) log
> [WRN] : slow request 32.285501 seconds old, received at 2014-11-13
> 20:55:39.031582: osd_op(client.46379104.0:182402
> rbd_data.2c26ec1333ab105.000000000000015a [stat,set-alloc-hint
> object_size 4194304 write_size 4194304,write 3956736~1024] 5.e9450c8d
> ack+ondisk+write e64096) currently waiting for subops from 4
> 2014-11-13 20:56:11.317179 7fd9645be700 0 log_channel(default) log
> [WRN] : slow request 32.047721 seconds old, received at 2014-11-13
> 20:55:39.269362: osd_op(client.46407343.0:3839258
> rbd_data.1f0a392ae8944a.0000000000000621 [set-alloc-hint object_size
> 4194304 write_size 4194304,write 1568768~8192] 5.9fe0f0f2
> ack+ondisk+write e64096) currently waiting for subops from 1
> 2014-11-13 20:56:11.317183 7fd9645be700 0 log_channel(default) log
> [WRN] : slow request 32.047396 seconds old, received at 2014-11-13
> 20:55:39.269687: osd_op(client.46407343.0:3839259
> rbd_data.1f0a392ae8944a.0000000000000621 [set-alloc-hint object_size
> 4194304 write_size 4194304,write 1773568~4096] 5.9fe0f0f2
> ack+ondisk+write e64096) currently waiting for subops from 1
> 2014-11-13 20:56:11.317187 7fd9645be700 0 log_channel(default) log
> [WRN] : slow request 32.047229 seconds old, received at 2014-11-13
> 20:55:39.269854: osd_op(client.46407343.0:3839260
> rbd_data.1f0a392ae8944a.0000000000000621 [set-alloc-hint object_size
> 4194304 write_size 4194304,write 1921024~4096] 5.9fe0f0f2
> ack+ondisk+write e64096) currently waiting for subops from 1
> 2014-11-13 20:56:11.317232 7fd9645be700 0 log_channel(default) log
> [WRN] : slow request 32.047069 seconds old, received at 2014-11-13
> 20:55:39.270014: osd_op(client.46407343.0:3839261
> rbd_data.1f0a392ae8944a.0000000000000621 [set-alloc-hint object_size
> 4194304 write_size 4194304,write 1949696~4096] 5.9fe0f0f2
> ack+ondisk+write e64096) currently waiting for subops from 1
> 2014-11-13 20:56:37.954923 7fd92c055700 0 -- 192.168.168.201:6812/10278
>>> 192.168.168.200:6820/56026102 pipe(0x2b369b00 sd=381 :6812 s=2
> pgs=205156 cs=1 l=0 c=0x1b29d420).fault with nothing to send, going to
> standby
> 2014-11-13 20:56:37.955547 7fd92bb50700 0 -- 192.168.168.201:6812/10278
>>> 192.168.168.200:6810/72026170 pipe(0x2ad35580 sd=238 :6812 s=2
> pgs=141844 cs=1 l=0 c=0xf33c420).fault with nothing to send, going to
> standby
> 2014-11-13 20:56:37.956392 7fd935deb700 0 -- 192.168.168.201:6812/10278
>>> 192.168.168.200:6807/70026130 pipe(0x2e2268c0 sd=408 :6812 s=2
> pgs=278536 cs=1 l=0 c=0x142f7420).fault with nothing to send, going to
> standby
> 2014-11-13 20:56:37.956695 7fd93e86d700 0 -- 192.168.168.201:6812/10278
>>> 192.168.168.200:6849/1026289 pipe(0x29b4c840 sd=129 :41140 s=2
> pgs=591 cs=1 l=0 c=0x29b58b00).fault with nothing to send, going to standby
> 2014-11-13 20:56:37.958245 7fd93e56a700 0 -- 192.168.168.201:6812/10278
>>> 192.168.168.200:6803/1026306 pipe(0x29bb7600 sd=154 :43005 s=2
> pgs=117 cs=1 l=0 c=0x29be4840).fault with nothing to send, going to standby
> 2014-11-13 20:56:37.969506 7fd93e368700 0 -- 192.168.168.201:6812/10278
>>> 192.168.168.200:6824/26238 pipe(0x29c98600 sd=146 :60953 s=2 pgs=148
> cs=1 l=0 c=0x29cd0840).fault with nothing to send, going to standby
> 2014-11-13 20:56:37.969620 7fd92a439700 0 -- 192.168.168.201:6812/10278
>>> 192.168.168.201:6848/26784 pipe(0x2c5fcb00 sd=231 :42835 s=2
> pgs=151539 cs=7 l=0 c=0x13c32580).fault with nothing to send, going to
> standby
> 2014-11-13 20:56:37.971391 7fd925df3700 0 -- 192.168.168.201:6812/10278
>>> 192.168.168.200:6831/62026114 pipe(0x2d93edc0 sd=21 :6812 s=2
> pgs=196755 cs=1 l=0 c=0x173c82c0).fault with nothing to send, going to
> standby
> 2014-11-13 20:56:37.980660 7fd93e267700 0 -- 192.168.168.201:6812/10278
>>> 192.168.168.200:6821/18026333 pipe(0x2a13c2c0 sd=122 :41160 s=2
> pgs=37077 cs=1 l=0 c=0x2a9ffdc0).fault with nothing to send, going to
> standby
>
>
>
> This was the last log entry for osd.12 until It has been restarted hours
> later. A very similar picture is in the logs of osd.16. Pretty much
> identical.
>
> Does anyone have any idea what is causing these problems with Giant
> release? How do I fix them as it is currently very unstable for a
> production ready release.
>
The heartbeat cutoffs are odd. Are you sure there are no firewalls in
place there or any other TCP settings?
Did you change any settings regarding the heartbeats inside Ceph or are
they all at their defaults?
Have you tried to run with debug_ms set to 10 for example. That might
show you more.
Wido
> Many thanks for your help
>
> Andrei
>
>
>
>
>
> _______________________________________________
> ceph-users mailing list
> ceph-users@xxxxxxxxxxxxxx
> http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
>
--
Wido den Hollander
42on B.V.
Phone: +31 (0)20 700 9902
Skype: contact42on
_______________________________________________
ceph-users mailing list
ceph-users@xxxxxxxxxxxxxx
http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
_______________________________________________ ceph-users mailing list ceph-users@xxxxxxxxxxxxxx http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
