ceph fs crashes on simple fio test
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
The WPQ scheduler may help your clients back off when things get busy. Put this in your ceph.conf and restart your OSDs. osd op queue = wpq osd op queue cut off = high ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Fri, Aug 23, 2019 at 5:03 AM Frank Schilder <frans@dtu.dk> wrote:
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 _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
Frank; Just out of curiosity; do you use a dedicated cluster network, or do you run a single network? Thank you, Dominic L. Hilsbos, MBA Director – Information Technology Perform Air International Inc. DHilsbos@PerformAir.com www.PerformAir.com From: Robert LeBlanc [mailto:robert@leblancnet.us] Sent: Friday, August 23, 2019 8:29 AM To: Frank Schilder Cc: ceph-users Subject: [ceph-users] Re: ceph fs crashes on simple fio test The WPQ scheduler may help your clients back off when things get busy. Put this in your ceph.conf and restart your OSDs. osd op queue = wpq osd op queue cut off = high ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Fri, Aug 23, 2019 at 5:03 AM Frank Schilder <frans@dtu.dk> wrote: 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 _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
We have separate public and cluster networks, but on the same physical switches with different VLANs. ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Fri, Aug 23, 2019 at 1:29 PM <DHilsbos@performair.com> wrote:
Frank;
Just out of curiosity; do you use a dedicated cluster network, or do you run a single network?
Thank you,
Dominic L. Hilsbos, MBA Director – Information Technology Perform Air International Inc. DHilsbos@PerformAir.com www.PerformAir.com
From: Robert LeBlanc [mailto:robert@leblancnet.us] Sent: Friday, August 23, 2019 8:29 AM To: Frank Schilder Cc: ceph-users Subject: [ceph-users] Re: ceph fs crashes on simple fio test
The WPQ scheduler may help your clients back off when things get busy.
Put this in your ceph.conf and restart your OSDs. osd op queue = wpq osd op queue cut off = high ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
On Fri, Aug 23, 2019 at 5:03 AM Frank Schilder <frans@dtu.dk> wrote: 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 _______________________________________________ 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
Same set-up as Robert. Two different VLANs for front and back network on same switch. We did load tests before and the switches have no problems routing the traffic. Best regards, ================= Frank Schilder AIT Risø Campus Bygning 109, rum S14 ________________________________________ From: Robert LeBlanc <robert@leblancnet.us> Sent: 24 August 2019 01:31 To: DHilsbos@performair.com Cc: Frank Schilder; ceph-users@ceph.io Subject: Re: [ceph-users] Re: ceph fs crashes on simple fio test We have separate public and cluster networks, but on the same physical switches with different VLANs. ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Fri, Aug 23, 2019 at 1:29 PM <DHilsbos@performair.com<mailto:DHilsbos@performair.com>> wrote: Frank; Just out of curiosity; do you use a dedicated cluster network, or do you run a single network? Thank you, Dominic L. Hilsbos, MBA Director – Information Technology Perform Air International Inc. DHilsbos@PerformAir.com www.PerformAir.com<http://www.PerformAir.com>
Hi Robert, thanks for your reply. These are actually settings I found in cases I referred to with "other cases" in my mail. These settings could be a first step. Looking at the documentation, solving the overload problem might require some QoS settings I found below the description of "osd op queue" https://docs.ceph.com/docs/master/rados/configuration/osd-config-ref/#operat... . I see some possibilities, but I'm not sure how to use these settings to enforce load dependent rate limiting on clients. As far as I can see, IOPs QoS does not take backlog into account, which would be important for distinguishing a burst from a sustained overload. In addition, this requires mClock, which is labelled experimental. If anyone could shed some light on what possibilities currently exist beyond playing with "osd op queue" and "osd op queue cut off" that would be great. Also if there is some experience out there about this problem. For example, would reducing "osd client op priority" have any effect? As far as I can see, this is only for weighting between recovery and client IO, not for priority of IO already in flight versus new client OPS. Best regards, ================= Frank Schilder AIT Risø Campus Bygning 109, rum S14 ________________________________________ From: Robert LeBlanc <robert@leblancnet.us> Sent: 23 August 2019 17:28 To: Frank Schilder Cc: ceph-users Subject: Re: [ceph-users] ceph fs crashes on simple fio test The WPQ scheduler may help your clients back off when things get busy. Put this in your ceph.conf and restart your OSDs. osd op queue = wpq osd op queue cut off = high ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
Frank, I wrote the wpq and the cut off code because the only scheduler at the time was not servicing other priorities under extreme load. The default op scheduler prioritized replication ops in the strict queue which meant as long as there were any ops from other OSDs for replication, no client or backfill ops would be serviced. Once the strict queue was empty then it would start dequeing client ops, but the way the token bucket code worked it would drain the client queue quickly and then start running backfill/recovery ops which didn't drain that bucket as fast. This did not sit well with our VMs with heavy write loads. I wrote WPQ to dequeue each op priority based on the weight of the op rather than token bucket queue and showed that it proportionally dequeued ops based on the priority. It meant that sometimes higher priority ops would be blocked to run a lower priority op but no queue was ever starved from dequeunig an op like before. An op that had twice the priority of another op had twice the probability of being dequed. The op scheduler in Ceph actually consists of two queues, a strict priority queue and a TB/WPQ queue. The cut off refers to the op priority number that separates the strict priority queue from the WPQ or default token bucket. By setting it to high, you are telling Ceph to include the replication ops in the token bucket or WPQ rather than the strict queue and only allows very small ops that don't require disk access to be in the strict priority queue (heartbeats, Mon messages, OSD messages, etc) so that all the slow work is prioritized by the WPQ/TB queue. With this, we found that we didn't need QoS as all client now got a fair share of I/O instead of some clients being 'lucky' to land on a non-busy OSD and send many rep ops to a busy OSD who could only service replication ops and never any client ops. I also found that op priorities worked as expected. We could raise the number of backfill operations on an OSD and it would negligibly impact clients as it started using only idle capacity to do the backfill and prioritize client traffic. I assume that if you change the op priority of the different classes of ops, that it would work more predictably with WPQ, but I don't think that you can change it on the fly and would require an OSD reboot which I could not do at the time I tried. The WPQ did not prevent all blocked I/O, but what it did was prevent any single client from being blocked indefinitely. I saw latencies become very tight across all clients, instead of some clients having very good latency and other extremely poor latency, each client had statistically the same latency. No longer was the cluster limited by the slowest drive in the cluster, the OSD with the slow drive would now execute client ops sending rep ops to other OSD and helping to generate more load on a less loaded OSD which would then possibly reduce the load on the overloaded OSD (because now the idle OSD had other work to do other than just servicing client ops). This allowed the cluster to appropriately throttle clients by increasing latency on all clients in a more uniform manner. It allows the cluster to achieve 100% utilization at the same time. WPQ was planned to be the default scheduler, but I left the company I was working for shortly after getting it merged and my new company wasn't doing object storage so I wasn't there to see it become the default. I'm at a new company and again working with Ceph and have made it the default on our two large production clusters with great success. The client latencies and backfill pain that my co-workers experienced on a daily basis have been all alleviated since moving to WPQ. Honestly, WPQ may do what you need without having to try to configure QoS. ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Sat, Aug 24, 2019 at 2:08 AM Frank Schilder <frans@dtu.dk> wrote:
Hi Robert,
thanks for your reply. These are actually settings I found in cases I referred to with "other cases" in my mail. These settings could be a first step. Looking at the documentation, solving the overload problem might require some QoS settings I found below the description of "osd op queue" https://docs.ceph.com/docs/master/rados/configuration/osd-config-ref/#operat... .
I see some possibilities, but I'm not sure how to use these settings to enforce load dependent rate limiting on clients. As far as I can see, IOPs QoS does not take backlog into account, which would be important for distinguishing a burst from a sustained overload. In addition, this requires mClock, which is labelled experimental.
If anyone could shed some light on what possibilities currently exist beyond playing with "osd op queue" and "osd op queue cut off" that would be great. Also if there is some experience out there about this problem.
For example, would reducing "osd client op priority" have any effect? As far as I can see, this is only for weighting between recovery and client IO, not for priority of IO already in flight versus new client OPS.
Best regards,
================= Frank Schilder AIT Risø Campus Bygning 109, rum S14
________________________________________ From: Robert LeBlanc <robert@leblancnet.us> Sent: 23 August 2019 17:28 To: Frank Schilder Cc: ceph-users Subject: Re: [ceph-users] ceph fs crashes on simple fio test
The WPQ scheduler may help your clients back off when things get busy.
Put this in your ceph.conf and restart your OSDs. osd op queue = wpq osd op queue cut off = high ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
WPQ has been the default queue for quite some time now (Luminous?). However, the default cut off is low. I remember changing this in some early jewel (or kraken?) version to high and it helped a lot with the only cluster we had back then. We've been running all of our clusters with cut off high since then, any reason why this isn't the default? Paul -- Paul Emmerich Looking for help with your Ceph cluster? Contact us at https://croit.io croit GmbH Freseniusstr. 31h 81247 München www.croit.io Tel: +49 89 1896585 90 On Mon, Aug 26, 2019 at 6:21 PM Robert LeBlanc <robert@leblancnet.us> wrote:
Frank,
I wrote the wpq and the cut off code because the only scheduler at the time was not servicing other priorities under extreme load. The default op scheduler prioritized replication ops in the strict queue which meant as long as there were any ops from other OSDs for replication, no client or backfill ops would be serviced. Once the strict queue was empty then it would start dequeing client ops, but the way the token bucket code worked it would drain the client queue quickly and then start running backfill/recovery ops which didn't drain that bucket as fast. This did not sit well with our VMs with heavy write loads.
I wrote WPQ to dequeue each op priority based on the weight of the op rather than token bucket queue and showed that it proportionally dequeued ops based on the priority. It meant that sometimes higher priority ops would be blocked to run a lower priority op but no queue was ever starved from dequeunig an op like before. An op that had twice the priority of another op had twice the probability of being dequed. The op scheduler in Ceph actually consists of two queues, a strict priority queue and a TB/WPQ queue. The cut off refers to the op priority number that separates the strict priority queue from the WPQ or default token bucket. By setting it to high, you are telling Ceph to include the replication ops in the token bucket or WPQ rather than the strict queue and only allows very small ops that don't require disk access to be in the strict priority queue (heartbeats, Mon messages, OSD messages, etc) so that all the slow work is prioritized by the WPQ/TB queue.
With this, we found that we didn't need QoS as all client now got a fair share of I/O instead of some clients being 'lucky' to land on a non-busy OSD and send many rep ops to a busy OSD who could only service replication ops and never any client ops. I also found that op priorities worked as expected. We could raise the number of backfill operations on an OSD and it would negligibly impact clients as it started using only idle capacity to do the backfill and prioritize client traffic. I assume that if you change the op priority of the different classes of ops, that it would work more predictably with WPQ, but I don't think that you can change it on the fly and would require an OSD reboot which I could not do at the time I tried.
The WPQ did not prevent all blocked I/O, but what it did was prevent any single client from being blocked indefinitely. I saw latencies become very tight across all clients, instead of some clients having very good latency and other extremely poor latency, each client had statistically the same latency. No longer was the cluster limited by the slowest drive in the cluster, the OSD with the slow drive would now execute client ops sending rep ops to other OSD and helping to generate more load on a less loaded OSD which would then possibly reduce the load on the overloaded OSD (because now the idle OSD had other work to do other than just servicing client ops). This allowed the cluster to appropriately throttle clients by increasing latency on all clients in a more uniform manner. It allows the cluster to achieve 100% utilization at the same time.
WPQ was planned to be the default scheduler, but I left the company I was working for shortly after getting it merged and my new company wasn't doing object storage so I wasn't there to see it become the default. I'm at a new company and again working with Ceph and have made it the default on our two large production clusters with great success. The client latencies and backfill pain that my co-workers experienced on a daily basis have been all alleviated since moving to WPQ.
Honestly, WPQ may do what you need without having to try to configure QoS.
---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
On Sat, Aug 24, 2019 at 2:08 AM Frank Schilder <frans@dtu.dk> wrote:
Hi Robert,
thanks for your reply. These are actually settings I found in cases I referred to with "other cases" in my mail. These settings could be a first step. Looking at the documentation, solving the overload problem might require some QoS settings I found below the description of "osd op queue" https://docs.ceph.com/docs/master/rados/configuration/osd-config-ref/#operat... .
I see some possibilities, but I'm not sure how to use these settings to enforce load dependent rate limiting on clients. As far as I can see, IOPs QoS does not take backlog into account, which would be important for distinguishing a burst from a sustained overload. In addition, this requires mClock, which is labelled experimental.
If anyone could shed some light on what possibilities currently exist beyond playing with "osd op queue" and "osd op queue cut off" that would be great. Also if there is some experience out there about this problem.
For example, would reducing "osd client op priority" have any effect? As far as I can see, this is only for weighting between recovery and client IO, not for priority of IO already in flight versus new client OPS.
Best regards,
================= Frank Schilder AIT Risø Campus Bygning 109, rum S14
________________________________________ From: Robert LeBlanc <robert@leblancnet.us> Sent: 23 August 2019 17:28 To: Frank Schilder Cc: ceph-users Subject: Re: [ceph-users] ceph fs crashes on simple fio test
The WPQ scheduler may help your clients back off when things get busy.
Put this in your ceph.conf and restart your OSDs. osd op queue = wpq osd op queue cut off = high ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
_______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
High should be the default with WPQ. ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Mon, Aug 26, 2019 at 10:44 AM Paul Emmerich <paul.emmerich@croit.io> wrote:
WPQ has been the default queue for quite some time now (Luminous?).
However, the default cut off is low. I remember changing this in some early jewel (or kraken?) version to high and it helped a lot with the only cluster we had back then. We've been running all of our clusters with cut off high since then, any reason why this isn't the default?
Paul
-- Paul Emmerich
Looking for help with your Ceph cluster? Contact us at https://croit.io
croit GmbH Freseniusstr. 31h 81247 München www.croit.io Tel: +49 89 1896585 90
On Mon, Aug 26, 2019 at 6:21 PM Robert LeBlanc <robert@leblancnet.us> wrote:
Frank,
I wrote the wpq and the cut off code because the only scheduler at the
time was not servicing other priorities under extreme load. The default op scheduler prioritized replication ops in the strict queue which meant as long as there were any ops from other OSDs for replication, no client or backfill ops would be serviced. Once the strict queue was empty then it would start dequeing client ops, but the way the token bucket code worked it would drain the client queue quickly and then start running backfill/recovery ops which didn't drain that bucket as fast. This did not sit well with our VMs with heavy write loads.
I wrote WPQ to dequeue each op priority based on the weight of the op
rather than token bucket queue and showed that it proportionally dequeued ops based on the priority. It meant that sometimes higher priority ops would be blocked to run a lower priority op but no queue was ever starved from dequeunig an op like before. An op that had twice the priority of another op had twice the probability of being dequed. The op scheduler in Ceph actually consists of two queues, a strict priority queue and a TB/WPQ queue. The cut off refers to the op priority number that separates the strict priority queue from the WPQ or default token bucket. By setting it to high, you are telling Ceph to include the replication ops in the token bucket or WPQ rather than the strict queue and only allows very small ops that don't require disk access to be in the strict priority queue (heartbeats, Mon messages, OSD messages, etc) so that all the slow work is prioritized by the WPQ/TB queue.
With this, we found that we didn't need QoS as all client now got a fair
share of I/O instead of some clients being 'lucky' to land on a non-busy OSD and send many rep ops to a busy OSD who could only service replication ops and never any client ops. I also found that op priorities worked as expected. We could raise the number of backfill operations on an OSD and it would negligibly impact clients as it started using only idle capacity to do the backfill and prioritize client traffic. I assume that if you change the op priority of the different classes of ops, that it would work more predictably with WPQ, but I don't think that you can change it on the fly and would require an OSD reboot which I could not do at the time I tried.
The WPQ did not prevent all blocked I/O, but what it did was prevent any
single client from being blocked indefinitely. I saw latencies become very tight across all clients, instead of some clients having very good latency and other extremely poor latency, each client had statistically the same latency. No longer was the cluster limited by the slowest drive in the cluster, the OSD with the slow drive would now execute client ops sending rep ops to other OSD and helping to generate more load on a less loaded OSD which would then possibly reduce the load on the overloaded OSD (because now the idle OSD had other work to do other than just servicing client ops). This allowed the cluster to appropriately throttle clients by increasing latency on all clients in a more uniform manner. It allows the cluster to achieve 100% utilization at the same time.
WPQ was planned to be the default scheduler, but I left the company I
was working for shortly after getting it merged and my new company wasn't doing object storage so I wasn't there to see it become the default. I'm at a new company and again working with Ceph and have made it the default on our two large production clusters with great success. The client latencies and backfill pain that my co-workers experienced on a daily basis have been all alleviated since moving to WPQ.
Honestly, WPQ may do what you need without having to try to configure
QoS.
---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
On Sat, Aug 24, 2019 at 2:08 AM Frank Schilder <frans@dtu.dk> wrote:
Hi Robert,
thanks for your reply. These are actually settings I found in cases I
referred to with "other cases" in my mail. These settings could be a first step. Looking at the documentation, solving the overload problem might require some QoS settings I found below the description of "osd op queue" https://docs.ceph.com/docs/master/rados/configuration/osd-config-ref/#operat... .
I see some possibilities, but I'm not sure how to use these settings to
enforce load dependent rate limiting on clients. As far as I can see, IOPs QoS does not take backlog into account, which would be important for distinguishing a burst from a sustained overload. In addition, this requires mClock, which is labelled experimental.
If anyone could shed some light on what possibilities currently exist
beyond playing with "osd op queue" and "osd op queue cut off" that would be great. Also if there is some experience out there about this problem.
For example, would reducing "osd client op priority" have any effect?
As far as I can see, this is only for weighting between recovery and client IO, not for priority of IO already in flight versus new client OPS.
Best regards,
================= Frank Schilder AIT Risø Campus Bygning 109, rum S14
________________________________________ From: Robert LeBlanc <robert@leblancnet.us> Sent: 23 August 2019 17:28 To: Frank Schilder Cc: ceph-users Subject: Re: [ceph-users] ceph fs crashes on simple fio test
The WPQ scheduler may help your clients back off when things get busy.
Put this in your ceph.conf and restart your OSDs. osd op queue = wpq osd op queue cut off = high ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
_______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
If it is the default, then the documentation should be updated. [0] [0] https://docs.ceph.com/docs/master/rados/configuration/osd-config-ref/?highli... ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Mon, Aug 26, 2019 at 1:22 PM Robert LeBlanc <robert@leblancnet.us> wrote:
High should be the default with WPQ. ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
On Mon, Aug 26, 2019 at 10:44 AM Paul Emmerich <paul.emmerich@croit.io> wrote:
WPQ has been the default queue for quite some time now (Luminous?).
However, the default cut off is low. I remember changing this in some early jewel (or kraken?) version to high and it helped a lot with the only cluster we had back then. We've been running all of our clusters with cut off high since then, any reason why this isn't the default?
Paul
-- Paul Emmerich
Looking for help with your Ceph cluster? Contact us at https://croit.io
croit GmbH Freseniusstr. 31h 81247 München www.croit.io Tel: +49 89 1896585 90
On Mon, Aug 26, 2019 at 6:21 PM Robert LeBlanc <robert@leblancnet.us> wrote:
Frank,
I wrote the wpq and the cut off code because the only scheduler at the
time was not servicing other priorities under extreme load. The default op scheduler prioritized replication ops in the strict queue which meant as long as there were any ops from other OSDs for replication, no client or backfill ops would be serviced. Once the strict queue was empty then it would start dequeing client ops, but the way the token bucket code worked it would drain the client queue quickly and then start running backfill/recovery ops which didn't drain that bucket as fast. This did not sit well with our VMs with heavy write loads.
I wrote WPQ to dequeue each op priority based on the weight of the op
rather than token bucket queue and showed that it proportionally dequeued ops based on the priority. It meant that sometimes higher priority ops would be blocked to run a lower priority op but no queue was ever starved from dequeunig an op like before. An op that had twice the priority of another op had twice the probability of being dequed. The op scheduler in Ceph actually consists of two queues, a strict priority queue and a TB/WPQ queue. The cut off refers to the op priority number that separates the strict priority queue from the WPQ or default token bucket. By setting it to high, you are telling Ceph to include the replication ops in the token bucket or WPQ rather than the strict queue and only allows very small ops that don't require disk access to be in the strict priority queue (heartbeats, Mon messages, OSD messages, etc) so that all the slow work is prioritized by the WPQ/TB queue.
With this, we found that we didn't need QoS as all client now got a
fair share of I/O instead of some clients being 'lucky' to land on a non-busy OSD and send many rep ops to a busy OSD who could only service replication ops and never any client ops. I also found that op priorities worked as expected. We could raise the number of backfill operations on an OSD and it would negligibly impact clients as it started using only idle capacity to do the backfill and prioritize client traffic. I assume that if you change the op priority of the different classes of ops, that it would work more predictably with WPQ, but I don't think that you can change it on the fly and would require an OSD reboot which I could not do at the time I tried.
The WPQ did not prevent all blocked I/O, but what it did was prevent
any single client from being blocked indefinitely. I saw latencies become very tight across all clients, instead of some clients having very good latency and other extremely poor latency, each client had statistically the same latency. No longer was the cluster limited by the slowest drive in the cluster, the OSD with the slow drive would now execute client ops sending rep ops to other OSD and helping to generate more load on a less loaded OSD which would then possibly reduce the load on the overloaded OSD (because now the idle OSD had other work to do other than just servicing client ops). This allowed the cluster to appropriately throttle clients by increasing latency on all clients in a more uniform manner. It allows the cluster to achieve 100% utilization at the same time.
WPQ was planned to be the default scheduler, but I left the company I
was working for shortly after getting it merged and my new company wasn't doing object storage so I wasn't there to see it become the default. I'm at a new company and again working with Ceph and have made it the default on our two large production clusters with great success. The client latencies and backfill pain that my co-workers experienced on a daily basis have been all alleviated since moving to WPQ.
Honestly, WPQ may do what you need without having to try to configure
QoS.
---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
On Sat, Aug 24, 2019 at 2:08 AM Frank Schilder <frans@dtu.dk> wrote:
Hi Robert,
thanks for your reply. These are actually settings I found in cases I
referred to with "other cases" in my mail. These settings could be a first step. Looking at the documentation, solving the overload problem might require some QoS settings I found below the description of "osd op queue" https://docs.ceph.com/docs/master/rados/configuration/osd-config-ref/#operat... .
I see some possibilities, but I'm not sure how to use these settings
to enforce load dependent rate limiting on clients. As far as I can see, IOPs QoS does not take backlog into account, which would be important for distinguishing a burst from a sustained overload. In addition, this requires mClock, which is labelled experimental.
If anyone could shed some light on what possibilities currently exist
beyond playing with "osd op queue" and "osd op queue cut off" that would be great. Also if there is some experience out there about this problem.
For example, would reducing "osd client op priority" have any effect?
As far as I can see, this is only for weighting between recovery and client IO, not for priority of IO already in flight versus new client OPS.
Best regards,
================= Frank Schilder AIT Risø Campus Bygning 109, rum S14
________________________________________ From: Robert LeBlanc <robert@leblancnet.us> Sent: 23 August 2019 17:28 To: Frank Schilder Cc: ceph-users Subject: Re: [ceph-users] ceph fs crashes on simple fio test
The WPQ scheduler may help your clients back off when things get busy.
Put this in your ceph.conf and restart your OSDs. osd op queue = wpq osd op queue cut off = high ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
_______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
Hi Robert and Paul, I checked today and the default scheduler is WPQ with cut off low (I was using the defaults). I changed cut off to high in the config data base, but still need to restart all OSDs to apply the change. I'm not sure how much it will help though. Maybe heartbeats will get through despite the mess, which will be a plus in any case. My observation was, that not some but *all* OSDs were heavily overloaded by just one client doing aggressive IO. Following your explanations, I'm not yet convinced that the changed cut-off will limit the rate of client OPs accepted by the cluster. Well, I will try again after OSD restart and report back. Thanks for your help! Best regards, ================= Frank Schilder AIT Risø Campus Bygning 109, rum S14 ________________________________________ From: Robert LeBlanc <robert@leblancnet.us> Sent: 26 August 2019 22:24 To: Paul Emmerich Cc: Frank Schilder; ceph-users Subject: Re: [ceph-users] Re: ceph fs crashes on simple fio test If it is the default, then the documentation should be updated. [0] [0] https://docs.ceph.com/docs/master/rados/configuration/osd-config-ref/?highli... ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Mon, Aug 26, 2019 at 1:22 PM Robert LeBlanc <robert@leblancnet.us<mailto:robert@leblancnet.us>> wrote: High should be the default with WPQ. ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Mon, Aug 26, 2019 at 10:44 AM Paul Emmerich <paul.emmerich@croit.io<mailto:paul.emmerich@croit.io>> wrote: WPQ has been the default queue for quite some time now (Luminous?). However, the default cut off is low. I remember changing this in some early jewel (or kraken?) version to high and it helped a lot with the only cluster we had back then. We've been running all of our clusters with cut off high since then, any reason why this isn't the default? Paul -- Paul Emmerich Looking for help with your Ceph cluster? Contact us at https://croit.io croit GmbH Freseniusstr. 31h 81247 München www.croit.io<http://www.croit.io> Tel: +49 89 1896585 90 On Mon, Aug 26, 2019 at 6:21 PM Robert LeBlanc <robert@leblancnet.us<mailto:robert@leblancnet.us>> wrote:
Frank,
I wrote the wpq and the cut off code because the only scheduler at the time was not servicing other priorities under extreme load. The default op scheduler prioritized replication ops in the strict queue which meant as long as there were any ops from other OSDs for replication, no client or backfill ops would be serviced. Once the strict queue was empty then it would start dequeing client ops, but the way the token bucket code worked it would drain the client queue quickly and then start running backfill/recovery ops which didn't drain that bucket as fast. This did not sit well with our VMs with heavy write loads.
I wrote WPQ to dequeue each op priority based on the weight of the op rather than token bucket queue and showed that it proportionally dequeued ops based on the priority. It meant that sometimes higher priority ops would be blocked to run a lower priority op but no queue was ever starved from dequeunig an op like before. An op that had twice the priority of another op had twice the probability of being dequed. The op scheduler in Ceph actually consists of two queues, a strict priority queue and a TB/WPQ queue. The cut off refers to the op priority number that separates the strict priority queue from the WPQ or default token bucket. By setting it to high, you are telling Ceph to include the replication ops in the token bucket or WPQ rather than the strict queue and only allows very small ops that don't require disk access to be in the strict priority queue (heartbeats, Mon messages, OSD messages, etc) so that all the slow work is prioritized by the WPQ/TB queue.
With this, we found that we didn't need QoS as all client now got a fair share of I/O instead of some clients being 'lucky' to land on a non-busy OSD and send many rep ops to a busy OSD who could only service replication ops and never any client ops. I also found that op priorities worked as expected. We could raise the number of backfill operations on an OSD and it would negligibly impact clients as it started using only idle capacity to do the backfill and prioritize client traffic. I assume that if you change the op priority of the different classes of ops, that it would work more predictably with WPQ, but I don't think that you can change it on the fly and would require an OSD reboot which I could not do at the time I tried.
The WPQ did not prevent all blocked I/O, but what it did was prevent any single client from being blocked indefinitely. I saw latencies become very tight across all clients, instead of some clients having very good latency and other extremely poor latency, each client had statistically the same latency. No longer was the cluster limited by the slowest drive in the cluster, the OSD with the slow drive would now execute client ops sending rep ops to other OSD and helping to generate more load on a less loaded OSD which would then possibly reduce the load on the overloaded OSD (because now the idle OSD had other work to do other than just servicing client ops). This allowed the cluster to appropriately throttle clients by increasing latency on all clients in a more uniform manner. It allows the cluster to achieve 100% utilization at the same time.
WPQ was planned to be the default scheduler, but I left the company I was working for shortly after getting it merged and my new company wasn't doing object storage so I wasn't there to see it become the default. I'm at a new company and again working with Ceph and have made it the default on our two large production clusters with great success. The client latencies and backfill pain that my co-workers experienced on a daily basis have been all alleviated since moving to WPQ.
Honestly, WPQ may do what you need without having to try to configure QoS.
---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
On Sat, Aug 24, 2019 at 2:08 AM Frank Schilder <frans@dtu.dk<mailto:frans@dtu.dk>> wrote:
Hi Robert,
thanks for your reply. These are actually settings I found in cases I referred to with "other cases" in my mail. These settings could be a first step. Looking at the documentation, solving the overload problem might require some QoS settings I found below the description of "osd op queue" https://docs.ceph.com/docs/master/rados/configuration/osd-config-ref/#operat... .
I see some possibilities, but I'm not sure how to use these settings to enforce load dependent rate limiting on clients. As far as I can see, IOPs QoS does not take backlog into account, which would be important for distinguishing a burst from a sustained overload. In addition, this requires mClock, which is labelled experimental.
If anyone could shed some light on what possibilities currently exist beyond playing with "osd op queue" and "osd op queue cut off" that would be great. Also if there is some experience out there about this problem.
For example, would reducing "osd client op priority" have any effect? As far as I can see, this is only for weighting between recovery and client IO, not for priority of IO already in flight versus new client OPS.
Best regards,
================= Frank Schilder AIT Risø Campus Bygning 109, rum S14
________________________________________ From: Robert LeBlanc <robert@leblancnet.us<mailto:robert@leblancnet.us>> Sent: 23 August 2019 17:28 To: Frank Schilder Cc: ceph-users Subject: Re: [ceph-users] ceph fs crashes on simple fio test
The WPQ scheduler may help your clients back off when things get busy.
Put this in your ceph.conf and restart your OSDs. osd op queue = wpq osd op queue cut off = high ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
_______________________________________________ ceph-users mailing list -- ceph-users@ceph.io<mailto:ceph-users@ceph.io> To unsubscribe send an email to ceph-users-leave@ceph.io<mailto:ceph-users-leave@ceph.io>
Hi Robert and Paul, a quick update. I restarted all OSDs today to activate osd_op_queue_cut_off=high. I run into a serious problem right after that. The standby-replay MDS daemons started missing mon beacons and were killed by the mons: ceph-01 journal: debug [...] log [INF] Standby daemon mds.ceph-12 is not responding, dropping it Apparently, one also needs to set this on the MDSes: ceph config set mds osd_op_queue_cut_off high This also requires a restart to become active. After that, everything seems to work again. The question that remains is: Do I need to change this for any other daemon? I will repeat the performance tests later and post results. On observation is, that an MDS fail-over was a factor of 5-10 faster with the cut-off set to high. Best regards, ================= Frank Schilder AIT Risø Campus Bygning 109, rum S14
Hi Robert and Paul, sad news. I did a 5 seconds single thread test after setting osd_op_queue_cut_off=high on all OSDs and MDSs. Here the current settings: [root@ceph-01 ~]# ceph config show osd.0 NAME VALUE SOURCE OVERRIDES IGNORES bluestore_compression_min_blob_size_hdd 262144 file bluestore_compression_mode aggressive file cluster_addr 192.168.16.68:0/0 override cluster_network 192.168.16.0/20 file crush_location host=c-04-A file daemonize false override err_to_syslog true file keyring $osd_data/keyring default leveldb_log default mgr_initial_modules balancer dashboard file mon_allow_pool_delete false file mon_pool_quota_crit_threshold 90 file mon_pool_quota_warn_threshold 70 file osd_journal_size 4096 file osd_max_backfills 3 mon osd_op_queue_cut_off high mon osd_pool_default_flag_nodelete true file osd_recovery_max_active 8 mon osd_recovery_sleep 0.050000 mon public_addr 192.168.32.68:0/0 override public_network 192.168.32.0/19 file rbd_default_features 61 default setgroup disk cmdline setuser ceph cmdline [root@ceph-01 ~]# ceph config get osd.0 osd_op_queue wpq Unfortunately, the problem is not resolved. The fio job script is: ===================== [global] name=fio-rand-write filename_format=fio-$jobname-${HOSTNAME}-$jobnum-$filenum rw=randwrite bs=4K numjobs=1 time_based=1 runtime=5 [file1] size=100G ioengine=sync ===================== That's a random write test on a 100G file with write size 4K. Note that fio uses "direct=0" by default. Using "direct=1" is absolutely fine. Running this short burst of load, I already get the cluster unhealthy: cluster log: 2019-09-03 20:00:00.000160 [INF] overall HEALTH_OK 2019-09-03 20:08:36.450527 [WRN] Health check failed: 1 MDSs report slow metadata IOs (MDS_SLOW_METADATA_IO) 2019-09-03 20:08:59.867124 [INF] MDS health message cleared (mds.0): 2 slow metadata IOs are blocked > 30 secs, oldest blocked for 49 secs 2019-09-03 20:09:00.373050 [INF] Health check cleared: MDS_SLOW_METADATA_IO (was: 1 MDSs report slow metadata IOs) 2019-09-03 20:09:00.373094 [INF] Cluster is now healthy /var/log/messages: loads of these (all OSDs!) Sep 3 20:08:39 ceph-09 journal: 2019-09-03 20:08:39.269 7f6a3d63c700 -1 osd.161 10411 get_health_metrics reporting 354 slow ops, oldest is osd_op(client.4497435.0:38244 5.f7s0 5:ef9f1be4:::100010ed9bd.0000390c:head [write 8192~4096,write 32768~4096,write 139264~4096,write 172032~4096,write 270336~4096,write 512000~4096,write 688128~4096,write 876544~4096,write 1048576~4096,write 1257472~4096,write 1425408~4096,write 1445888~4096,write 1503232~4096,write 1552384~4096,write 1716224~4096,write 1765376~4096] snapc 12e=[] ondisk+write+known_if_redirected e10411) It looks like the MDS is pushing waaaayyy too many requests onto the HDDs instead of throttling the client. An ordinary user should not have so much power in his hands. This makes it trivial to destroy a ceph cluster. This very short fio test is probably sufficient to reproduce the issue on any test cluster. Should I open an issue? Best regards, ================= Frank Schilder AIT Risø Campus Bygning 109, rum S14 ________________________________________ From: Frank Schilder <frans@dtu.dk> Sent: 30 August 2019 12:56 To: Robert LeBlanc; Paul Emmerich Cc: ceph-users Subject: [ceph-users] Re: ceph fs crashes on simple fio test Hi Robert and Paul, a quick update. I restarted all OSDs today to activate osd_op_queue_cut_off=high. I run into a serious problem right after that. The standby-replay MDS daemons started missing mon beacons and were killed by the mons: ceph-01 journal: debug [...] log [INF] Standby daemon mds.ceph-12 is not responding, dropping it Apparently, one also needs to set this on the MDSes: ceph config set mds osd_op_queue_cut_off high This also requires a restart to become active. After that, everything seems to work again. The question that remains is: Do I need to change this for any other daemon? I will repeat the performance tests later and post results. On observation is, that an MDS fail-over was a factor of 5-10 faster with the cut-off set to high. Best regards, ================= Frank Schilder AIT Risø Campus Bygning 109, rum S14 _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
On Tue, Sep 3, 2019 at 11:33 AM Frank Schilder <frans@dtu.dk> wrote:
Hi Robert and Paul,
sad news. I did a 5 seconds single thread test after setting osd_op_queue_cut_off=high on all OSDs and MDSs. Here the current settings:
[root@ceph-01 ~]# ceph config show osd.0 NAME VALUE SOURCE OVERRIDES IGNORES bluestore_compression_min_blob_size_hdd 262144 file
bluestore_compression_mode aggressive file
cluster_addr 192.168.16.68:0/0 override
cluster_network 192.168.16.0/20 file
crush_location host=c-04-A file
daemonize false override
err_to_syslog true file
keyring $osd_data/keyring default
leveldb_log default
mgr_initial_modules balancer dashboard file
mon_allow_pool_delete false file
mon_pool_quota_crit_threshold 90 file
mon_pool_quota_warn_threshold 70 file
osd_journal_size 4096 file
osd_max_backfills 3 mon
osd_op_queue_cut_off high mon
osd_pool_default_flag_nodelete true file
osd_recovery_max_active 8 mon
osd_recovery_sleep 0.050000 mon
public_addr 192.168.32.68:0/0 override
public_network 192.168.32.0/19 file
rbd_default_features 61 default
setgroup disk cmdline
setuser ceph cmdline
[root@ceph-01 ~]# ceph config get osd.0 osd_op_queue wpq
Unfortunately, the problem is not resolved. The fio job script is:
===================== [global] name=fio-rand-write filename_format=fio-$jobname-${HOSTNAME}-$jobnum-$filenum rw=randwrite bs=4K numjobs=1 time_based=1 runtime=5
[file1] size=100G ioengine=sync =====================
That's a random write test on a 100G file with write size 4K. Note that fio uses "direct=0" by default. Using "direct=1" is absolutely fine.
Running this short burst of load, I already get the cluster unhealthy:
cluster log:
2019-09-03 20:00:00.000160 [INF] overall HEALTH_OK 2019-09-03 20:08:36.450527 [WRN] Health check failed: 1 MDSs report slow metadata IOs (MDS_SLOW_METADATA_IO) 2019-09-03 20:08:59.867124 [INF] MDS health message cleared (mds.0): 2 slow metadata IOs are blocked > 30 secs, oldest blocked for 49 secs 2019-09-03 20:09:00.373050 [INF] Health check cleared: MDS_SLOW_METADATA_IO (was: 1 MDSs report slow metadata IOs) 2019-09-03 20:09:00.373094 [INF] Cluster is now healthy
/var/log/messages: loads of these (all OSDs!)
Sep 3 20:08:39 ceph-09 journal: 2019-09-03 20:08:39.269 7f6a3d63c700 -1 osd.161 10411 get_health_metrics reporting 354 slow ops, oldest is osd_op(client.4497435.0:38244 5.f7s0 5:ef9f1be4:::100010ed9bd.0000390c:head [write 8192~4096,write 32768~4096,write 139264~4096,write 172032~4096,write 270336~4096,write 512000~4096,write 688128~4096,write 876544~4096,write 1048576~4096,write 1257472~4096,write 1425408~4096,write 1445888~4096,write 1503232~4096,write 1552384~4096,write 1716224~4096,write 1765376~4096] snapc 12e=[] ondisk+write+known_if_redirected e10411)
It looks like the MDS is pushing waaaayyy too many requests onto the HDDs instead of throttling the client.
An ordinary user should not have so much power in his hands. This makes it trivial to destroy a ceph cluster.
This very short fio test is probably sufficient to reproduce the issue on any test cluster. Should I open an issue?
Best regards,
Are your metadata pools on SSD, or HDD? Usually for us, as long as the blocked I/O fluctuates and goes up and down, the cluster run fine even with the warnings. Usually on an idle cluster a client will send a bunch of data which fills up the queues, then the HDDs have to work through them, at that point the client realizes that the storage is 'slow' and starts throttling the traffic and will then match the speed at which the HDDs can perform the work. If you run the job for a long time, are you still seeing the trimming errors, or just a steady rise in blocked IO on the OSDs without any drops in count? What about the client, does it have a fairly even distribution of latencies, or does it have a lot that are just really long? ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
Thanks for this thread -- I'd forgotten all about high/low. On one congested rbd cluster it just dropped our 4kB object write latency from ~150ms to ~40ms :-) Who wants to send the PR? -- sounds like an easy way to get on the next t-shirt. -- dan On Mon, Aug 26, 2019 at 10:24 PM Robert LeBlanc <robert@leblancnet.us> wrote:
High should be the default with WPQ. ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
On Mon, Aug 26, 2019 at 10:44 AM Paul Emmerich <paul.emmerich@croit.io> wrote:
WPQ has been the default queue for quite some time now (Luminous?).
However, the default cut off is low. I remember changing this in some early jewel (or kraken?) version to high and it helped a lot with the only cluster we had back then. We've been running all of our clusters with cut off high since then, any reason why this isn't the default?
Paul
-- Paul Emmerich
Looking for help with your Ceph cluster? Contact us at https://croit.io
croit GmbH Freseniusstr. 31h 81247 München www.croit.io Tel: +49 89 1896585 90
On Mon, Aug 26, 2019 at 6:21 PM Robert LeBlanc <robert@leblancnet.us> wrote:
Frank,
I wrote the wpq and the cut off code because the only scheduler at the time was not servicing other priorities under extreme load. The default op scheduler prioritized replication ops in the strict queue which meant as long as there were any ops from other OSDs for replication, no client or backfill ops would be serviced. Once the strict queue was empty then it would start dequeing client ops, but the way the token bucket code worked it would drain the client queue quickly and then start running backfill/recovery ops which didn't drain that bucket as fast. This did not sit well with our VMs with heavy write loads.
I wrote WPQ to dequeue each op priority based on the weight of the op rather than token bucket queue and showed that it proportionally dequeued ops based on the priority. It meant that sometimes higher priority ops would be blocked to run a lower priority op but no queue was ever starved from dequeunig an op like before. An op that had twice the priority of another op had twice the probability of being dequed. The op scheduler in Ceph actually consists of two queues, a strict priority queue and a TB/WPQ queue. The cut off refers to the op priority number that separates the strict priority queue from the WPQ or default token bucket. By setting it to high, you are telling Ceph to include the replication ops in the token bucket or WPQ rather than the strict queue and only allows very small ops that don't require disk access to be in the strict priority queue (heartbeats, Mon messages, OSD messages, etc) so that all the slow work is prioritized by the WPQ/TB queue.
With this, we found that we didn't need QoS as all client now got a fair share of I/O instead of some clients being 'lucky' to land on a non-busy OSD and send many rep ops to a busy OSD who could only service replication ops and never any client ops. I also found that op priorities worked as expected. We could raise the number of backfill operations on an OSD and it would negligibly impact clients as it started using only idle capacity to do the backfill and prioritize client traffic. I assume that if you change the op priority of the different classes of ops, that it would work more predictably with WPQ, but I don't think that you can change it on the fly and would require an OSD reboot which I could not do at the time I tried.
The WPQ did not prevent all blocked I/O, but what it did was prevent any single client from being blocked indefinitely. I saw latencies become very tight across all clients, instead of some clients having very good latency and other extremely poor latency, each client had statistically the same latency. No longer was the cluster limited by the slowest drive in the cluster, the OSD with the slow drive would now execute client ops sending rep ops to other OSD and helping to generate more load on a less loaded OSD which would then possibly reduce the load on the overloaded OSD (because now the idle OSD had other work to do other than just servicing client ops). This allowed the cluster to appropriately throttle clients by increasing latency on all clients in a more uniform manner. It allows the cluster to achieve 100% utilization at the same time.
WPQ was planned to be the default scheduler, but I left the company I was working for shortly after getting it merged and my new company wasn't doing object storage so I wasn't there to see it become the default. I'm at a new company and again working with Ceph and have made it the default on our two large production clusters with great success. The client latencies and backfill pain that my co-workers experienced on a daily basis have been all alleviated since moving to WPQ.
Honestly, WPQ may do what you need without having to try to configure QoS.
---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
On Sat, Aug 24, 2019 at 2:08 AM Frank Schilder <frans@dtu.dk> wrote:
Hi Robert,
thanks for your reply. These are actually settings I found in cases I referred to with "other cases" in my mail. These settings could be a first step. Looking at the documentation, solving the overload problem might require some QoS settings I found below the description of "osd op queue" https://docs.ceph.com/docs/master/rados/configuration/osd-config-ref/#operat... .
I see some possibilities, but I'm not sure how to use these settings to enforce load dependent rate limiting on clients. As far as I can see, IOPs QoS does not take backlog into account, which would be important for distinguishing a burst from a sustained overload. In addition, this requires mClock, which is labelled experimental.
If anyone could shed some light on what possibilities currently exist beyond playing with "osd op queue" and "osd op queue cut off" that would be great. Also if there is some experience out there about this problem.
For example, would reducing "osd client op priority" have any effect? As far as I can see, this is only for weighting between recovery and client IO, not for priority of IO already in flight versus new client OPS.
Best regards,
================= Frank Schilder AIT Risø Campus Bygning 109, rum S14
________________________________________ From: Robert LeBlanc <robert@leblancnet.us> Sent: 23 August 2019 17:28 To: Frank Schilder Cc: ceph-users Subject: Re: [ceph-users] ceph fs crashes on simple fio test
The WPQ scheduler may help your clients back off when things get busy.
Put this in your ceph.conf and restart your OSDs. osd op queue = wpq osd op queue cut off = high ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
_______________________________________________ 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)
-
Dan van der Ster
-
DHilsbos＠performair.com
-
Frank Schilder
-
Paul Emmerich
-
Robert LeBlanc