OSD reboot loop after running out of memory
Hi, We recently upgraded a cluster from 15.2.1 to 15.2.5. About two days later, one of the server ran out of memory for unknown reasons (normally the machine uses about 60 out of 128 GB). Since then, some OSDs on that machine get caught in an endless restart loop. Logs will just mention system seeing the daemon fail and then restarting it. Since the out of memory incident, we’ve have 3 OSDs fail this way at separate times. We resorted to wiping the affected OSD and re-adding it to the cluster, but it seems as soon as all PGs have moved to the OSD, the next one fails. This is also keeping us from re-deploying RGW, which was affected by the same out of memory incident, since cephadm runs a check and won’t deploy the service unless the cluster is in HEALTH_OK status. Any help would be greatly appreciated. Thanks, Stefan
Just had another look at the logs and this is what I did notice after the affected OSD starts up. Loads of entries of this sort: Dec 12 21:38:40 ceph-tpa-server1 bash[780507]: debug 2020-12-13T02:38:40.851+0000 7fafd32c7700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fafb721f700' had timed out after 15 Then a few pages of this: Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9249> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9248> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9247> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9246> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9245> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13026 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9244> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9243> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9242> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9241> 2020-12-13T02:35:44.022+0000 7fafb721f700 1 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9240> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9239> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9238> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9237> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9236> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9235> 2020-12-13T02:35:44.022+0000 7fafb521b700 1 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 And this is where it crashes: Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9232> 2020-12-13T02:35:44.022+0000 7fafd02c1700 0 log_channel(cluster) log [DBG] : purged_snaps scrub starts Dec 12 21:38:57 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Main process exited, code=exited, status=1/FAILURE Dec 12 21:38:59 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Failed with result 'exit-code'. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Service hold-off time over, scheduling restart. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Scheduled restart job, restart counter is at 1. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Stopped Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Starting Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142... Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Started Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142. Hope that helps… Thanks, Stefan From: Stefan Wild <swild@tiltworks.com> Date: Saturday, December 12, 2020 at 9:35 PM To: "ceph-users@ceph.io" <ceph-users@ceph.io> Subject: OSD reboot loop after running out of memory Hi, We recently upgraded a cluster from 15.2.1 to 15.2.5. About two days later, one of the server ran out of memory for unknown reasons (normally the machine uses about 60 out of 128 GB). Since then, some OSDs on that machine get caught in an endless restart loop. Logs will just mention system seeing the daemon fail and then restarting it. Since the out of memory incident, we’ve have 3 OSDs fail this way at separate times. We resorted to wiping the affected OSD and re-adding it to the cluster, but it seems as soon as all PGs have moved to the OSD, the next one fails. This is also keeping us from re-deploying RGW, which was affected by the same out of memory incident, since cephadm runs a check and won’t deploy the service unless the cluster is in HEALTH_OK status. Any help would be greatly appreciated. Thanks, Stefan
Got a trace of the osd process, shortly after ceph status -w announced boot for the osd: strace: Process 784735 attached futex(0x5587c3e22fc8, FUTEX_WAIT_PRIVATE, 0, NULL) = ? +++ exited with 1 +++ It was stuck at that one call for several minutes before exiting. From: Stefan Wild <swild@tiltworks.com> Date: Saturday, December 12, 2020 at 9:44 PM To: "ceph-users@ceph.io" <ceph-users@ceph.io> Subject: Re: OSD reboot loop after running out of memory Just had another look at the logs and this is what I did notice after the affected OSD starts up. Loads of entries of this sort: Dec 12 21:38:40 ceph-tpa-server1 bash[780507]: debug 2020-12-13T02:38:40.851+0000 7fafd32c7700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fafb721f700' had timed out after 15 Then a few pages of this: Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9249> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9248> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9247> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9246> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9245> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13026 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9244> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9243> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9242> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9241> 2020-12-13T02:35:44.022+0000 7fafb721f700 1 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9240> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9239> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9238> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9237> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9236> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9235> 2020-12-13T02:35:44.022+0000 7fafb521b700 1 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 And this is where it crashes: Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9232> 2020-12-13T02:35:44.022+0000 7fafd02c1700 0 log_channel(cluster) log [DBG] : purged_snaps scrub starts Dec 12 21:38:57 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Main process exited, code=exited, status=1/FAILURE Dec 12 21:38:59 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Failed with result 'exit-code'. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Service hold-off time over, scheduling restart. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Scheduled restart job, restart counter is at 1. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Stopped Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Starting Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142... Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Started Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142. Hope that helps… Thanks, Stefan From: Stefan Wild <swild@tiltworks.com> Date: Saturday, December 12, 2020 at 9:35 PM To: "ceph-users@ceph.io" <ceph-users@ceph.io> Subject: OSD reboot loop after running out of memory Hi, We recently upgraded a cluster from 15.2.1 to 15.2.5. About two days later, one of the server ran out of memory for unknown reasons (normally the machine uses about 60 out of 128 GB). Since then, some OSDs on that machine get caught in an endless restart loop. Logs will just mention system seeing the daemon fail and then restarting it. Since the out of memory incident, we’ve have 3 OSDs fail this way at separate times. We resorted to wiping the affected OSD and re-adding it to the cluster, but it seems as soon as all PGs have moved to the OSD, the next one fails. This is also keeping us from re-deploying RGW, which was affected by the same out of memory incident, since cephadm runs a check and won’t deploy the service unless the cluster is in HEALTH_OK status. Any help would be greatly appreciated. Thanks, Stefan
Hi Stefan, could you please share OSD startup log from /var/log/ceph? Thanks, Igor On 12/13/2020 5:44 AM, Stefan Wild wrote:
Just had another look at the logs and this is what I did notice after the affected OSD starts up.
Loads of entries of this sort:
Dec 12 21:38:40 ceph-tpa-server1 bash[780507]: debug 2020-12-13T02:38:40.851+0000 7fafd32c7700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fafb721f700' had timed out after 15
Then a few pages of this:
Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9249> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9248> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9247> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9246> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9245> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13026 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9244> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9243> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9242> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9241> 2020-12-13T02:35:44.022+0000 7fafb721f700 1 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9240> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9239> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9238> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9237> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9236> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9235> 2020-12-13T02:35:44.022+0000 7fafb521b700 1 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916
And this is where it crashes:
Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9232> 2020-12-13T02:35:44.022+0000 7fafd02c1700 0 log_channel(cluster) log [DBG] : purged_snaps scrub starts Dec 12 21:38:57 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Main process exited, code=exited, status=1/FAILURE Dec 12 21:38:59 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Failed with result 'exit-code'. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Service hold-off time over, scheduling restart. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Scheduled restart job, restart counter is at 1. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Stopped Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Starting Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142... Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Started Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142.
Hope that helps…
Thanks, Stefan
From: Stefan Wild <swild@tiltworks.com> Date: Saturday, December 12, 2020 at 9:35 PM To: "ceph-users@ceph.io" <ceph-users@ceph.io> Subject: OSD reboot loop after running out of memory
Hi,
We recently upgraded a cluster from 15.2.1 to 15.2.5. About two days later, one of the server ran out of memory for unknown reasons (normally the machine uses about 60 out of 128 GB). Since then, some OSDs on that machine get caught in an endless restart loop. Logs will just mention system seeing the daemon fail and then restarting it. Since the out of memory incident, we’ve have 3 OSDs fail this way at separate times. We resorted to wiping the affected OSD and re-adding it to the cluster, but it seems as soon as all PGs have moved to the OSD, the next one fails.
This is also keeping us from re-deploying RGW, which was affected by the same out of memory incident, since cephadm runs a check and won’t deploy the service unless the cluster is in HEALTH_OK status.
Any help would be greatly appreciated.
Thanks, Stefan
_______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
Hi Igor, Full osd logs from startup to failed exit: https://tiltworks.com/osd.1.log In other news, can I expect osd.10 to go down next? Dec 13 07:40:14 ceph-tpa-server1 bash[1825010]: debug 2020-12-13T12:40:14.823+0000 7ff37c2e1700 -1 osd.7 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.310905+0000 front 2020-12-13T12:39:43.311164+0000 (oldest deadline 2020-12-13T12:40:06.810981+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:15.055+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[2060428]: debug 2020-12-13T12:40:15.155+0000 7fb247eaf700 -1 osd.8 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.181904+0000 front 2020-12-13T12:39:42.181856+0000 (oldest deadline 2020-12-13T12:40:06.281648+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.171+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.2 is reporting failure:0 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.171+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.2 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:15.176057+0000 mon.ceph-tpa-server1 (mon.0) 1172513 : cluster [DBG] osd.10 failure report canceled by osd.2 Dec 13 07:40:15 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:15.295+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.423+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.6 is reporting failure:0 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.423+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.6 Dec 13 07:40:15 ceph-tpa-server1 bash[1824845]: debug 2020-12-13T12:40:15.447+0000 7f85048db700 -1 osd.3 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:39.770822+0000 front 2020-12-13T12:39:39.770700+0000 (oldest deadline 2020-12-13T12:40:05.070662+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[231499]: debug 2020-12-13T12:40:15.687+0000 7fa8e1800700 -1 osd.4 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:39.977106+0000 front 2020-12-13T12:39:39.977176+0000 (oldest deadline 2020-12-13T12:40:04.677320+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1825010]: debug 2020-12-13T12:40:15.799+0000 7ff37c2e1700 -1 osd.7 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.310905+0000 front 2020-12-13T12:39:43.311164+0000 (oldest deadline 2020-12-13T12:40:06.810981+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:16.019+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.179+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.4 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.179+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.4 Dec 13 07:40:16 ceph-tpa-server1 bash[2060428]: debug 2020-12-13T12:40:16.191+0000 7fb247eaf700 -1 osd.8 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.181904+0000 front 2020-12-13T12:39:42.181856+0000 (oldest deadline 2020-12-13T12:40:06.281648+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:15.429755+0000 mon.ceph-tpa-server1 (mon.0) 1172514 : cluster [DBG] osd.10 failure report canceled by osd.6 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.183521+0000 mon.ceph-tpa-server1 (mon.0) 1172515 : cluster [DBG] osd.10 failure report canceled by osd.4 Dec 13 07:40:16 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:16.303+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.371+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.3 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.371+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.3 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.611+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.7 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.611+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.7 Dec 13 07:40:16 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:16.979+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:17 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:17.271+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.378213+0000 mon.ceph-tpa-server1 (mon.0) 1172516 : cluster [DBG] osd.10 failure report canceled by osd.3 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.616685+0000 mon.ceph-tpa-server1 (mon.0) 1172517 : cluster [DBG] osd.10 failure report canceled by osd.7 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.727+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.0 is reporting failure:0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.727+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.839+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.5 is reporting failure:0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.839+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.5 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:17.733200+0000 mon.ceph-tpa-server1 (mon.0) 1172518 : cluster [DBG] osd.10 failure report canceled by osd.0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:17.843775+0000 mon.ceph-tpa-server1 (mon.0) 1172519 : cluster [DBG] osd.10 failure report canceled by osd.5 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.575+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.11 is reporting failure:0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.575+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.11 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.783+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.8 is reporting failure:0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.783+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.8 Dec 13 07:40:19 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:18.578914+0000 mon.ceph-tpa-server1 (mon.0) 1172520 : cluster [DBG] osd.10 failure report canceled by osd.11 Dec 13 07:40:19 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:18.789301+0000 mon.ceph-tpa-server1 (mon.0) 1172521 : cluster [DBG] osd.10 failure report canceled by osd.8 Thanks, Stefan On 12/13/20, 2:18 AM, "Igor Fedotov" <ifedotov@suse.de> wrote: Hi Stefan, could you please share OSD startup log from /var/log/ceph? Thanks, Igor On 12/13/2020 5:44 AM, Stefan Wild wrote: > Just had another look at the logs and this is what I did notice after the affected OSD starts up. > > Loads of entries of this sort: > > Dec 12 21:38:40 ceph-tpa-server1 bash[780507]: debug 2020-12-13T02:38:40.851+0000 7fafd32c7700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fafb721f700' had timed out after 15 > > Then a few pages of this: > > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9249> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9248> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9247> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9246> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9245> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13026 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9244> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9243> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9242> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9241> 2020-12-13T02:35:44.022+0000 7fafb721f700 1 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9240> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9239> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9238> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9237> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9236> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9235> 2020-12-13T02:35:44.022+0000 7fafb521b700 1 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > > And this is where it crashes: > > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9232> 2020-12-13T02:35:44.022+0000 7fafd02c1700 0 log_channel(cluster) log [DBG] : purged_snaps scrub starts > Dec 12 21:38:57 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Main process exited, code=exited, status=1/FAILURE > Dec 12 21:38:59 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Failed with result 'exit-code'. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Service hold-off time over, scheduling restart. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Scheduled restart job, restart counter is at 1. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Stopped Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Starting Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142... > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Started Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142. > > Hope that helps… > > > Thanks, > Stefan > > > From: Stefan Wild <swild@tiltworks.com> > Date: Saturday, December 12, 2020 at 9:35 PM > To: "ceph-users@ceph.io" <ceph-users@ceph.io> > Subject: OSD reboot loop after running out of memory > > Hi, > > We recently upgraded a cluster from 15.2.1 to 15.2.5. About two days later, one of the server ran out of memory for unknown reasons (normally the machine uses about 60 out of 128 GB). Since then, some OSDs on that machine get caught in an endless restart loop. Logs will just mention system seeing the daemon fail and then restarting it. Since the out of memory incident, we’ve have 3 OSDs fail this way at separate times. We resorted to wiping the affected OSD and re-adding it to the cluster, but it seems as soon as all PGs have moved to the OSD, the next one fails. > > This is also keeping us from re-deploying RGW, which was affected by the same out of memory incident, since cephadm runs a check and won’t deploy the service unless the cluster is in HEALTH_OK status. > > Any help would be greatly appreciated. > > Thanks, > Stefan > > _______________________________________________ > ceph-users mailing list -- ceph-users@ceph.io > To unsubscribe send an email to ceph-users-leave@ceph.io _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
Hi Stefan, we had been seeing OSDs OOMing on 14.2.13, but on a larger scale. In our case we hit a some bugs with pg_log memory growth and buffer_anon memory growth. Can you check what's taking up the memory on the OSD with the following command? ceph daemon osd.123 dump_mempools Cheers, Kalle ----- Original Message -----
From: "Stefan Wild" <swild@tiltworks.com> To: "Igor Fedotov" <ifedotov@suse.de>, "ceph-users" <ceph-users@ceph.io> Sent: Sunday, 13 December, 2020 14:46:44 Subject: [ceph-users] Re: OSD reboot loop after running out of memory
Hi Igor,
Full osd logs from startup to failed exit: https://tiltworks.com/osd.1.log
In other news, can I expect osd.10 to go down next?
Dec 13 07:40:14 ceph-tpa-server1 bash[1825010]: debug 2020-12-13T12:40:14.823+0000 7ff37c2e1700 -1 osd.7 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.310905+0000 front 2020-12-13T12:39:43.311164+0000 (oldest deadline 2020-12-13T12:40:06.810981+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:15.055+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[2060428]: debug 2020-12-13T12:40:15.155+0000 7fb247eaf700 -1 osd.8 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.181904+0000 front 2020-12-13T12:39:42.181856+0000 (oldest deadline 2020-12-13T12:40:06.281648+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.171+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.2 is reporting failure:0 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.171+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.2 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:15.176057+0000 mon.ceph-tpa-server1 (mon.0) 1172513 : cluster [DBG] osd.10 failure report canceled by osd.2 Dec 13 07:40:15 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:15.295+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.423+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.6 is reporting failure:0 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.423+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.6 Dec 13 07:40:15 ceph-tpa-server1 bash[1824845]: debug 2020-12-13T12:40:15.447+0000 7f85048db700 -1 osd.3 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:39.770822+0000 front 2020-12-13T12:39:39.770700+0000 (oldest deadline 2020-12-13T12:40:05.070662+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[231499]: debug 2020-12-13T12:40:15.687+0000 7fa8e1800700 -1 osd.4 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:39.977106+0000 front 2020-12-13T12:39:39.977176+0000 (oldest deadline 2020-12-13T12:40:04.677320+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1825010]: debug 2020-12-13T12:40:15.799+0000 7ff37c2e1700 -1 osd.7 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.310905+0000 front 2020-12-13T12:39:43.311164+0000 (oldest deadline 2020-12-13T12:40:06.810981+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:16.019+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.179+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.4 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.179+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.4 Dec 13 07:40:16 ceph-tpa-server1 bash[2060428]: debug 2020-12-13T12:40:16.191+0000 7fb247eaf700 -1 osd.8 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.181904+0000 front 2020-12-13T12:39:42.181856+0000 (oldest deadline 2020-12-13T12:40:06.281648+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:15.429755+0000 mon.ceph-tpa-server1 (mon.0) 1172514 : cluster [DBG] osd.10 failure report canceled by osd.6 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.183521+0000 mon.ceph-tpa-server1 (mon.0) 1172515 : cluster [DBG] osd.10 failure report canceled by osd.4 Dec 13 07:40:16 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:16.303+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.371+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.3 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.371+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.3 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.611+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.7 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.611+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.7 Dec 13 07:40:16 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:16.979+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:17 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:17.271+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.378213+0000 mon.ceph-tpa-server1 (mon.0) 1172516 : cluster [DBG] osd.10 failure report canceled by osd.3 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.616685+0000 mon.ceph-tpa-server1 (mon.0) 1172517 : cluster [DBG] osd.10 failure report canceled by osd.7 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.727+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.0 is reporting failure:0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.727+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.839+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.5 is reporting failure:0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.839+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.5 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:17.733200+0000 mon.ceph-tpa-server1 (mon.0) 1172518 : cluster [DBG] osd.10 failure report canceled by osd.0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:17.843775+0000 mon.ceph-tpa-server1 (mon.0) 1172519 : cluster [DBG] osd.10 failure report canceled by osd.5 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.575+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.11 is reporting failure:0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.575+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.11 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.783+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.8 is reporting failure:0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.783+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.8 Dec 13 07:40:19 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:18.578914+0000 mon.ceph-tpa-server1 (mon.0) 1172520 : cluster [DBG] osd.10 failure report canceled by osd.11 Dec 13 07:40:19 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:18.789301+0000 mon.ceph-tpa-server1 (mon.0) 1172521 : cluster [DBG] osd.10 failure report canceled by osd.8
Thanks, Stefan
On 12/13/20, 2:18 AM, "Igor Fedotov" <ifedotov@suse.de> wrote:
Hi Stefan,
could you please share OSD startup log from /var/log/ceph?
Thanks,
Igor
On 12/13/2020 5:44 AM, Stefan Wild wrote:
Just had another look at the logs and this is what I did notice after the affected OSD starts up.
Loads of entries of this sort:
Dec 12 21:38:40 ceph-tpa-server1 bash[780507]: debug 2020-12-13T02:38:40.851+0000 7fafd32c7700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fafb721f700' had timed out after 15
Then a few pages of this:
Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9249> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9248> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9247> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9246> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9245> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13026 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9244> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9243> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9242> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9241> 2020-12-13T02:35:44.022+0000 7fafb721f700 1 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9240> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9239> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9238> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9237> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9236> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9235> 2020-12-13T02:35:44.022+0000 7fafb521b700 1 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916
And this is where it crashes:
Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9232> 2020-12-13T02:35:44.022+0000 7fafd02c1700 0 log_channel(cluster) log [DBG] : purged_snaps scrub starts Dec 12 21:38:57 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Main process exited, code=exited, status=1/FAILURE Dec 12 21:38:59 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Failed with result 'exit-code'. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Service hold-off time over, scheduling restart. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Scheduled restart job, restart counter is at 1. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Stopped Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Starting Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142... Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Started Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142.
Hope that helps…
Thanks, Stefan
From: Stefan Wild <swild@tiltworks.com> Date: Saturday, December 12, 2020 at 9:35 PM To: "ceph-users@ceph.io" <ceph-users@ceph.io> Subject: OSD reboot loop after running out of memory
Hi,
We recently upgraded a cluster from 15.2.1 to 15.2.5. About two days later, one of the server ran out of memory for unknown reasons (normally the machine uses about 60 out of 128 GB). Since then, some OSDs on that machine get caught in an endless restart loop. Logs will just mention system seeing the daemon fail and then restarting it. Since the out of memory incident, we’ve have 3 OSDs fail this way at separate times. We resorted to wiping the affected OSD and re-adding it to the cluster, but it seems as soon as all PGs have moved to the OSD, the next one fails.
This is also keeping us from re-deploying RGW, which was affected by the same out of memory incident, since cephadm runs a check and won’t deploy the service unless the cluster is in HEALTH_OK status.
Any help would be greatly appreciated.
Thanks, Stefan
_______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
_______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
Hello, Kalle, Your comments abount some bugs with pg_log memory and buffer_anon memory growth worry me a lot, as i am planning to build a cluster with the latest Nautilous version. Could you please comment on, how to safely deal with these bugs or to avoid, if indeed they occur? thanks a lot, samuel huxiaoyu@horebdata.cn From: Kalle Happonen Date: 2020-12-14 08:28 To: Stefan Wild CC: ceph-users Subject: [ceph-users] Re: OSD reboot loop after running out of memory Hi Stefan, we had been seeing OSDs OOMing on 14.2.13, but on a larger scale. In our case we hit a some bugs with pg_log memory growth and buffer_anon memory growth. Can you check what's taking up the memory on the OSD with the following command? ceph daemon osd.123 dump_mempools Cheers, Kalle ----- Original Message -----
From: "Stefan Wild" <swild@tiltworks.com> To: "Igor Fedotov" <ifedotov@suse.de>, "ceph-users" <ceph-users@ceph.io> Sent: Sunday, 13 December, 2020 14:46:44 Subject: [ceph-users] Re: OSD reboot loop after running out of memory
Hi Igor,
Full osd logs from startup to failed exit: https://tiltworks.com/osd.1.log
In other news, can I expect osd.10 to go down next?
Dec 13 07:40:14 ceph-tpa-server1 bash[1825010]: debug 2020-12-13T12:40:14.823+0000 7ff37c2e1700 -1 osd.7 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.310905+0000 front 2020-12-13T12:39:43.311164+0000 (oldest deadline 2020-12-13T12:40:06.810981+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:15.055+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[2060428]: debug 2020-12-13T12:40:15.155+0000 7fb247eaf700 -1 osd.8 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.181904+0000 front 2020-12-13T12:39:42.181856+0000 (oldest deadline 2020-12-13T12:40:06.281648+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.171+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.2 is reporting failure:0 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.171+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.2 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:15.176057+0000 mon.ceph-tpa-server1 (mon.0) 1172513 : cluster [DBG] osd.10 failure report canceled by osd.2 Dec 13 07:40:15 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:15.295+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.423+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.6 is reporting failure:0 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.423+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.6 Dec 13 07:40:15 ceph-tpa-server1 bash[1824845]: debug 2020-12-13T12:40:15.447+0000 7f85048db700 -1 osd.3 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:39.770822+0000 front 2020-12-13T12:39:39.770700+0000 (oldest deadline 2020-12-13T12:40:05.070662+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[231499]: debug 2020-12-13T12:40:15.687+0000 7fa8e1800700 -1 osd.4 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:39.977106+0000 front 2020-12-13T12:39:39.977176+0000 (oldest deadline 2020-12-13T12:40:04.677320+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1825010]: debug 2020-12-13T12:40:15.799+0000 7ff37c2e1700 -1 osd.7 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.310905+0000 front 2020-12-13T12:39:43.311164+0000 (oldest deadline 2020-12-13T12:40:06.810981+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:16.019+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.179+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.4 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.179+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.4 Dec 13 07:40:16 ceph-tpa-server1 bash[2060428]: debug 2020-12-13T12:40:16.191+0000 7fb247eaf700 -1 osd.8 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.181904+0000 front 2020-12-13T12:39:42.181856+0000 (oldest deadline 2020-12-13T12:40:06.281648+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:15.429755+0000 mon.ceph-tpa-server1 (mon.0) 1172514 : cluster [DBG] osd.10 failure report canceled by osd.6 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.183521+0000 mon.ceph-tpa-server1 (mon.0) 1172515 : cluster [DBG] osd.10 failure report canceled by osd.4 Dec 13 07:40:16 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:16.303+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.371+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.3 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.371+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.3 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.611+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.7 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.611+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.7 Dec 13 07:40:16 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:16.979+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:17 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:17.271+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.378213+0000 mon.ceph-tpa-server1 (mon.0) 1172516 : cluster [DBG] osd.10 failure report canceled by osd.3 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.616685+0000 mon.ceph-tpa-server1 (mon.0) 1172517 : cluster [DBG] osd.10 failure report canceled by osd.7 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.727+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.0 is reporting failure:0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.727+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.839+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.5 is reporting failure:0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.839+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.5 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:17.733200+0000 mon.ceph-tpa-server1 (mon.0) 1172518 : cluster [DBG] osd.10 failure report canceled by osd.0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:17.843775+0000 mon.ceph-tpa-server1 (mon.0) 1172519 : cluster [DBG] osd.10 failure report canceled by osd.5 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.575+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.11 is reporting failure:0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.575+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.11 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.783+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.8 is reporting failure:0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.783+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.8 Dec 13 07:40:19 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:18.578914+0000 mon.ceph-tpa-server1 (mon.0) 1172520 : cluster [DBG] osd.10 failure report canceled by osd.11 Dec 13 07:40:19 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:18.789301+0000 mon.ceph-tpa-server1 (mon.0) 1172521 : cluster [DBG] osd.10 failure report canceled by osd.8
Thanks, Stefan
On 12/13/20, 2:18 AM, "Igor Fedotov" <ifedotov@suse.de> wrote:
Hi Stefan,
could you please share OSD startup log from /var/log/ceph?
Thanks,
Igor
On 12/13/2020 5:44 AM, Stefan Wild wrote:
Just had another look at the logs and this is what I did notice after the affected OSD starts up.
Loads of entries of this sort:
Dec 12 21:38:40 ceph-tpa-server1 bash[780507]: debug 2020-12-13T02:38:40.851+0000 7fafd32c7700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fafb721f700' had timed out after 15
Then a few pages of this:
Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9249> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9248> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9247> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9246> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9245> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13026 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9244> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9243> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9242> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9241> 2020-12-13T02:35:44.022+0000 7fafb721f700 1 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9240> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9239> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9238> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9237> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9236> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9235> 2020-12-13T02:35:44.022+0000 7fafb521b700 1 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916
And this is where it crashes:
Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9232> 2020-12-13T02:35:44.022+0000 7fafd02c1700 0 log_channel(cluster) log [DBG] : purged_snaps scrub starts Dec 12 21:38:57 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Main process exited, code=exited, status=1/FAILURE Dec 12 21:38:59 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Failed with result 'exit-code'. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Service hold-off time over, scheduling restart. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Scheduled restart job, restart counter is at 1. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Stopped Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Starting Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142... Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Started Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142.
Hope that helps…
Thanks, Stefan
From: Stefan Wild <swild@tiltworks.com> Date: Saturday, December 12, 2020 at 9:35 PM To: "ceph-users@ceph.io" <ceph-users@ceph.io> Subject: OSD reboot loop after running out of memory
Hi,
We recently upgraded a cluster from 15.2.1 to 15.2.5. About two days later, one of the server ran out of memory for unknown reasons (normally the machine uses about 60 out of 128 GB). Since then, some OSDs on that machine get caught in an endless restart loop. Logs will just mention system seeing the daemon fail and then restarting it. Since the out of memory incident, we’ve have 3 OSDs fail this way at separate times. We resorted to wiping the affected OSD and re-adding it to the cluster, but it seems as soon as all PGs have moved to the OSD, the next one fails.
This is also keeping us from re-deploying RGW, which was affected by the same out of memory incident, since cephadm runs a check and won’t deploy the service unless the cluster is in HEALTH_OK status.
Any help would be greatly appreciated.
Thanks, Stefan
_______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
_______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
Hi Samuel, I think we're hitting some niche cases. Most of our experience (and links to other posts) is here. https://lists.ceph.io/hyperkitty/list/ceph-users@ceph.io/thread/EWPPEMPAJQT6... For the pg_log issue, the default of 3000 might be too large for some installations, depending on your PG count. We have set it to 400. For the buffer_anon problem, there some speculation that it started when buffer_anon trimming changed. I assume it'll be fixed in a new version, these two may be candidates for fixes. https://github.com/ceph/ceph/pull/35171 https://github.com/ceph/ceph/pull/35584 Cheers, Kalle ----- Original Message -----
From: huxiaoyu@horebdata.cn To: "Kalle Happonen" <kalle.happonen@csc.fi>, "Stefan Wild" <swild@tiltworks.com> Cc: "ceph-users" <ceph-users@ceph.io> Sent: Monday, 14 December, 2020 10:27:57 Subject: Re: [ceph-users] Re: OSD reboot loop after running out of memory
Hello, Kalle,
Your comments abount some bugs with pg_log memory and buffer_anon memory growth worry me a lot, as i am planning to build a cluster with the latest Nautilous version.
Could you please comment on, how to safely deal with these bugs or to avoid, if indeed they occur?
thanks a lot,
samuel
huxiaoyu@horebdata.cn
From: Kalle Happonen Date: 2020-12-14 08:28 To: Stefan Wild CC: ceph-users Subject: [ceph-users] Re: OSD reboot loop after running out of memory Hi Stefan, we had been seeing OSDs OOMing on 14.2.13, but on a larger scale. In our case we hit a some bugs with pg_log memory growth and buffer_anon memory growth. Can you check what's taking up the memory on the OSD with the following command?
ceph daemon osd.123 dump_mempools
Cheers, Kalle
----- Original Message -----
From: "Stefan Wild" <swild@tiltworks.com> To: "Igor Fedotov" <ifedotov@suse.de>, "ceph-users" <ceph-users@ceph.io> Sent: Sunday, 13 December, 2020 14:46:44 Subject: [ceph-users] Re: OSD reboot loop after running out of memory
Hi Igor,
Full osd logs from startup to failed exit: https://tiltworks.com/osd.1.log
In other news, can I expect osd.10 to go down next?
Dec 13 07:40:14 ceph-tpa-server1 bash[1825010]: debug 2020-12-13T12:40:14.823+0000 7ff37c2e1700 -1 osd.7 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.310905+0000 front 2020-12-13T12:39:43.311164+0000 (oldest deadline 2020-12-13T12:40:06.810981+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:15.055+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[2060428]: debug 2020-12-13T12:40:15.155+0000 7fb247eaf700 -1 osd.8 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.181904+0000 front 2020-12-13T12:39:42.181856+0000 (oldest deadline 2020-12-13T12:40:06.281648+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.171+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.2 is reporting failure:0 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.171+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.2 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:15.176057+0000 mon.ceph-tpa-server1 (mon.0) 1172513 : cluster [DBG] osd.10 failure report canceled by osd.2 Dec 13 07:40:15 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:15.295+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.423+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.6 is reporting failure:0 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.423+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.6 Dec 13 07:40:15 ceph-tpa-server1 bash[1824845]: debug 2020-12-13T12:40:15.447+0000 7f85048db700 -1 osd.3 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:39.770822+0000 front 2020-12-13T12:39:39.770700+0000 (oldest deadline 2020-12-13T12:40:05.070662+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[231499]: debug 2020-12-13T12:40:15.687+0000 7fa8e1800700 -1 osd.4 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:39.977106+0000 front 2020-12-13T12:39:39.977176+0000 (oldest deadline 2020-12-13T12:40:04.677320+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1825010]: debug 2020-12-13T12:40:15.799+0000 7ff37c2e1700 -1 osd.7 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.310905+0000 front 2020-12-13T12:39:43.311164+0000 (oldest deadline 2020-12-13T12:40:06.810981+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:16.019+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.179+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.4 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.179+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.4 Dec 13 07:40:16 ceph-tpa-server1 bash[2060428]: debug 2020-12-13T12:40:16.191+0000 7fb247eaf700 -1 osd.8 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.181904+0000 front 2020-12-13T12:39:42.181856+0000 (oldest deadline 2020-12-13T12:40:06.281648+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:15.429755+0000 mon.ceph-tpa-server1 (mon.0) 1172514 : cluster [DBG] osd.10 failure report canceled by osd.6 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.183521+0000 mon.ceph-tpa-server1 (mon.0) 1172515 : cluster [DBG] osd.10 failure report canceled by osd.4 Dec 13 07:40:16 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:16.303+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.371+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.3 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.371+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.3 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.611+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.7 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.611+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.7 Dec 13 07:40:16 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:16.979+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:17 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:17.271+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.378213+0000 mon.ceph-tpa-server1 (mon.0) 1172516 : cluster [DBG] osd.10 failure report canceled by osd.3 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.616685+0000 mon.ceph-tpa-server1 (mon.0) 1172517 : cluster [DBG] osd.10 failure report canceled by osd.7 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.727+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.0 is reporting failure:0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.727+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.839+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.5 is reporting failure:0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.839+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.5 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:17.733200+0000 mon.ceph-tpa-server1 (mon.0) 1172518 : cluster [DBG] osd.10 failure report canceled by osd.0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:17.843775+0000 mon.ceph-tpa-server1 (mon.0) 1172519 : cluster [DBG] osd.10 failure report canceled by osd.5 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.575+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.11 is reporting failure:0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.575+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.11 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.783+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.8 is reporting failure:0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.783+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.8 Dec 13 07:40:19 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:18.578914+0000 mon.ceph-tpa-server1 (mon.0) 1172520 : cluster [DBG] osd.10 failure report canceled by osd.11 Dec 13 07:40:19 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:18.789301+0000 mon.ceph-tpa-server1 (mon.0) 1172521 : cluster [DBG] osd.10 failure report canceled by osd.8
Thanks, Stefan
On 12/13/20, 2:18 AM, "Igor Fedotov" <ifedotov@suse.de> wrote:
Hi Stefan,
could you please share OSD startup log from /var/log/ceph?
Thanks,
Igor
On 12/13/2020 5:44 AM, Stefan Wild wrote:
Just had another look at the logs and this is what I did notice after the affected OSD starts up.
Loads of entries of this sort:
Dec 12 21:38:40 ceph-tpa-server1 bash[780507]: debug 2020-12-13T02:38:40.851+0000 7fafd32c7700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fafb721f700' had timed out after 15
Then a few pages of this:
Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9249> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9248> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9247> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9246> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9245> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13026 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9244> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9243> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9242> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9241> 2020-12-13T02:35:44.022+0000 7fafb721f700 1 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9240> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9239> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9238> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9237> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9236> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9235> 2020-12-13T02:35:44.022+0000 7fafb521b700 1 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916
And this is where it crashes:
Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9232> 2020-12-13T02:35:44.022+0000 7fafd02c1700 0 log_channel(cluster) log [DBG] : purged_snaps scrub starts Dec 12 21:38:57 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Main process exited, code=exited, status=1/FAILURE Dec 12 21:38:59 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Failed with result 'exit-code'. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Service hold-off time over, scheduling restart. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Scheduled restart job, restart counter is at 1. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Stopped Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Starting Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142... Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Started Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142.
Hope that helps…
Thanks, Stefan
From: Stefan Wild <swild@tiltworks.com> Date: Saturday, December 12, 2020 at 9:35 PM To: "ceph-users@ceph.io" <ceph-users@ceph.io> Subject: OSD reboot loop after running out of memory
Hi,
We recently upgraded a cluster from 15.2.1 to 15.2.5. About two days later, one of the server ran out of memory for unknown reasons (normally the machine uses about 60 out of 128 GB). Since then, some OSDs on that machine get caught in an endless restart loop. Logs will just mention system seeing the daemon fail and then restarting it. Since the out of memory incident, we’ve have 3 OSDs fail this way at separate times. We resorted to wiping the affected OSD and re-adding it to the cluster, but it seems as soon as all PGs have moved to the OSD, the next one fails.
This is also keeping us from re-deploying RGW, which was affected by the same out of memory incident, since cephadm runs a check and won’t deploy the service unless the cluster is in HEALTH_OK status.
Any help would be greatly appreciated.
Thanks, Stefan
_______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
_______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
Hi Kalle, Memory usage is back on track for the OSDs since the OOM crash. I don’t know what caused it back then, but until all OSDs were back up together, each one of them (10 TiB capacity, 7 TiB used) ballooned to over 15 GB memory used. I’m happy to dump the stats if they’re showing any history from 2 weeks ago, but ballooning and running out of memory is not the issue anymore. Thanks, Stefan ________________________________ From: Kalle Happonen <kalle.happonen@csc.fi> Sent: Monday, December 14, 2020 5:00:17 AM To: huxiaoyu@horebdata.cn <huxiaoyu@horebdata.cn> Cc: Stefan Wild <swild@tiltworks.com>; ceph-users <ceph-users@ceph.io> Subject: Re: [ceph-users] Re: OSD reboot loop after running out of memory Hi Samuel, I think we're hitting some niche cases. Most of our experience (and links to other posts) is here. https://lists.ceph.io/hyperkitty/list/ceph-users@ceph.io/thread/EWPPEMPAJQT6... For the pg_log issue, the default of 3000 might be too large for some installations, depending on your PG count. We have set it to 400. For the buffer_anon problem, there some speculation that it started when buffer_anon trimming changed. I assume it'll be fixed in a new version, these two may be candidates for fixes. https://github.com/ceph/ceph/pull/35171 https://github.com/ceph/ceph/pull/35584 Cheers, Kalle ----- Original Message -----
From: huxiaoyu@horebdata.cn To: "Kalle Happonen" <kalle.happonen@csc.fi>, "Stefan Wild" <swild@tiltworks.com> Cc: "ceph-users" <ceph-users@ceph.io> Sent: Monday, 14 December, 2020 10:27:57 Subject: Re: [ceph-users] Re: OSD reboot loop after running out of memory
Hello, Kalle,
Your comments abount some bugs with pg_log memory and buffer_anon memory growth worry me a lot, as i am planning to build a cluster with the latest Nautilous version.
Could you please comment on, how to safely deal with these bugs or to avoid, if indeed they occur?
thanks a lot,
samuel
huxiaoyu@horebdata.cn
From: Kalle Happonen Date: 2020-12-14 08:28 To: Stefan Wild CC: ceph-users Subject: [ceph-users] Re: OSD reboot loop after running out of memory Hi Stefan, we had been seeing OSDs OOMing on 14.2.13, but on a larger scale. In our case we hit a some bugs with pg_log memory growth and buffer_anon memory growth. Can you check what's taking up the memory on the OSD with the following command?
ceph daemon osd.123 dump_mempools
Cheers, Kalle
----- Original Message -----
From: "Stefan Wild" <swild@tiltworks.com> To: "Igor Fedotov" <ifedotov@suse.de>, "ceph-users" <ceph-users@ceph.io> Sent: Sunday, 13 December, 2020 14:46:44 Subject: [ceph-users] Re: OSD reboot loop after running out of memory
Hi Igor,
Full osd logs from startup to failed exit: https://tiltworks.com/osd.1.log
In other news, can I expect osd.10 to go down next?
Dec 13 07:40:14 ceph-tpa-server1 bash[1825010]: debug 2020-12-13T12:40:14.823+0000 7ff37c2e1700 -1 osd.7 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.310905+0000 front 2020-12-13T12:39:43.311164+0000 (oldest deadline 2020-12-13T12:40:06.810981+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:15.055+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[2060428]: debug 2020-12-13T12:40:15.155+0000 7fb247eaf700 -1 osd.8 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.181904+0000 front 2020-12-13T12:39:42.181856+0000 (oldest deadline 2020-12-13T12:40:06.281648+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.171+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.2 is reporting failure:0 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.171+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.2 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:15.176057+0000 mon.ceph-tpa-server1 (mon.0) 1172513 : cluster [DBG] osd.10 failure report canceled by osd.2 Dec 13 07:40:15 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:15.295+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.423+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.6 is reporting failure:0 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.423+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.6 Dec 13 07:40:15 ceph-tpa-server1 bash[1824845]: debug 2020-12-13T12:40:15.447+0000 7f85048db700 -1 osd.3 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:39.770822+0000 front 2020-12-13T12:39:39.770700+0000 (oldest deadline 2020-12-13T12:40:05.070662+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[231499]: debug 2020-12-13T12:40:15.687+0000 7fa8e1800700 -1 osd.4 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:39.977106+0000 front 2020-12-13T12:39:39.977176+0000 (oldest deadline 2020-12-13T12:40:04.677320+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1825010]: debug 2020-12-13T12:40:15.799+0000 7ff37c2e1700 -1 osd.7 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.310905+0000 front 2020-12-13T12:39:43.311164+0000 (oldest deadline 2020-12-13T12:40:06.810981+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:16.019+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.179+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.4 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.179+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.4 Dec 13 07:40:16 ceph-tpa-server1 bash[2060428]: debug 2020-12-13T12:40:16.191+0000 7fb247eaf700 -1 osd.8 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.181904+0000 front 2020-12-13T12:39:42.181856+0000 (oldest deadline 2020-12-13T12:40:06.281648+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:15.429755+0000 mon.ceph-tpa-server1 (mon.0) 1172514 : cluster [DBG] osd.10 failure report canceled by osd.6 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.183521+0000 mon.ceph-tpa-server1 (mon.0) 1172515 : cluster [DBG] osd.10 failure report canceled by osd.4 Dec 13 07:40:16 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:16.303+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.371+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.3 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.371+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.3 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.611+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.7 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.611+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.7 Dec 13 07:40:16 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:16.979+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:17 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:17.271+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.378213+0000 mon.ceph-tpa-server1 (mon.0) 1172516 : cluster [DBG] osd.10 failure report canceled by osd.3 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.616685+0000 mon.ceph-tpa-server1 (mon.0) 1172517 : cluster [DBG] osd.10 failure report canceled by osd.7 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.727+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.0 is reporting failure:0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.727+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.839+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.5 is reporting failure:0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.839+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.5 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:17.733200+0000 mon.ceph-tpa-server1 (mon.0) 1172518 : cluster [DBG] osd.10 failure report canceled by osd.0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:17.843775+0000 mon.ceph-tpa-server1 (mon.0) 1172519 : cluster [DBG] osd.10 failure report canceled by osd.5 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.575+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.11 is reporting failure:0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.575+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.11 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.783+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.8 is reporting failure:0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.783+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.8 Dec 13 07:40:19 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:18.578914+0000 mon.ceph-tpa-server1 (mon.0) 1172520 : cluster [DBG] osd.10 failure report canceled by osd.11 Dec 13 07:40:19 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:18.789301+0000 mon.ceph-tpa-server1 (mon.0) 1172521 : cluster [DBG] osd.10 failure report canceled by osd.8
Thanks, Stefan
On 12/13/20, 2:18 AM, "Igor Fedotov" <ifedotov@suse.de> wrote:
Hi Stefan,
could you please share OSD startup log from /var/log/ceph?
Thanks,
Igor
On 12/13/2020 5:44 AM, Stefan Wild wrote:
Just had another look at the logs and this is what I did notice after the affected OSD starts up.
Loads of entries of this sort:
Dec 12 21:38:40 ceph-tpa-server1 bash[780507]: debug 2020-12-13T02:38:40.851+0000 7fafd32c7700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fafb721f700' had timed out after 15
Then a few pages of this:
Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9249> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9248> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9247> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9246> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9245> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13026 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9244> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9243> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9242> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9241> 2020-12-13T02:35:44.022+0000 7fafb721f700 1 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9240> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9239> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9238> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9237> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9236> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9235> 2020-12-13T02:35:44.022+0000 7fafb521b700 1 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916
And this is where it crashes:
Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9232> 2020-12-13T02:35:44.022+0000 7fafd02c1700 0 log_channel(cluster) log [DBG] : purged_snaps scrub starts Dec 12 21:38:57 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Main process exited, code=exited, status=1/FAILURE Dec 12 21:38:59 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Failed with result 'exit-code'. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Service hold-off time over, scheduling restart. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Scheduled restart job, restart counter is at 1. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Stopped Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142. Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Starting Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142... Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Started Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142.
Hope that helps…
Thanks, Stefan
From: Stefan Wild <swild@tiltworks.com> Date: Saturday, December 12, 2020 at 9:35 PM To: "ceph-users@ceph.io" <ceph-users@ceph.io> Subject: OSD reboot loop after running out of memory
Hi,
We recently upgraded a cluster from 15.2.1 to 15.2.5. About two days later, one of the server ran out of memory for unknown reasons (normally the machine uses about 60 out of 128 GB). Since then, some OSDs on that machine get caught in an endless restart loop. Logs will just mention system seeing the daemon fail and then restarting it. Since the out of memory incident, we’ve have 3 OSDs fail this way at separate times. We resorted to wiping the affected OSD and re-adding it to the cluster, but it seems as soon as all PGs have moved to the OSD, the next one fails.
This is also keeping us from re-deploying RGW, which was affected by the same out of memory incident, since cephadm runs a check and won’t deploy the service unless the cluster is in HEALTH_OK status.
Any help would be greatly appreciated.
Thanks, Stefan
_______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
_______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
Hi Stefan, given the crash backtrace in your log I presume some data removal is in progress: Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 3: (KernelDevice::direct_read_unaligned(unsigned long, unsigned long, char*)+0xd8) [0x5587b9364a48] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 4: (KernelDevice::read_random(unsigned long, unsigned long, char*, bool)+0x1b3) [0x5587b93653e3] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 5: (BlueFS::_read_random(BlueFS::FileReader*, unsigned long, unsigned long, char*)+0x674) [0x5587b9328cb4] ... Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 19: (BlueStore::_do_omap_clear(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Onode>&)+0xa2) [0x5587b922f0e2] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 20: (BlueStore::_do_remove(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Collection>&, boost::intrusive_ptr<BlueStore::Onode>)+0xc65) [0x5587b923b555] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 21: (BlueStore::_remove(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Collection>&, boost::intrusive_ptr<BlueStore::Onode>&)+0x64) [0x5587b923c3b4] ... Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 24: (ObjectStore::queue_transaction(boost::intrusive_ptr<ObjectStore::CollectionImpl>&, ceph::os::Transaction&&, boost::intrusive_ptr<TrackedOp>, ThreadPool::TPHandle*)+0x85) [0x5587b8dcf745] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 25: (PG::do_delete_work(ceph::os::Transaction&)+0xb2e) [0x5587b8e269ee] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 26: (PeeringState::Deleting::react(PeeringState::DeleteSome const&)+0x3e) [0x5587b8fd6ede] ... Did you initiate some large pool removal recently? Or may be data rebalancing triggered PG migration (and hence source PG removal) for you? Highly likely you're facing a well known issue with RocksDB/BlueFS performance issues caused by massive data removal. So your OSDs are just processing I/O very slowly which triggers suicide timeout. We've had multiple threads on the issue in this mailing list - the latest one is at https://lists.ceph.io/hyperkitty/list/ceph-users@ceph.io/thread/YBHNOSWW72ZV... For now the good enough workaround is manual offline DB compaction for all the OSDs (this might have temporary effect though as the removal proceeds). Additionally there are users' reports that recent default value's modification for bluefs_buffered_io setting has negative impact (or just worsen existing issue with massive removal) as well. So you might want to switch it back to true. As for OSD.10 - can't say for sure as I haven't seen its' logs but I think it's experiencing the same issue which might eventually lead it into unresponsive state as well. Just grep its log for "heartbeat_map is_healthy 'OSD::osd_op_tp thread" strings. Thanks, Igor On 12/13/2020 3:46 PM, Stefan Wild wrote:
Hi Igor,
Full osd logs from startup to failed exit: https://tiltworks.com/osd.1.log
In other news, can I expect osd.10 to go down next?
Dec 13 07:40:14 ceph-tpa-server1 bash[1825010]: debug 2020-12-13T12:40:14.823+0000 7ff37c2e1700 -1 osd.7 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.310905+0000 front 2020-12-13T12:39:43.311164+0000 (oldest deadline 2020-12-13T12:40:06.810981+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:15.055+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[2060428]: debug 2020-12-13T12:40:15.155+0000 7fb247eaf700 -1 osd.8 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.181904+0000 front 2020-12-13T12:39:42.181856+0000 (oldest deadline 2020-12-13T12:40:06.281648+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.171+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.2 is reporting failure:0 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.171+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.2 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:15.176057+0000 mon.ceph-tpa-server1 (mon.0) 1172513 : cluster [DBG] osd.10 failure report canceled by osd.2 Dec 13 07:40:15 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:15.295+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.423+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.6 is reporting failure:0 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.423+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.6 Dec 13 07:40:15 ceph-tpa-server1 bash[1824845]: debug 2020-12-13T12:40:15.447+0000 7f85048db700 -1 osd.3 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:39.770822+0000 front 2020-12-13T12:39:39.770700+0000 (oldest deadline 2020-12-13T12:40:05.070662+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[231499]: debug 2020-12-13T12:40:15.687+0000 7fa8e1800700 -1 osd.4 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:39.977106+0000 front 2020-12-13T12:39:39.977176+0000 (oldest deadline 2020-12-13T12:40:04.677320+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1825010]: debug 2020-12-13T12:40:15.799+0000 7ff37c2e1700 -1 osd.7 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.310905+0000 front 2020-12-13T12:39:43.311164+0000 (oldest deadline 2020-12-13T12:40:06.810981+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:16.019+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.179+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.4 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.179+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.4 Dec 13 07:40:16 ceph-tpa-server1 bash[2060428]: debug 2020-12-13T12:40:16.191+0000 7fb247eaf700 -1 osd.8 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.181904+0000 front 2020-12-13T12:39:42.181856+0000 (oldest deadline 2020-12-13T12:40:06.281648+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:15.429755+0000 mon.ceph-tpa-server1 (mon.0) 1172514 : cluster [DBG] osd.10 failure report canceled by osd.6 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.183521+0000 mon.ceph-tpa-server1 (mon.0) 1172515 : cluster [DBG] osd.10 failure report canceled by osd.4 Dec 13 07:40:16 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:16.303+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.371+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.3 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.371+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.3 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.611+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.7 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.611+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.7 Dec 13 07:40:16 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:16.979+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:17 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:17.271+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.378213+0000 mon.ceph-tpa-server1 (mon.0) 1172516 : cluster [DBG] osd.10 failure report canceled by osd.3 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.616685+0000 mon.ceph-tpa-server1 (mon.0) 1172517 : cluster [DBG] osd.10 failure report canceled by osd.7 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.727+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.0 is reporting failure:0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.727+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.839+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.5 is reporting failure:0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.839+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.5 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:17.733200+0000 mon.ceph-tpa-server1 (mon.0) 1172518 : cluster [DBG] osd.10 failure report canceled by osd.0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:17.843775+0000 mon.ceph-tpa-server1 (mon.0) 1172519 : cluster [DBG] osd.10 failure report canceled by osd.5 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.575+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.11 is reporting failure:0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.575+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.11 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.783+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.8 is reporting failure:0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.783+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.8 Dec 13 07:40:19 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:18.578914+0000 mon.ceph-tpa-server1 (mon.0) 1172520 : cluster [DBG] osd.10 failure report canceled by osd.11 Dec 13 07:40:19 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:18.789301+0000 mon.ceph-tpa-server1 (mon.0) 1172521 : cluster [DBG] osd.10 failure report canceled by osd.8
Thanks, Stefan
On 12/13/20, 2:18 AM, "Igor Fedotov" <ifedotov@suse.de> wrote:
Hi Stefan,
could you please share OSD startup log from /var/log/ceph?
Thanks,
Igor
On 12/13/2020 5:44 AM, Stefan Wild wrote: > Just had another look at the logs and this is what I did notice after the affected OSD starts up. > > Loads of entries of this sort: > > Dec 12 21:38:40 ceph-tpa-server1 bash[780507]: debug 2020-12-13T02:38:40.851+0000 7fafd32c7700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fafb721f700' had timed out after 15 > > Then a few pages of this: > > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9249> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9248> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9247> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9246> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9245> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13026 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9244> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9243> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9242> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9241> 2020-12-13T02:35:44.022+0000 7fafb721f700 1 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9240> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9239> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9238> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9237> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9236> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9235> 2020-12-13T02:35:44.022+0000 7fafb521b700 1 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > > And this is where it crashes: > > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9232> 2020-12-13T02:35:44.022+0000 7fafd02c1700 0 log_channel(cluster) log [DBG] : purged_snaps scrub starts > Dec 12 21:38:57 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Main process exited, code=exited, status=1/FAILURE > Dec 12 21:38:59 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Failed with result 'exit-code'. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Service hold-off time over, scheduling restart. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Scheduled restart job, restart counter is at 1. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Stopped Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Starting Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142... > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Started Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142. > > Hope that helps… > > > Thanks, > Stefan > > > From: Stefan Wild <swild@tiltworks.com> > Date: Saturday, December 12, 2020 at 9:35 PM > To: "ceph-users@ceph.io" <ceph-users@ceph.io> > Subject: OSD reboot loop after running out of memory > > Hi, > > We recently upgraded a cluster from 15.2.1 to 15.2.5. About two days later, one of the server ran out of memory for unknown reasons (normally the machine uses about 60 out of 128 GB). Since then, some OSDs on that machine get caught in an endless restart loop. Logs will just mention system seeing the daemon fail and then restarting it. Since the out of memory incident, we’ve have 3 OSDs fail this way at separate times. We resorted to wiping the affected OSD and re-adding it to the cluster, but it seems as soon as all PGs have moved to the OSD, the next one fails. > > This is also keeping us from re-deploying RGW, which was affected by the same out of memory incident, since cephadm runs a check and won’t deploy the service unless the cluster is in HEALTH_OK status. > > Any help would be greatly appreciated. > > Thanks, > Stefan > > _______________________________________________ > ceph-users mailing list -- ceph-users@ceph.io > To unsubscribe send an email to ceph-users-leave@ceph.io _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
Just a note - all the below is almost completely unrelated to high RAM usage. The latter is a different issue which presumably just triggered PG removal one... On 12/14/2020 2:39 PM, Igor Fedotov wrote:
Hi Stefan,
given the crash backtrace in your log I presume some data removal is in progress:
Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 3: (KernelDevice::direct_read_unaligned(unsigned long, unsigned long, char*)+0xd8) [0x5587b9364a48] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 4: (KernelDevice::read_random(unsigned long, unsigned long, char*, bool)+0x1b3) [0x5587b93653e3] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 5: (BlueFS::_read_random(BlueFS::FileReader*, unsigned long, unsigned long, char*)+0x674) [0x5587b9328cb4] ...
Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 19: (BlueStore::_do_omap_clear(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Onode>&)+0xa2) [0x5587b922f0e2] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 20: (BlueStore::_do_remove(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Collection>&, boost::intrusive_ptr<BlueStore::Onode>)+0xc65) [0x5587b923b555] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 21: (BlueStore::_remove(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Collection>&, boost::intrusive_ptr<BlueStore::Onode>&)+0x64) [0x5587b923c3b4] ...
Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 24: (ObjectStore::queue_transaction(boost::intrusive_ptr<ObjectStore::CollectionImpl>&, ceph::os::Transaction&&, boost::intrusive_ptr<TrackedOp>, ThreadPool::TPHandle*)+0x85) [0x5587b8dcf745] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 25: (PG::do_delete_work(ceph::os::Transaction&)+0xb2e) [0x5587b8e269ee] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 26: (PeeringState::Deleting::react(PeeringState::DeleteSome const&)+0x3e) [0x5587b8fd6ede] ...
Did you initiate some large pool removal recently? Or may be data rebalancing triggered PG migration (and hence source PG removal) for you?
Highly likely you're facing a well known issue with RocksDB/BlueFS performance issues caused by massive data removal.
So your OSDs are just processing I/O very slowly which triggers suicide timeout.
We've had multiple threads on the issue in this mailing list - the latest one is at https://lists.ceph.io/hyperkitty/list/ceph-users@ceph.io/thread/YBHNOSWW72ZV...
For now the good enough workaround is manual offline DB compaction for all the OSDs (this might have temporary effect though as the removal proceeds).
Additionally there are users' reports that recent default value's modification for bluefs_buffered_io setting has negative impact (or just worsen existing issue with massive removal) as well. So you might want to switch it back to true.
As for OSD.10 - can't say for sure as I haven't seen its' logs but I think it's experiencing the same issue which might eventually lead it into unresponsive state as well. Just grep its log for "heartbeat_map is_healthy 'OSD::osd_op_tp thread" strings.
Thanks,
Igor
On 12/13/2020 3:46 PM, Stefan Wild wrote:
Hi Igor,
Full osd logs from startup to failed exit: https://tiltworks.com/osd.1.log
In other news, can I expect osd.10 to go down next?
Dec 13 07:40:14 ceph-tpa-server1 bash[1825010]: debug 2020-12-13T12:40:14.823+0000 7ff37c2e1700 -1 osd.7 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.310905+0000 front 2020-12-13T12:39:43.311164+0000 (oldest deadline 2020-12-13T12:40:06.810981+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:15.055+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[2060428]: debug 2020-12-13T12:40:15.155+0000 7fb247eaf700 -1 osd.8 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.181904+0000 front 2020-12-13T12:39:42.181856+0000 (oldest deadline 2020-12-13T12:40:06.281648+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.171+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.2 is reporting failure:0 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.171+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.2 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:15.176057+0000 mon.ceph-tpa-server1 (mon.0) 1172513 : cluster [DBG] osd.10 failure report canceled by osd.2 Dec 13 07:40:15 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:15.295+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.423+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.6 is reporting failure:0 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.423+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.6 Dec 13 07:40:15 ceph-tpa-server1 bash[1824845]: debug 2020-12-13T12:40:15.447+0000 7f85048db700 -1 osd.3 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:39.770822+0000 front 2020-12-13T12:39:39.770700+0000 (oldest deadline 2020-12-13T12:40:05.070662+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[231499]: debug 2020-12-13T12:40:15.687+0000 7fa8e1800700 -1 osd.4 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:39.977106+0000 front 2020-12-13T12:39:39.977176+0000 (oldest deadline 2020-12-13T12:40:04.677320+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1825010]: debug 2020-12-13T12:40:15.799+0000 7ff37c2e1700 -1 osd.7 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.310905+0000 front 2020-12-13T12:39:43.311164+0000 (oldest deadline 2020-12-13T12:40:06.810981+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:16.019+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.179+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.4 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.179+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.4 Dec 13 07:40:16 ceph-tpa-server1 bash[2060428]: debug 2020-12-13T12:40:16.191+0000 7fb247eaf700 -1 osd.8 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.181904+0000 front 2020-12-13T12:39:42.181856+0000 (oldest deadline 2020-12-13T12:40:06.281648+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:15.429755+0000 mon.ceph-tpa-server1 (mon.0) 1172514 : cluster [DBG] osd.10 failure report canceled by osd.6 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.183521+0000 mon.ceph-tpa-server1 (mon.0) 1172515 : cluster [DBG] osd.10 failure report canceled by osd.4 Dec 13 07:40:16 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:16.303+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.371+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.3 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.371+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.3 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.611+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.7 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.611+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.7 Dec 13 07:40:16 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:16.979+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:17 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:17.271+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.378213+0000 mon.ceph-tpa-server1 (mon.0) 1172516 : cluster [DBG] osd.10 failure report canceled by osd.3 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.616685+0000 mon.ceph-tpa-server1 (mon.0) 1172517 : cluster [DBG] osd.10 failure report canceled by osd.7 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.727+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.0 is reporting failure:0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.727+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.839+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.5 is reporting failure:0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.839+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.5 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:17.733200+0000 mon.ceph-tpa-server1 (mon.0) 1172518 : cluster [DBG] osd.10 failure report canceled by osd.0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:17.843775+0000 mon.ceph-tpa-server1 (mon.0) 1172519 : cluster [DBG] osd.10 failure report canceled by osd.5 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.575+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.11 is reporting failure:0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.575+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.11 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.783+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.8 is reporting failure:0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.783+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.8 Dec 13 07:40:19 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:18.578914+0000 mon.ceph-tpa-server1 (mon.0) 1172520 : cluster [DBG] osd.10 failure report canceled by osd.11 Dec 13 07:40:19 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:18.789301+0000 mon.ceph-tpa-server1 (mon.0) 1172521 : cluster [DBG] osd.10 failure report canceled by osd.8
Thanks, Stefan
On 12/13/20, 2:18 AM, "Igor Fedotov" <ifedotov@suse.de> wrote:
Hi Stefan,
could you please share OSD startup log from /var/log/ceph?
Thanks,
Igor
On 12/13/2020 5:44 AM, Stefan Wild wrote: > Just had another look at the logs and this is what I did notice after the affected OSD starts up. > > Loads of entries of this sort: > > Dec 12 21:38:40 ceph-tpa-server1 bash[780507]: debug 2020-12-13T02:38:40.851+0000 7fafd32c7700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fafb721f700' had timed out after 15 > > Then a few pages of this: > > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9249> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9248> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9247> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9246> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9245> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13026 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9244> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9243> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9242> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9241> 2020-12-13T02:35:44.022+0000 7fafb721f700 1 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9240> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9239> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9238> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9237> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9236> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9235> 2020-12-13T02:35:44.022+0000 7fafb521b700 1 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > > And this is where it crashes: > > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9232> 2020-12-13T02:35:44.022+0000 7fafd02c1700 0 log_channel(cluster) log [DBG] : purged_snaps scrub starts > Dec 12 21:38:57 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Main process exited, code=exited, status=1/FAILURE > Dec 12 21:38:59 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Failed with result 'exit-code'. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Service hold-off time over, scheduling restart. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Scheduled restart job, restart counter is at 1. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Stopped Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Starting Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142... > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Started Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142. > > Hope that helps… > > > Thanks, > Stefan > > > From: Stefan Wild <swild@tiltworks.com> > Date: Saturday, December 12, 2020 at 9:35 PM > To: "ceph-users@ceph.io" <ceph-users@ceph.io> > Subject: OSD reboot loop after running out of memory > > Hi, > > We recently upgraded a cluster from 15.2.1 to 15.2.5. About two days later, one of the server ran out of memory for unknown reasons (normally the machine uses about 60 out of 128 GB). Since then, some OSDs on that machine get caught in an endless restart loop. Logs will just mention system seeing the daemon fail and then restarting it. Since the out of memory incident, we’ve have 3 OSDs fail this way at separate times. We resorted to wiping the affected OSD and re-adding it to the cluster, but it seems as soon as all PGs have moved to the OSD, the next one fails. > > This is also keeping us from re-deploying RGW, which was affected by the same out of memory incident, since cephadm runs a check and won’t deploy the service unless the cluster is in HEALTH_OK status. > > Any help would be greatly appreciated. > > Thanks, > Stefan > > _______________________________________________ > ceph-users mailing list -- ceph-users@ceph.io > To unsubscribe send an email to ceph-users-leave@ceph.io _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
_______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
Hi Igor, Thank you for the detailed analysis. That makes me hopeful we can get the cluster back on track. No pools have been removed, but yes, due to the initial crash of multiple OSDs and the subsequent issues with individual OSDs we’ve had substantial PG remappings happening constantly. I will look up the referenced thread(s) and try the offline DB compaction. It would be amazing if that does the trick. Will keep you posted, here. Thanks, Stefan ________________________________ From: Igor Fedotov <ifedotov@suse.de> Sent: Monday, December 14, 2020 6:39:28 AM To: Stefan Wild <swild@tiltworks.com>; ceph-users@ceph.io <ceph-users@ceph.io> Subject: Re: [ceph-users] Re: OSD reboot loop after running out of memory Hi Stefan, given the crash backtrace in your log I presume some data removal is in progress: Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 3: (KernelDevice::direct_read_unaligned(unsigned long, unsigned long, char*)+0xd8) [0x5587b9364a48] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 4: (KernelDevice::read_random(unsigned long, unsigned long, char*, bool)+0x1b3) [0x5587b93653e3] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 5: (BlueFS::_read_random(BlueFS::FileReader*, unsigned long, unsigned long, char*)+0x674) [0x5587b9328cb4] ... Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 19: (BlueStore::_do_omap_clear(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Onode>&)+0xa2) [0x5587b922f0e2] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 20: (BlueStore::_do_remove(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Collection>&, boost::intrusive_ptr<BlueStore::Onode>)+0xc65) [0x5587b923b555] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 21: (BlueStore::_remove(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Collection>&, boost::intrusive_ptr<BlueStore::Onode>&)+0x64) [0x5587b923c3b4] ... Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 24: (ObjectStore::queue_transaction(boost::intrusive_ptr<ObjectStore::CollectionImpl>&, ceph::os::Transaction&&, boost::intrusive_ptr<TrackedOp>, ThreadPool::TPHandle*)+0x85) [0x5587b8dcf745] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 25: (PG::do_delete_work(ceph::os::Transaction&)+0xb2e) [0x5587b8e269ee] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 26: (PeeringState::Deleting::react(PeeringState::DeleteSome const&)+0x3e) [0x5587b8fd6ede] ... Did you initiate some large pool removal recently? Or may be data rebalancing triggered PG migration (and hence source PG removal) for you? Highly likely you're facing a well known issue with RocksDB/BlueFS performance issues caused by massive data removal. So your OSDs are just processing I/O very slowly which triggers suicide timeout. We've had multiple threads on the issue in this mailing list - the latest one is at https://lists.ceph.io/hyperkitty/list/ceph-users@ceph.io/thread/YBHNOSWW72ZV... For now the good enough workaround is manual offline DB compaction for all the OSDs (this might have temporary effect though as the removal proceeds). Additionally there are users' reports that recent default value's modification for bluefs_buffered_io setting has negative impact (or just worsen existing issue with massive removal) as well. So you might want to switch it back to true. As for OSD.10 - can't say for sure as I haven't seen its' logs but I think it's experiencing the same issue which might eventually lead it into unresponsive state as well. Just grep its log for "heartbeat_map is_healthy 'OSD::osd_op_tp thread" strings. Thanks, Igor On 12/13/2020 3:46 PM, Stefan Wild wrote:
Hi Igor,
Full osd logs from startup to failed exit: https://tiltworks.com/osd.1.log
In other news, can I expect osd.10 to go down next?
Dec 13 07:40:14 ceph-tpa-server1 bash[1825010]: debug 2020-12-13T12:40:14.823+0000 7ff37c2e1700 -1 osd.7 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.310905+0000 front 2020-12-13T12:39:43.311164+0000 (oldest deadline 2020-12-13T12:40:06.810981+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:15.055+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[2060428]: debug 2020-12-13T12:40:15.155+0000 7fb247eaf700 -1 osd.8 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.181904+0000 front 2020-12-13T12:39:42.181856+0000 (oldest deadline 2020-12-13T12:40:06.281648+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.171+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.2 is reporting failure:0 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.171+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.2 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:15.176057+0000 mon.ceph-tpa-server1 (mon.0) 1172513 : cluster [DBG] osd.10 failure report canceled by osd.2 Dec 13 07:40:15 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:15.295+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.423+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.6 is reporting failure:0 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.423+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.6 Dec 13 07:40:15 ceph-tpa-server1 bash[1824845]: debug 2020-12-13T12:40:15.447+0000 7f85048db700 -1 osd.3 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:39.770822+0000 front 2020-12-13T12:39:39.770700+0000 (oldest deadline 2020-12-13T12:40:05.070662+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[231499]: debug 2020-12-13T12:40:15.687+0000 7fa8e1800700 -1 osd.4 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:39.977106+0000 front 2020-12-13T12:39:39.977176+0000 (oldest deadline 2020-12-13T12:40:04.677320+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1825010]: debug 2020-12-13T12:40:15.799+0000 7ff37c2e1700 -1 osd.7 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.310905+0000 front 2020-12-13T12:39:43.311164+0000 (oldest deadline 2020-12-13T12:40:06.810981+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:16.019+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.179+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.4 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.179+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.4 Dec 13 07:40:16 ceph-tpa-server1 bash[2060428]: debug 2020-12-13T12:40:16.191+0000 7fb247eaf700 -1 osd.8 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.181904+0000 front 2020-12-13T12:39:42.181856+0000 (oldest deadline 2020-12-13T12:40:06.281648+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:15.429755+0000 mon.ceph-tpa-server1 (mon.0) 1172514 : cluster [DBG] osd.10 failure report canceled by osd.6 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.183521+0000 mon.ceph-tpa-server1 (mon.0) 1172515 : cluster [DBG] osd.10 failure report canceled by osd.4 Dec 13 07:40:16 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:16.303+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.371+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.3 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.371+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.3 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.611+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.7 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.611+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.7 Dec 13 07:40:16 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:16.979+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:17 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:17.271+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.378213+0000 mon.ceph-tpa-server1 (mon.0) 1172516 : cluster [DBG] osd.10 failure report canceled by osd.3 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.616685+0000 mon.ceph-tpa-server1 (mon.0) 1172517 : cluster [DBG] osd.10 failure report canceled by osd.7 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.727+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.0 is reporting failure:0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.727+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.839+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.5 is reporting failure:0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.839+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.5 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:17.733200+0000 mon.ceph-tpa-server1 (mon.0) 1172518 : cluster [DBG] osd.10 failure report canceled by osd.0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:17.843775+0000 mon.ceph-tpa-server1 (mon.0) 1172519 : cluster [DBG] osd.10 failure report canceled by osd.5 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.575+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.11 is reporting failure:0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.575+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.11 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.783+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.8 is reporting failure:0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.783+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.8 Dec 13 07:40:19 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:18.578914+0000 mon.ceph-tpa-server1 (mon.0) 1172520 : cluster [DBG] osd.10 failure report canceled by osd.11 Dec 13 07:40:19 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:18.789301+0000 mon.ceph-tpa-server1 (mon.0) 1172521 : cluster [DBG] osd.10 failure report canceled by osd.8
Thanks, Stefan
On 12/13/20, 2:18 AM, "Igor Fedotov" <ifedotov@suse.de> wrote:
Hi Stefan,
could you please share OSD startup log from /var/log/ceph?
Thanks,
Igor
On 12/13/2020 5:44 AM, Stefan Wild wrote: > Just had another look at the logs and this is what I did notice after the affected OSD starts up. > > Loads of entries of this sort: > > Dec 12 21:38:40 ceph-tpa-server1 bash[780507]: debug 2020-12-13T02:38:40.851+0000 7fafd32c7700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fafb721f700' had timed out after 15 > > Then a few pages of this: > > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9249> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9248> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9247> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9246> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9245> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13026 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9244> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9243> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9242> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9241> 2020-12-13T02:35:44.022+0000 7fafb721f700 1 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9240> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9239> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9238> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9237> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9236> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9235> 2020-12-13T02:35:44.022+0000 7fafb521b700 1 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > > And this is where it crashes: > > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9232> 2020-12-13T02:35:44.022+0000 7fafd02c1700 0 log_channel(cluster) log [DBG] : purged_snaps scrub starts > Dec 12 21:38:57 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Main process exited, code=exited, status=1/FAILURE > Dec 12 21:38:59 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Failed with result 'exit-code'. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Service hold-off time over, scheduling restart. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Scheduled restart job, restart counter is at 1. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Stopped Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Starting Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142... > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Started Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142. > > Hope that helps… > > > Thanks, > Stefan > > > From: Stefan Wild <swild@tiltworks.com> > Date: Saturday, December 12, 2020 at 9:35 PM > To: "ceph-users@ceph.io" <ceph-users@ceph.io> > Subject: OSD reboot loop after running out of memory > > Hi, > > We recently upgraded a cluster from 15.2.1 to 15.2.5. About two days later, one of the server ran out of memory for unknown reasons (normally the machine uses about 60 out of 128 GB). Since then, some OSDs on that machine get caught in an endless restart loop. Logs will just mention system seeing the daemon fail and then restarting it. Since the out of memory incident, we’ve have 3 OSDs fail this way at separate times. We resorted to wiping the affected OSD and re-adding it to the cluster, but it seems as soon as all PGs have moved to the OSD, the next one fails. > > This is also keeping us from re-deploying RGW, which was affected by the same out of memory incident, since cephadm runs a check and won’t deploy the service unless the cluster is in HEALTH_OK status. > > Any help would be greatly appreciated. > > Thanks, > Stefan > > _______________________________________________ > ceph-users mailing list -- ceph-users@ceph.io > To unsubscribe send an email to ceph-users-leave@ceph.io _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
Hi Stefan, Initial data removal could also have resulted from a snapshot removal leading to OSDs OOMing and then pg remappings leading to more removals after OOMed OSDs rejoined the cluster and so on. As mentioned by Igor : "Additionally there are users' reports that recent default value's modification for bluefs_buffered_io setting has negative impact (or just worsen existing issue with massive removal) as well. So you might want to switch it back to true." We're some of them. Our cluster suffered from a severe performance drop during snapshot removal right after upgrading to Nautilus, due to bluefs_buffered_io being set to false by default, with slow requests observed around the cluster. Once back to true (can be done with ceph tell osd.* injectargs '--bluefs_buffered_io=true') snap trimming would be fast again so as before the upgrade, with no more slow requests. But of course we've seen the excessive memory swap usage described here : https://github.com/ceph/ceph/pull/34224 So we lower osd_memory_target from 8MB to 4MB and haven't observed any swap usage since then. You can also have a look here : https://github.com/ceph/ceph/pull/38044 What you need to look at to understand if your cluster would benefit from changing bluefs_buffered_io back to true is the %util of your RocksDBD devices on an iostat. Run an iostat -dmx 1 /dev/sdX (if you're using SSD RocksDB devices) and look at the %util of the device with bluefs_buffered_io=false and with bluefs_buffered_io=true. If with bluefs_buffered_io=false, the %util is over 75% most of the time, then you'd better change it to true. :-) Regards, Frédéric. Le 14/12/2020 à 12:47, Stefan Wild a écrit :
Hi Igor,
Thank you for the detailed analysis. That makes me hopeful we can get the cluster back on track. No pools have been removed, but yes, due to the initial crash of multiple OSDs and the subsequent issues with individual OSDs we’ve had substantial PG remappings happening constantly.
I will look up the referenced thread(s) and try the offline DB compaction. It would be amazing if that does the trick.
Will keep you posted, here.
Thanks, Stefan
________________________________ From: Igor Fedotov <ifedotov@suse.de> Sent: Monday, December 14, 2020 6:39:28 AM To: Stefan Wild <swild@tiltworks.com>; ceph-users@ceph.io <ceph-users@ceph.io> Subject: Re: [ceph-users] Re: OSD reboot loop after running out of memory
Hi Stefan,
given the crash backtrace in your log I presume some data removal is in progress:
Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 3: (KernelDevice::direct_read_unaligned(unsigned long, unsigned long, char*)+0xd8) [0x5587b9364a48] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 4: (KernelDevice::read_random(unsigned long, unsigned long, char*, bool)+0x1b3) [0x5587b93653e3] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 5: (BlueFS::_read_random(BlueFS::FileReader*, unsigned long, unsigned long, char*)+0x674) [0x5587b9328cb4] ...
Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 19: (BlueStore::_do_omap_clear(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Onode>&)+0xa2) [0x5587b922f0e2] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 20: (BlueStore::_do_remove(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Collection>&, boost::intrusive_ptr<BlueStore::Onode>)+0xc65) [0x5587b923b555] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 21: (BlueStore::_remove(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Collection>&, boost::intrusive_ptr<BlueStore::Onode>&)+0x64) [0x5587b923c3b4] ...
Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 24: (ObjectStore::queue_transaction(boost::intrusive_ptr<ObjectStore::CollectionImpl>&, ceph::os::Transaction&&, boost::intrusive_ptr<TrackedOp>, ThreadPool::TPHandle*)+0x85) [0x5587b8dcf745] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 25: (PG::do_delete_work(ceph::os::Transaction&)+0xb2e) [0x5587b8e269ee] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 26: (PeeringState::Deleting::react(PeeringState::DeleteSome const&)+0x3e) [0x5587b8fd6ede] ...
Did you initiate some large pool removal recently? Or may be data rebalancing triggered PG migration (and hence source PG removal) for you?
Highly likely you're facing a well known issue with RocksDB/BlueFS performance issues caused by massive data removal.
So your OSDs are just processing I/O very slowly which triggers suicide timeout.
We've had multiple threads on the issue in this mailing list - the latest one is at https://lists.ceph.io/hyperkitty/list/ceph-users@ceph.io/thread/YBHNOSWW72ZV...
For now the good enough workaround is manual offline DB compaction for all the OSDs (this might have temporary effect though as the removal proceeds).
Additionally there are users' reports that recent default value's modification for bluefs_buffered_io setting has negative impact (or just worsen existing issue with massive removal) as well. So you might want to switch it back to true.
As for OSD.10 - can't say for sure as I haven't seen its' logs but I think it's experiencing the same issue which might eventually lead it into unresponsive state as well. Just grep its log for "heartbeat_map is_healthy 'OSD::osd_op_tp thread" strings.
Thanks,
Igor
On 12/13/2020 3:46 PM, Stefan Wild wrote:
Hi Igor,
Full osd logs from startup to failed exit: https://tiltworks.com/osd.1.log
In other news, can I expect osd.10 to go down next?
Dec 13 07:40:14 ceph-tpa-server1 bash[1825010]: debug 2020-12-13T12:40:14.823+0000 7ff37c2e1700 -1 osd.7 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.310905+0000 front 2020-12-13T12:39:43.311164+0000 (oldest deadline 2020-12-13T12:40:06.810981+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:15.055+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[2060428]: debug 2020-12-13T12:40:15.155+0000 7fb247eaf700 -1 osd.8 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.181904+0000 front 2020-12-13T12:39:42.181856+0000 (oldest deadline 2020-12-13T12:40:06.281648+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.171+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.2 is reporting failure:0 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.171+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.2 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:15.176057+0000 mon.ceph-tpa-server1 (mon.0) 1172513 : cluster [DBG] osd.10 failure report canceled by osd.2 Dec 13 07:40:15 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:15.295+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.423+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.6 is reporting failure:0 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.423+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.6 Dec 13 07:40:15 ceph-tpa-server1 bash[1824845]: debug 2020-12-13T12:40:15.447+0000 7f85048db700 -1 osd.3 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:39.770822+0000 front 2020-12-13T12:39:39.770700+0000 (oldest deadline 2020-12-13T12:40:05.070662+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[231499]: debug 2020-12-13T12:40:15.687+0000 7fa8e1800700 -1 osd.4 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:39.977106+0000 front 2020-12-13T12:39:39.977176+0000 (oldest deadline 2020-12-13T12:40:04.677320+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1825010]: debug 2020-12-13T12:40:15.799+0000 7ff37c2e1700 -1 osd.7 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.310905+0000 front 2020-12-13T12:39:43.311164+0000 (oldest deadline 2020-12-13T12:40:06.810981+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:16.019+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.179+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.4 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.179+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.4 Dec 13 07:40:16 ceph-tpa-server1 bash[2060428]: debug 2020-12-13T12:40:16.191+0000 7fb247eaf700 -1 osd.8 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.181904+0000 front 2020-12-13T12:39:42.181856+0000 (oldest deadline 2020-12-13T12:40:06.281648+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:15.429755+0000 mon.ceph-tpa-server1 (mon.0) 1172514 : cluster [DBG] osd.10 failure report canceled by osd.6 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.183521+0000 mon.ceph-tpa-server1 (mon.0) 1172515 : cluster [DBG] osd.10 failure report canceled by osd.4 Dec 13 07:40:16 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:16.303+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.371+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.3 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.371+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.3 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.611+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.7 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.611+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.7 Dec 13 07:40:16 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:16.979+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:17 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:17.271+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.378213+0000 mon.ceph-tpa-server1 (mon.0) 1172516 : cluster [DBG] osd.10 failure report canceled by osd.3 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.616685+0000 mon.ceph-tpa-server1 (mon.0) 1172517 : cluster [DBG] osd.10 failure report canceled by osd.7 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.727+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.0 is reporting failure:0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.727+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.839+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.5 is reporting failure:0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.839+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.5 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:17.733200+0000 mon.ceph-tpa-server1 (mon.0) 1172518 : cluster [DBG] osd.10 failure report canceled by osd.0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:17.843775+0000 mon.ceph-tpa-server1 (mon.0) 1172519 : cluster [DBG] osd.10 failure report canceled by osd.5 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.575+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.11 is reporting failure:0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.575+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.11 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.783+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.8 is reporting failure:0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.783+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.8 Dec 13 07:40:19 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:18.578914+0000 mon.ceph-tpa-server1 (mon.0) 1172520 : cluster [DBG] osd.10 failure report canceled by osd.11 Dec 13 07:40:19 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:18.789301+0000 mon.ceph-tpa-server1 (mon.0) 1172521 : cluster [DBG] osd.10 failure report canceled by osd.8
Thanks, Stefan
On 12/13/20, 2:18 AM, "Igor Fedotov" <ifedotov@suse.de> wrote:
Hi Stefan,
could you please share OSD startup log from /var/log/ceph?
Thanks,
Igor
On 12/13/2020 5:44 AM, Stefan Wild wrote: > Just had another look at the logs and this is what I did notice after the affected OSD starts up. > > Loads of entries of this sort: > > Dec 12 21:38:40 ceph-tpa-server1 bash[780507]: debug 2020-12-13T02:38:40.851+0000 7fafd32c7700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fafb721f700' had timed out after 15 > > Then a few pages of this: > > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9249> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9248> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9247> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9246> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9245> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13026 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9244> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9243> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9242> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9241> 2020-12-13T02:35:44.022+0000 7fafb721f700 1 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9240> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9239> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9238> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9237> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9236> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9235> 2020-12-13T02:35:44.022+0000 7fafb521b700 1 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > > And this is where it crashes: > > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9232> 2020-12-13T02:35:44.022+0000 7fafd02c1700 0 log_channel(cluster) log [DBG] : purged_snaps scrub starts > Dec 12 21:38:57 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Main process exited, code=exited, status=1/FAILURE > Dec 12 21:38:59 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Failed with result 'exit-code'. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Service hold-off time over, scheduling restart. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Scheduled restart job, restart counter is at 1. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Stopped Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Starting Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142... > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Started Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142. > > Hope that helps… > > > Thanks, > Stefan > > > From: Stefan Wild <swild@tiltworks.com> > Date: Saturday, December 12, 2020 at 9:35 PM > To: "ceph-users@ceph.io" <ceph-users@ceph.io> > Subject: OSD reboot loop after running out of memory > > Hi, > > We recently upgraded a cluster from 15.2.1 to 15.2.5. About two days later, one of the server ran out of memory for unknown reasons (normally the machine uses about 60 out of 128 GB). Since then, some OSDs on that machine get caught in an endless restart loop. Logs will just mention system seeing the daemon fail and then restarting it. Since the out of memory incident, we’ve have 3 OSDs fail this way at separate times. We resorted to wiping the affected OSD and re-adding it to the cluster, but it seems as soon as all PGs have moved to the OSD, the next one fails. > > This is also keeping us from re-deploying RGW, which was affected by the same out of memory incident, since cephadm runs a check and won’t deploy the service unless the cluster is in HEALTH_OK status. > > Any help would be greatly appreciated. > > Thanks, > Stefan > > _______________________________________________ > ceph-users mailing list -- ceph-users@ceph.io > To unsubscribe send an email to ceph-users-leave@ceph.io _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
_______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
Hi Frédéric, Thanks for the additional input. We are currently only running RGW on the cluster, so no snapshot removal, but there have been plenty of remappings with the OSDs failing (all of them at first during and after the OOM incident, then one-by-one). I haven't had a chance to look into or test the bluefs_buffered_io setting, but will do that next. Initial results from compacting all OSDs' RocksDBs look promising (thank you, Igor!). Things have been stable for the past two hours, including the two OSDs with issues (one in reboot loop, the other with some heartbeats missed), while 15 degraded PGs are backfilling. The ballooning of each OSD to over 15GB memory right after the initial crash was even with osd_memory_target set to 2GB. The only thing that helped at that point was to temporarily add enough swap space to fit 12 x 15GB and let them do their thing. Once they had all booted, memory usage went back down to normal levels. I will report back here with more details when the cluster is hopefully back to a healthy state. Thanks, Stefan On 12/14/20, 3:35 PM, "Frédéric Nass" <frederic.nass@univ-lorraine.fr> wrote: Hi Stefan, Initial data removal could also have resulted from a snapshot removal leading to OSDs OOMing and then pg remappings leading to more removals after OOMed OSDs rejoined the cluster and so on. As mentioned by Igor : "Additionally there are users' reports that recent default value's modification for bluefs_buffered_io setting has negative impact (or just worsen existing issue with massive removal) as well. So you might want to switch it back to true." We're some of them. Our cluster suffered from a severe performance drop during snapshot removal right after upgrading to Nautilus, due to bluefs_buffered_io being set to false by default, with slow requests observed around the cluster. Once back to true (can be done with ceph tell osd.* injectargs '--bluefs_buffered_io=true') snap trimming would be fast again so as before the upgrade, with no more slow requests. But of course we've seen the excessive memory swap usage described here : https://github.com/ceph/ceph/pull/34224 So we lower osd_memory_target from 8MB to 4MB and haven't observed any swap usage since then. You can also have a look here : https://github.com/ceph/ceph/pull/38044 What you need to look at to understand if your cluster would benefit from changing bluefs_buffered_io back to true is the %util of your RocksDBD devices on an iostat. Run an iostat -dmx 1 /dev/sdX (if you're using SSD RocksDB devices) and look at the %util of the device with bluefs_buffered_io=false and with bluefs_buffered_io=true. If with bluefs_buffered_io=false, the %util is over 75% most of the time, then you'd better change it to true. :-) Regards, Frédéric.
Hi Sefan, This has me thinking that the issue your cluster may be facing is probably with bluefs_buffered_io set to true, as this has been reported to induce excessive swap usage (and OSDs flapping or OOMing as consequences) in some versions starting from Nautilus I believe. Can you check the value of bluefs_buffered_io that OSDs are currently using ? : ceph --admin-daemon /var/run/ceph/ceph-osd.0.asok config show | grep bluefs_buffered_io Can you check the kernel value of vm.swappiness ? : sysctl vm.swappiness (default value is 30) And describe your OSD nodes ? # of HDDS and SSDs/NVMes and HDD/SSD ratio, and how much memory they have ? You should be able to avoid swap usage by setting bluefs_buffered_io to false but your cluster / workload might not allow that performance and stability wise. Or you may be able to workaround the excessive swap usage (when bluefs_buffered_io is set to true) by lowering vm.swappiness or disabling the swap. Regards, Frédéric. Le 14/12/2020 à 22:12, Stefan Wild a écrit :
Hi Frédéric,
Thanks for the additional input. We are currently only running RGW on the cluster, so no snapshot removal, but there have been plenty of remappings with the OSDs failing (all of them at first during and after the OOM incident, then one-by-one). I haven't had a chance to look into or test the bluefs_buffered_io setting, but will do that next. Initial results from compacting all OSDs' RocksDBs look promising (thank you, Igor!). Things have been stable for the past two hours, including the two OSDs with issues (one in reboot loop, the other with some heartbeats missed), while 15 degraded PGs are backfilling.
The ballooning of each OSD to over 15GB memory right after the initial crash was even with osd_memory_target set to 2GB. The only thing that helped at that point was to temporarily add enough swap space to fit 12 x 15GB and let them do their thing. Once they had all booted, memory usage went back down to normal levels.
I will report back here with more details when the cluster is hopefully back to a healthy state.
Thanks, Stefan
On 12/14/20, 3:35 PM, "Frédéric Nass" <frederic.nass@univ-lorraine.fr> wrote:
Hi Stefan,
Initial data removal could also have resulted from a snapshot removal leading to OSDs OOMing and then pg remappings leading to more removals after OOMed OSDs rejoined the cluster and so on.
As mentioned by Igor : "Additionally there are users' reports that recent default value's modification for bluefs_buffered_io setting has negative impact (or just worsen existing issue with massive removal) as well. So you might want to switch it back to true."
We're some of them. Our cluster suffered from a severe performance drop during snapshot removal right after upgrading to Nautilus, due to bluefs_buffered_io being set to false by default, with slow requests observed around the cluster. Once back to true (can be done with ceph tell osd.* injectargs '--bluefs_buffered_io=true') snap trimming would be fast again so as before the upgrade, with no more slow requests.
But of course we've seen the excessive memory swap usage described here : https://github.com/ceph/ceph/pull/34224 So we lower osd_memory_target from 8MB to 4MB and haven't observed any swap usage since then. You can also have a look here : https://github.com/ceph/ceph/pull/38044
What you need to look at to understand if your cluster would benefit from changing bluefs_buffered_io back to true is the %util of your RocksDBD devices on an iostat. Run an iostat -dmx 1 /dev/sdX (if you're using SSD RocksDB devices) and look at the %util of the device with bluefs_buffered_io=false and with bluefs_buffered_io=true. If with bluefs_buffered_io=false, the %util is over 75% most of the time, then you'd better change it to true. :-)
Regards,
Frédéric.
_______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
Regarding RocksDB compaction, if you were in a situation were RocksDB had overspilled to HDDs (if your cluster is using an hybrid setup), the compaction should have move the bits back to fast devices. So it might have helped in this situation too. Regards, Frédéric. Le 16/12/2020 à 09:57, Frédéric Nass a écrit :
Hi Sefan,
This has me thinking that the issue your cluster may be facing is probably with bluefs_buffered_io set to true, as this has been reported to induce excessive swap usage (and OSDs flapping or OOMing as consequences) in some versions starting from Nautilus I believe.
Can you check the value of bluefs_buffered_io that OSDs are currently using ? : ceph --admin-daemon /var/run/ceph/ceph-osd.0.asok config show | grep bluefs_buffered_io
Can you check the kernel value of vm.swappiness ? : sysctl vm.swappiness (default value is 30)
And describe your OSD nodes ? # of HDDS and SSDs/NVMes and HDD/SSD ratio, and how much memory they have ?
You should be able to avoid swap usage by setting bluefs_buffered_io to false but your cluster / workload might not allow that performance and stability wise. Or you may be able to workaround the excessive swap usage (when bluefs_buffered_io is set to true) by lowering vm.swappiness or disabling the swap.
Regards,
Frédéric.
Le 14/12/2020 à 22:12, Stefan Wild a écrit :
Hi Frédéric,
Thanks for the additional input. We are currently only running RGW on the cluster, so no snapshot removal, but there have been plenty of remappings with the OSDs failing (all of them at first during and after the OOM incident, then one-by-one). I haven't had a chance to look into or test the bluefs_buffered_io setting, but will do that next. Initial results from compacting all OSDs' RocksDBs look promising (thank you, Igor!). Things have been stable for the past two hours, including the two OSDs with issues (one in reboot loop, the other with some heartbeats missed), while 15 degraded PGs are backfilling.
The ballooning of each OSD to over 15GB memory right after the initial crash was even with osd_memory_target set to 2GB. The only thing that helped at that point was to temporarily add enough swap space to fit 12 x 15GB and let them do their thing. Once they had all booted, memory usage went back down to normal levels.
I will report back here with more details when the cluster is hopefully back to a healthy state.
Thanks, Stefan
On 12/14/20, 3:35 PM, "Frédéric Nass" <frederic.nass@univ-lorraine.fr> wrote:
Hi Stefan,
Initial data removal could also have resulted from a snapshot removal leading to OSDs OOMing and then pg remappings leading to more removals after OOMed OSDs rejoined the cluster and so on.
As mentioned by Igor : "Additionally there are users' reports that recent default value's modification for bluefs_buffered_io setting has negative impact (or just worsen existing issue with massive removal) as well. So you might want to switch it back to true."
We're some of them. Our cluster suffered from a severe performance drop during snapshot removal right after upgrading to Nautilus, due to bluefs_buffered_io being set to false by default, with slow requests observed around the cluster. Once back to true (can be done with ceph tell osd.* injectargs '--bluefs_buffered_io=true') snap trimming would be fast again so as before the upgrade, with no more slow requests.
But of course we've seen the excessive memory swap usage described here : https://github.com/ceph/ceph/pull/34224 So we lower osd_memory_target from 8MB to 4MB and haven't observed any swap usage since then. You can also have a look here : https://github.com/ceph/ceph/pull/38044
What you need to look at to understand if your cluster would benefit from changing bluefs_buffered_io back to true is the %util of your RocksDBD devices on an iostat. Run an iostat -dmx 1 /dev/sdX (if you're using SSD RocksDB devices) and look at the %util of the device with bluefs_buffered_io=false and with bluefs_buffered_io=true. If with bluefs_buffered_io=false, the %util is over 75% most of the time, then you'd better change it to true. :-)
Regards,
Frédéric.
_______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
Our setup is not using SSDs as the Bluestore DB devices. We only have 2 SSDs vs 12 HDDs, which is normally fine for the low workload of the cluster. The SSDs are serving a pool that is just used by RGW for index and meta. Since the compaction two weeks ago the OSDs have all been stable. However, besides some other minor issues the cluster now keeps remapping erasure coded PGs with identical OSDs just in different order. Ceph will remap 11 (out of 128) PGs, then slowly backfill them and the second it's done, it'll pick another 11 PGs and remap those. I had to set osd_max_backfills to 0 in order to get any scrubbing/repair in. Not sure how to stop the constant cycle of remapping/backfilling. Thanks, Stefan On 12/16/20, 4:24 AM, "Frédéric Nass" <frederic.nass@univ-lorraine.fr> wrote: Regarding RocksDB compaction, if you were in a situation were RocksDB had overspilled to HDDs (if your cluster is using an hybrid setup), the compaction should have move the bits back to fast devices. So it might have helped in this situation too. Regards, Frédéric. Le 16/12/2020 à 09:57, Frédéric Nass a écrit : > Hi Sefan, > > This has me thinking that the issue your cluster may be facing is > probably with bluefs_buffered_io set to true, as this has been > reported to induce excessive swap usage (and OSDs flapping or OOMing > as consequences) in some versions starting from Nautilus I believe. > > Can you check the value of bluefs_buffered_io that OSDs are currently > using ? : ceph --admin-daemon /var/run/ceph/ceph-osd.0.asok config > show | grep bluefs_buffered_io > > Can you check the kernel value of vm.swappiness ? : sysctl > vm.swappiness (default value is 30) > > And describe your OSD nodes ? # of HDDS and SSDs/NVMes and HDD/SSD > ratio, and how much memory they have ? > > You should be able to avoid swap usage by setting bluefs_buffered_io > to false but your cluster / workload might not allow that performance > and stability wise. > Or you may be able to workaround the excessive swap usage (when > bluefs_buffered_io is set to true) by lowering vm.swappiness or > disabling the swap. > > Regards, > > Frédéric. > > Le 14/12/2020 à 22:12, Stefan Wild a écrit : >> Hi Frédéric, >> >> Thanks for the additional input. We are currently only running RGW on >> the cluster, so no snapshot removal, but there have been plenty of >> remappings with the OSDs failing (all of them at first during and >> after the OOM incident, then one-by-one). I haven't had a chance to >> look into or test the bluefs_buffered_io setting, but will do that >> next. Initial results from compacting all OSDs' RocksDBs look >> promising (thank you, Igor!). Things have been stable for the past >> two hours, including the two OSDs with issues (one in reboot loop, >> the other with some heartbeats missed), while 15 degraded PGs are >> backfilling. >> >> The ballooning of each OSD to over 15GB memory right after the >> initial crash was even with osd_memory_target set to 2GB. The only >> thing that helped at that point was to temporarily add enough swap >> space to fit 12 x 15GB and let them do their thing. Once they had all >> booted, memory usage went back down to normal levels. >> >> I will report back here with more details when the cluster is >> hopefully back to a healthy state. >> >> Thanks, >> Stefan >> >> >> >> On 12/14/20, 3:35 PM, "Frédéric Nass" >> <frederic.nass@univ-lorraine.fr> wrote: >> >> Hi Stefan, >> >> Initial data removal could also have resulted from a snapshot >> removal >> leading to OSDs OOMing and then pg remappings leading to more >> removals >> after OOMed OSDs rejoined the cluster and so on. >> >> As mentioned by Igor : "Additionally there are users' reports that >> recent default value's modification for bluefs_buffered_io >> setting has >> negative impact (or just worsen existing issue with massive >> removal) as >> well. So you might want to switch it back to true." >> >> We're some of them. Our cluster suffered from a severe >> performance drop >> during snapshot removal right after upgrading to Nautilus, due to >> bluefs_buffered_io being set to false by default, with slow >> requests >> observed around the cluster. >> Once back to true (can be done with ceph tell osd.* injectargs >> '--bluefs_buffered_io=true') snap trimming would be fast again >> so as >> before the upgrade, with no more slow requests. >> >> But of course we've seen the excessive memory swap usage >> described here >> : https://github.com/ceph/ceph/pull/34224 >> So we lower osd_memory_target from 8MB to 4MB and haven't >> observed any >> swap usage since then. You can also have a look here : >> https://github.com/ceph/ceph/pull/38044 >> >> What you need to look at to understand if your cluster would >> benefit >> from changing bluefs_buffered_io back to true is the %util of your >> RocksDBD devices on an iostat. Run an iostat -dmx 1 /dev/sdX (if >> you're >> using SSD RocksDB devices) and look at the %util of the device with >> bluefs_buffered_io=false and with bluefs_buffered_io=true. If with >> bluefs_buffered_io=false, the %util is over 75% most of the >> time, then >> you'd better change it to true. :-) >> >> Regards, >> >> Frédéric. >> >> _______________________________________________ >> ceph-users mailing list -- ceph-users@ceph.io >> To unsubscribe send an email to ceph-users-leave@ceph.io > _______________________________________________ > ceph-users mailing list -- ceph-users@ceph.io > To unsubscribe send an email to ceph-users-leave@ceph.io
I forgot to mention "If with bluefs_buffered_io=false, the %util is over 75% most of the time ** during data removal (like snapshot removal) **, then you'd better change it to true." Regards, Frédéric. Le 14/12/2020 à 21:35, Frédéric Nass a écrit :
Hi Stefan,
Initial data removal could also have resulted from a snapshot removal leading to OSDs OOMing and then pg remappings leading to more removals after OOMed OSDs rejoined the cluster and so on.
As mentioned by Igor : "Additionally there are users' reports that recent default value's modification for bluefs_buffered_io setting has negative impact (or just worsen existing issue with massive removal) as well. So you might want to switch it back to true."
We're some of them. Our cluster suffered from a severe performance drop during snapshot removal right after upgrading to Nautilus, due to bluefs_buffered_io being set to false by default, with slow requests observed around the cluster. Once back to true (can be done with ceph tell osd.* injectargs '--bluefs_buffered_io=true') snap trimming would be fast again so as before the upgrade, with no more slow requests.
But of course we've seen the excessive memory swap usage described here : https://github.com/ceph/ceph/pull/34224 So we lower osd_memory_target from 8MB to 4MB and haven't observed any swap usage since then. You can also have a look here : https://github.com/ceph/ceph/pull/38044
What you need to look at to understand if your cluster would benefit from changing bluefs_buffered_io back to true is the %util of your RocksDBD devices on an iostat. Run an iostat -dmx 1 /dev/sdX (if you're using SSD RocksDB devices) and look at the %util of the device with bluefs_buffered_io=false and with bluefs_buffered_io=true. If with bluefs_buffered_io=false, the %util is over 75% most of the time, then you'd better change it to true. :-)
Regards,
Frédéric.
Le 14/12/2020 à 12:47, Stefan Wild a écrit :
Hi Igor,
Thank you for the detailed analysis. That makes me hopeful we can get the cluster back on track. No pools have been removed, but yes, due to the initial crash of multiple OSDs and the subsequent issues with individual OSDs we’ve had substantial PG remappings happening constantly.
I will look up the referenced thread(s) and try the offline DB compaction. It would be amazing if that does the trick.
Will keep you posted, here.
Thanks, Stefan
________________________________ From: Igor Fedotov <ifedotov@suse.de> Sent: Monday, December 14, 2020 6:39:28 AM To: Stefan Wild <swild@tiltworks.com>; ceph-users@ceph.io <ceph-users@ceph.io> Subject: Re: [ceph-users] Re: OSD reboot loop after running out of memory
Hi Stefan,
given the crash backtrace in your log I presume some data removal is in progress:
Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 3: (KernelDevice::direct_read_unaligned(unsigned long, unsigned long, char*)+0xd8) [0x5587b9364a48] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 4: (KernelDevice::read_random(unsigned long, unsigned long, char*, bool)+0x1b3) [0x5587b93653e3] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 5: (BlueFS::_read_random(BlueFS::FileReader*, unsigned long, unsigned long, char*)+0x674) [0x5587b9328cb4] ...
Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 19: (BlueStore::_do_omap_clear(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Onode>&)+0xa2) [0x5587b922f0e2] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 20: (BlueStore::_do_remove(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Collection>&, boost::intrusive_ptr<BlueStore::Onode>)+0xc65) [0x5587b923b555] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 21: (BlueStore::_remove(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Collection>&, boost::intrusive_ptr<BlueStore::Onode>&)+0x64) [0x5587b923c3b4] ...
Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 24: (ObjectStore::queue_transaction(boost::intrusive_ptr<ObjectStore::CollectionImpl>&,
ceph::os::Transaction&&, boost::intrusive_ptr<TrackedOp>, ThreadPool::TPHandle*)+0x85) [0x5587b8dcf745] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 25: (PG::do_delete_work(ceph::os::Transaction&)+0xb2e) [0x5587b8e269ee] Dec 12 21:58:38 ceph-tpa-server1 bash[784256]: 26: (PeeringState::Deleting::react(PeeringState::DeleteSome const&)+0x3e) [0x5587b8fd6ede] ...
Did you initiate some large pool removal recently? Or may be data rebalancing triggered PG migration (and hence source PG removal) for you?
Highly likely you're facing a well known issue with RocksDB/BlueFS performance issues caused by massive data removal.
So your OSDs are just processing I/O very slowly which triggers suicide timeout.
We've had multiple threads on the issue in this mailing list - the latest one is at https://lists.ceph.io/hyperkitty/list/ceph-users@ceph.io/thread/YBHNOSWW72ZV...
For now the good enough workaround is manual offline DB compaction for all the OSDs (this might have temporary effect though as the removal proceeds).
Additionally there are users' reports that recent default value's modification for bluefs_buffered_io setting has negative impact (or just worsen existing issue with massive removal) as well. So you might want to switch it back to true.
As for OSD.10 - can't say for sure as I haven't seen its' logs but I think it's experiencing the same issue which might eventually lead it into unresponsive state as well. Just grep its log for "heartbeat_map is_healthy 'OSD::osd_op_tp thread" strings.
Thanks,
Igor
On 12/13/2020 3:46 PM, Stefan Wild wrote:
Hi Igor,
Full osd logs from startup to failed exit: https://tiltworks.com/osd.1.log
In other news, can I expect osd.10 to go down next?
Dec 13 07:40:14 ceph-tpa-server1 bash[1825010]: debug 2020-12-13T12:40:14.823+0000 7ff37c2e1700 -1 osd.7 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.310905+0000 front 2020-12-13T12:39:43.311164+0000 (oldest deadline 2020-12-13T12:40:06.810981+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:15.055+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[2060428]: debug 2020-12-13T12:40:15.155+0000 7fb247eaf700 -1 osd.8 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.181904+0000 front 2020-12-13T12:39:42.181856+0000 (oldest deadline 2020-12-13T12:40:06.281648+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.171+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.2 is reporting failure:0 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.171+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.2 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:15.176057+0000 mon.ceph-tpa-server1 (mon.0) 1172513 : cluster [DBG] osd.10 failure report canceled by osd.2 Dec 13 07:40:15 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:15.295+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.423+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.6 is reporting failure:0 Dec 13 07:40:15 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:15.423+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.6 Dec 13 07:40:15 ceph-tpa-server1 bash[1824845]: debug 2020-12-13T12:40:15.447+0000 7f85048db700 -1 osd.3 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:39.770822+0000 front 2020-12-13T12:39:39.770700+0000 (oldest deadline 2020-12-13T12:40:05.070662+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[231499]: debug 2020-12-13T12:40:15.687+0000 7fa8e1800700 -1 osd.4 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:39.977106+0000 front 2020-12-13T12:39:39.977176+0000 (oldest deadline 2020-12-13T12:40:04.677320+0000) Dec 13 07:40:15 ceph-tpa-server1 bash[1825010]: debug 2020-12-13T12:40:15.799+0000 7ff37c2e1700 -1 osd.7 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.310905+0000 front 2020-12-13T12:39:43.311164+0000 (oldest deadline 2020-12-13T12:40:06.810981+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:16.019+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.179+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.4 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.179+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.4 Dec 13 07:40:16 ceph-tpa-server1 bash[2060428]: debug 2020-12-13T12:40:16.191+0000 7fb247eaf700 -1 osd.8 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.181904+0000 front 2020-12-13T12:39:42.181856+0000 (oldest deadline 2020-12-13T12:40:06.281648+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:15.429755+0000 mon.ceph-tpa-server1 (mon.0) 1172514 : cluster [DBG] osd.10 failure report canceled by osd.6 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.183521+0000 mon.ceph-tpa-server1 (mon.0) 1172515 : cluster [DBG] osd.10 failure report canceled by osd.4 Dec 13 07:40:16 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:16.303+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.371+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.3 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.371+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.3 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.611+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.7 is reporting failure:0 Dec 13 07:40:16 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:16.611+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.7 Dec 13 07:40:16 ceph-tpa-server1 bash[1824817]: debug 2020-12-13T12:40:16.979+0000 7f9220af3700 -1 osd.11 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:42.972558+0000 front 2020-12-13T12:39:42.972702+0000 (oldest deadline 2020-12-13T12:40:05.272435+0000) Dec 13 07:40:17 ceph-tpa-server1 bash[1824779]: debug 2020-12-13T12:40:17.271+0000 7fa60679a700 -1 osd.0 13375 heartbeat_check: no reply from 172.18.189.20:6878 osd.10 since back 2020-12-13T12:39:43.326792+0000 front 2020-12-13T12:39:43.326666+0000 (oldest deadline 2020-12-13T12:40:07.426786+0000) Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.378213+0000 mon.ceph-tpa-server1 (mon.0) 1172516 : cluster [DBG] osd.10 failure report canceled by osd.3 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:16.616685+0000 mon.ceph-tpa-server1 (mon.0) 1172517 : cluster [DBG] osd.10 failure report canceled by osd.7 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.727+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.0 is reporting failure:0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.727+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.839+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.5 is reporting failure:0 Dec 13 07:40:17 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:17.839+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.5 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:17.733200+0000 mon.ceph-tpa-server1 (mon.0) 1172518 : cluster [DBG] osd.10 failure report canceled by osd.0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:17.843775+0000 mon.ceph-tpa-server1 (mon.0) 1172519 : cluster [DBG] osd.10 failure report canceled by osd.5 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.575+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.11 is reporting failure:0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.575+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.11 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.783+0000 7fe929be8700 1 mon.ceph-tpa-server1@0(leader).osd e13375 prepare_failure osd.10 [v2:172.18.189.20:6872/2139598710,v1:172.18.189.20:6873/2139598710] from osd.8 is reporting failure:0 Dec 13 07:40:18 ceph-tpa-server1 bash[1822497]: debug 2020-12-13T12:40:18.783+0000 7fe929be8700 0 log_channel(cluster) log [DBG] : osd.10 failure report canceled by osd.8 Dec 13 07:40:19 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:18.578914+0000 mon.ceph-tpa-server1 (mon.0) 1172520 : cluster [DBG] osd.10 failure report canceled by osd.11 Dec 13 07:40:19 ceph-tpa-server1 bash[1822497]: cluster 2020-12-13T12:40:18.789301+0000 mon.ceph-tpa-server1 (mon.0) 1172521 : cluster [DBG] osd.10 failure report canceled by osd.8
Thanks, Stefan
On 12/13/20, 2:18 AM, "Igor Fedotov" <ifedotov@suse.de> wrote:
Hi Stefan,
could you please share OSD startup log from /var/log/ceph?
Thanks,
Igor
On 12/13/2020 5:44 AM, Stefan Wild wrote: > Just had another look at the logs and this is what I did notice after the affected OSD starts up. > > Loads of entries of this sort: > > Dec 12 21:38:40 ceph-tpa-server1 bash[780507]: debug 2020-12-13T02:38:40.851+0000 7fafd32c7700 1 heartbeat_map is_healthy 'OSD::osd_op_tp thread 0x7fafb721f700' had timed out after 15 > > Then a few pages of this: > > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9249> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9248> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9247> 2020-12-13T02:35:44.018+0000 7fafb621d700 5 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9246> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13024 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9245> 2020-12-13T02:35:44.018+0000 7fafb621d700 1 osd.1 pg_epoch: 13026 pg[28.11( empty local-lis/les=13015/13016 n=0 ec=1530 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9244> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9243> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9242> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9241> 2020-12-13T02:35:44.022+0000 7fafb721f700 1 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9240> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9239> 2020-12-13T02:35:44.022+0000 7fafb721f700 5 osd.1 pg_epoch: 13143 pg[19.69s2( v 3437'1753192 (3437'1753192,3437'1753192 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9238> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9237> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9236> 2020-12-13T02:35:44.022+0000 7fafb521b700 5 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9235> 2020-12-13T02:35:44.022+0000 7fafb521b700 1 osd.1 pg_epoch: 13143 pg[19.3bs10( v 3437'1759161 (3437'1759161,3437'175916 > > And this is where it crashes: > > Dec 12 21:38:56 ceph-tpa-server1 bash[780507]: debug -9232> 2020-12-13T02:35:44.022+0000 7fafd02c1700 0 log_channel(cluster) log [DBG] : purged_snaps scrub starts > Dec 12 21:38:57 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Main process exited, code=exited, status=1/FAILURE > Dec 12 21:38:59 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Failed with result 'exit-code'. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Service hold-off time over, scheduling restart. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: ceph-08fa929a-8e23-11ea-a1a2-ac1f6bf83142@osd.1.service: Scheduled restart job, restart counter is at 1. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Stopped Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142. > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Starting Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142... > Dec 12 21:39:09 ceph-tpa-server1 systemd[1]: Started Ceph osd.1 for 08fa929a-8e23-11ea-a1a2-ac1f6bf83142. > > Hope that helps… > > > Thanks, > Stefan > > > From: Stefan Wild <swild@tiltworks.com> > Date: Saturday, December 12, 2020 at 9:35 PM > To: "ceph-users@ceph.io" <ceph-users@ceph.io> > Subject: OSD reboot loop after running out of memory > > Hi, > > We recently upgraded a cluster from 15.2.1 to 15.2.5. About two days later, one of the server ran out of memory for unknown reasons (normally the machine uses about 60 out of 128 GB). Since then, some OSDs on that machine get caught in an endless restart loop. Logs will just mention system seeing the daemon fail and then restarting it. Since the out of memory incident, we’ve have 3 OSDs fail this way at separate times. We resorted to wiping the affected OSD and re-adding it to the cluster, but it seems as soon as all PGs have moved to the OSD, the next one fails. > > This is also keeping us from re-deploying RGW, which was affected by the same out of memory incident, since cephadm runs a check and won’t deploy the service unless the cluster is in HEALTH_OK status. > > Any help would be greatly appreciated. > > Thanks, > Stefan > > _______________________________________________ > ceph-users mailing list -- ceph-users@ceph.io > To unsubscribe send an email to ceph-users-leave@ceph.io _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
_______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
participants (5)
-
Frédéric Nass
-
huxiaoyu＠horebdata.cn
-
Igor Fedotov
-
Kalle Happonen
-
Stefan Wild