I need to harden our ceph cluster to satisfy the following properties:
Assuming all hardware is functioning properly,
1) Cluster health has highest priority. Heartbeats have priority over client requests.
2) The cluster does not accept more IO than the OSDs can handle. The only exception might be a configurable burst option.
3) Client IO is accepted as long as it does not compromise 1.
4) Ideally, there is fair sharing of the cluster's IO budget between clients (like deadline or completely fair scheduling). Rogue clients should not get priority just because they push a lot.
Unfortunately, with default settings our (any?) cluster prefers client IO over cluster health, which opens up for a simple but serious non-privileged client attack on cluster health:
I observed a serious issue on our cluster when running a simple fio test that does 4K random writes on 100GB files (see details below). What I observe is that within a few seconds the cluster goes to health_warn with the MDS reporting slow meta data IO and behind on trimming. What is not shown in ceph health detail is, that all OSDs report thousands of slow ops and the counter increases really fast (I include some snippets below). This goes rapidly to the point where OSDs start missing heartbeats and start flapping, some PGs become inactive+degraded and start peering regularly. CPU load, memory and even network load were rather low (one-figure % CPU load). Nothing out of the ordinary. The mons had no issues.
After the fio test completed, the OSDs slowly crunched through the backlog and managed to complete all OPS. The complete processing of the ops of a 30 second fio test took ca. 10 minutes. However, even then the cluster did not come back healthy as essential messages between daemons seem to have been lost. It is not a long stretch to assume that one can destroy a ceph fs beyond repair when running this test or an application performing the same IO pattern from multiple clients for several hours. We have a 500 node cluster as clients and I'm afraid that even ordinary IO might trigger this scenario in unlucky circumstances.
Since our cluster is only half-trusted (we have root access to clients, but no control over user IO patterns), we are in need to harden our cluster against such destructive IO patterns as much as possible.
To me it looks like the cluster is accepting way more IO than the OSDs can handle. Ideally, what I would like to do is configure effective rate limiting on (rogue) clients depending on how much OPS they have in flight already. I would expect that there are tunables for MDS/OSD daemons that control how much IO requests a client can submit/OSD will accept before throttling IO. In particular, I would like to prioritize heartbeats to prevent load-induced OSD flapping. How can I tune the cluster to satisfy the conditions outlined at the top of this e-mail?
There were recent threads with similar topics, in particular, "MDS failing under load with large cache sizes" and others reporting unstable MDS daemons under load. However, I believe they were mostly related to cache trimming issues due to large amounts of files created. This is not the case here, its just 4 files with lots of random IO from a single client.
A bit of information about our cluster and observations:
The cluster is bluestore-only with 8+2 EC fs data pool on spinning disks and an 3(2) replicated fs meta data pool on SSD. We have 8 OSD hosts with 2 shards per host. Each host has 4SSDs and 12 10TB HDDs SAS 12GB with 4k block size. Network is 2x10G bonded for client and 2x10G bonded for replication. The replication network will be extended to 4x10G soon. We are aware that currently the network bandwidth greatly exceeds what the spinning disks can handle. It is dimensioned for adding more disks in the future.
The fio job script is:
[global]
name=fio-rand-write
directory=/home/fio # /home is on ceph fs
filename_format=tmp/fio-$jobname-${HOSTNAME}-$jobnum-$filenum
rw=randwrite
bs=4K
numjobs=4
time_based=1
runtime=30
[file1]
size=100G
ioengine=sync
Its one of the examples in the fio source repo with small modifications (file pattern, run time). Shortly after starting this fio job from a client connected with single 10G line, all OSDs start reporting slow ops. Picking one, the log messages look like this:
Aug 22 12:06:22 ceph-09 ceph-osd: 2019-08-22 10:06:22.151 7f399d1bd700 -1 osd.125 3778 get_health_metrics reporting 146 slow ops, oldest is osd_op(client.1178165.0:1670940 5.3fs0 5:fcc65fe3:::10000f403bc.0000063e:head [write 307200~4096,write 315392~8192,write 380928~12288,write 405504~12288,write 421888~4096,write 458752~4096,write 466944~4096,write 475136~4096,write 487424~8192,write 512000~4096,write 524288~4096,write 565248~4096,write 589824~8192,write 622592~4096,write 651264~4096,write 724992~12288] snapc 12e=[] ondisk+write+known_if_redirected e3778)
...
Aug 22 12:06:49 ceph-09 journal: 2019-08-22 10:06:49.415 7f399d1bd700 -1 osd.125 3779 get_health_metrics reporting 4595 slow ops, olde
st is osd_op(client.1178165.0:1686216 5.acs0 5:354e96d5:::10000f403bc.00000bc1:head [write 2359296~4096,write 2375680~4096,write 23838
72~4096,write 2404352~4096,write 2428928~8192,write 2469888~4096,write 2490368~8192,write 2514944~4096,write 2527232~4096,write 253542
4~4096,write 2588672~4096,write 2600960~4096,write 2621440~8192,write 2658304~4096,write 2715648~8192,write 2727936~4096] snapc 12e=[]
ondisk+write+known_if_redirected e3778)
...
Aug 22 12:12:57 ceph-09 journal: 2019-08-22 10:12:57.650 7f399d1bd700 -1 osd.125 3839 get_health_metrics reporting 8419 slow ops, oldest is osd_op(client.1178165.0:2009417 5.3fs0 5:fcdcf2bd:::10000f47e2d.00001501:head [write 2236416~4096,write 2256896~4096,write 2265088~4096,write 2301952~4096,write 2322432~4096,write 2355200~4096,write 2371584~4096,write 2387968~4096,write 2449408~4096,write 2486272~4096,write 2547712~8192,write 2617344~4096,write 2809856~4096,write 3018752~4096,write 3194880~4096,write 3223552~4096] snapc 12e=[] ondisk+write+known_if_redirected e3839)
Aug 22 12:12:58 ceph-09 ceph-osd: 2019-08-22 10:12:58.681 7f399d1bd700 -1 osd.125 3839 get_health_metrics reporting 8862 slow ops, oldest is osd_op(mds.0.16909:69577511 5.ees0 5.992388ee (undecoded) ondisk+write+known_if_redirected+full_force e3839)
...
Aug 22 12:13:27 ceph-09 journal: 2019-08-22 10:13:27.691 7f399d1bd700 -1 osd.125 3839 get_health_metrics reporting 13795 slow ops, oldest is osd_op(mds.0.16909:69577573 5.e6s0 5.d8994de6 (undecoded) ondisk+write+known_if_redirected+full_force e3839)
...
Aug 22 12:13:59 ceph-09 ceph-osd: 2019-08-22 10:13:59.762 7f399d1bd700 -1 osd.125 3900 get_health_metrics reporting 12 slow ops, oldest is osd_op(mds.0.16909:69577511 5.ees0 5.992388ee (undecoded) ondisk+retry+write+known_if_redirected+full_force e3875)
...
Aug 22 12:14:46 ceph-09 journal: 2019-08-22 10:14:46.569 7f399d1bd700 -1 osd.125 3916 get_health_metrics reporting 969 slow ops, oldes
t is osd_op(mds.0.16909:69577511 5.ees0 5.992388ee (undecoded) ondisk+retry+write+known_if_redirected+full_force e3875)
Aug 22 12:14:47 ceph-09 ceph-osd: 2019-08-22 10:14:47.617 7f399d1bd700 -1 osd.125 3935 get_health_metrics reporting 1 slow ops, oldest
is osd_op(mds.0.16909:69577511 5.ees0 5:7711c499:::10000f4798b.00000000:head [create,setxattr parent (289),setxattr layout (30)] snap
c 0=[] RETRY=2 ondisk+retry+write+known_if_redirected+full_force e3875)
...
Aug 22 12:14:53 ceph-09 journal: 2019-08-22 10:14:53.675 7f399d1bd700 -1 osd.125 3939 get_health_metrics reporting 1 slow ops, oldest is osd_op(mds.0.16909:69577511 5.ees0 5:7711c499:::10000f4798b.00000000:head [create,setxattr parent (289),setxattr layout (30)] snapc 0=[] RETRY=2 ondisk+retry+write+known_if_redirected+full_force e3875)
This is the last log message, the OSD seems to have executed all OPS at this point or shortly after. The cluster state went to health_ok - at least shortly.
At about 12:45 (yes, lunch break) we looked at the cluster again and it was back in health_warn with the following status output:
[root@ceph-01 ~]# ceph status
cluster:
id: e4ece518-f2cb-4708-b00f-b6bf511e91d9
health: HEALTH_WARN
1 MDSs report slow metadata IOs
2 MDSs behind on trimming
services:
mon: 3 daemons, quorum ceph-01,ceph-02,ceph-03
mgr: ceph-01(active), standbys: ceph-02, ceph-03
mds: con-fs-1/1/1 up {0=ceph-08=up:active}, 1 up:standby-replay
osd: 192 osds: 192 up, 192 in
data:
pools: 7 pools, 790 pgs
objects: 9.01 M objects, 16 TiB
usage: 20 TiB used, 1.3 PiB / 1.3 PiB avail
pgs: 790 active+clean
io:
client: 1.9 MiB/s rd, 21 MiB/s wr, 60 op/s rd, 721 op/s wr
[root@ceph-01 ~]# ceph health detail
HEALTH_WARN 1 MDSs report slow metadata IOs; 2 MDSs behind on trimming
MDS_SLOW_METADATA_IO 1 MDSs report slow metadata IOs
mdsceph-08(mds.0): 2 slow metadata IOs are blocked > 30 secs, oldest blocked for 3275 secs
MDS_TRIM 2 MDSs behind on trimming
mdsceph-08(mds.0): Behind on trimming (1778/128) max_segments: 128, num_segments: 1778
mdsceph-12(mds.0): Behind on trimming (1780/128) max_segments: 128, num_segments: 1780
Num_segments was increasing constantly. Apparently, an operation got stuck and never completed. We hunted a little bit and found
[root@ceph-mds:ceph-08 /]# ceph daemon mds.ceph-08 objecter_requests
{
"ops": [
{
"tid": 71206302,
"pg": "4.952611b7",
"osd": 19,
"object_id": "200.0001be74",
"object_locator": "@4",
"target_object_id": "200.0001be74",
"target_object_locator": "@4",
"paused": 0,
"used_replica": 0,
"precalc_pgid": 0,
"last_sent": "268516s",
"attempts": 1,
"snapid": "head",
"snap_context": "0=[]",
"mtime": "2019-08-22 11:12:41.0.565912s",
"osd_ops": [
"write 890478~1923"
]
},
{
"tid": 71206303,
"pg": "4.952611b7",
"osd": 19,
"object_id": "200.0001be74",
"object_locator": "@4",
"target_object_id": "200.0001be74",
"target_object_locator": "@4",
"paused": 0,
"used_replica": 0,
"precalc_pgid": 0,
"last_sent": "268516s",
"attempts": 1,
"snapid": "head",
"snap_context": "0=[]",
"mtime": "2019-08-22 11:12:41.0.566236s",
"osd_ops": [
"write 892401~1931"
]
},
{
"tid": 71206301,
"pg": "5.eeb918c6",
"osd": 67,
"object_id": "10000f26f67.00000000",
"object_locator": "@5",
"target_object_id": "10000f26f67.00000000",
"target_object_locator": "@5",
"paused": 0,
"used_replica": 0,
"precalc_pgid": 0,
"last_sent": "268516s",
"attempts": 1,
"snapid": "head",
"snap_context": "12e=[]",
"mtime": "1970-01-01 00:00:00.000000s",
"osd_ops": [
"trimtrunc 81854@573"
]
},
{
"tid": 69577573,
"pg": "5.d8994de6",
"osd": 125,
"object_id": "10000f479c9.00000000",
"object_locator": "@5",
"target_object_id": "10000f479c9.00000000",
"target_object_locator": "@5",
"paused": 0,
"used_replica": 0,
"precalc_pgid": 0,
"last_sent": "265042s",
"attempts": 5,
"snapid": "head",
"snap_context": "0=[]",
"mtime": "2019-08-22 10:12:05.0.256058s",
"osd_ops": [
"create",
"setxattr parent (319)",
"setxattr layout (30)"
]
},
{
"tid": 69577598,
"pg": "5.deb003e6",
"osd": 125,
"object_id": "10000f479da.00000000",
"object_locator": "@5",
"target_object_id": "10000f479da.00000000",
"target_object_locator": "@5",
"paused": 0,
"used_replica": 0,
"precalc_pgid": 0,
"last_sent": "265042s",
"attempts": 5,
"snapid": "head",
"snap_context": "0=[]",
"mtime": "2019-08-22 10:12:05.0.258824s",
"osd_ops": [
"create",
"setxattr parent (288)",
"setxattr layout (30)"
]
},
{
"tid": 71206300,
"pg": "5.5cd5b20b",
"osd": 163,
"object_id": "10000f01396.00000000",
"object_locator": "@5",
"target_object_id": "10000f01396.00000000",
"target_object_locator": "@5",
"paused": 0,
"used_replica": 0,
"precalc_pgid": 0,
"last_sent": "268516s",
"attempts": 1,
"snapid": "head",
"snap_context": "12e=[]",
"mtime": "1970-01-01 00:00:00.000000s",
"osd_ops": [
"trimtrunc 208782@573"
]
}
],
"linger_ops": [],
"pool_ops": [],
"pool_stat_ops": [],
"statfs_ops": [],
"command_ops": []
}
Notice the ops from the 1970's. Checking ops and dump_blocked_ops on osd.19 showed that these lists were empty. So, we decided to restart osd.19 and it cleared out most of the stuck requests, but did not clear the health warnings:
[root@ceph-mds:ceph-08 /]# ceph daemon mds.ceph-08 objecter_requests
{
"ops": [
{
"tid": 69577573,
"pg": "5.d8994de6",
"osd": 125,
"object_id": "10000f479c9.00000000",
"object_locator": "@5",
"target_object_id": "10000f479c9.00000000",
"target_object_locator": "@5",
"paused": 0,
"used_replica": 0,
"precalc_pgid": 0,
"last_sent": "265042s",
"attempts": 5,
"snapid": "head",
"snap_context": "0=[]",
"mtime": "2019-08-22 10:12:05.0.256058s",
"osd_ops": [
"create",
"setxattr parent (319)",
"setxattr layout (30)"
]
},
{
"tid": 69577598,
"pg": "5.deb003e6",
"osd": 125,
"object_id": "10000f479da.00000000",
"object_locator": "@5",
"target_object_id": "10000f479da.00000000",
"target_object_locator": "@5",
"paused": 0,
"used_replica": 0,
"precalc_pgid": 0,
"last_sent": "265042s",
"attempts": 5,
"snapid": "head",
"snap_context": "0=[]",
"mtime": "2019-08-22 10:12:05.0.258824s",
"osd_ops": [
"create",
"setxattr parent (288)",
"setxattr layout (30)"
]
}
],
"linger_ops": [],
"pool_ops": [],
"pool_stat_ops": [],
"statfs_ops": [],
"command_ops": []
}
Restarting osd.125 finally resolved the health issues. However, the client I run fio on had lost connection to ceph due to this incident, which is really annoying. This client is the head node of our HPC cluster and it was not possible to restore ceph fs access without reboot. This is an additional bad fallout as all users will loose access to our HPC cluster when this happens (/home is on the ceph fs).
I dumped the dump_historic_slow_ops of osd.125 in case anyone can use this information.
I might be able to repeat this experiment, but cannot promise anything.
Best regards,
=================
Frank Schilder
AIT Risø Campus
Bygning 109, rum S14