Re: CephFS constant high write I/O to the metadata pool
Hi - mostly as a note to future me and if anyone else looking for the same issue... I finally solved this a couple of months ago. No idea what is wrong with Ceph but the root cause that was triggering this MDS issue was that I had several workstations and a couple servers where the updatedb of "locate" was getting run by daily cron exactly the same time every night causing high momentary strain on the MDS which then somehow screwed up the metadata caching and flushing creating this cumulative write io. The thing to note here is that there's a difference with "locate" and "mlocate" packages. The default config (on Ubuntu atleast) of updatedb for "mlocate" does skip scanning cephfs filesystems but not so for "locate" which happily ventures onto all of your cephfs mounts :| --------------------------- Olli Rajala - Lead TD Anima Vitae Ltd. www.anima.fi --------------------------- On Wed, Dec 14, 2022 at 7:41 PM Olli Rajala <olli.rajala@anima.fi> wrote:
Hi,
One thing I now noticed in the mds logs is that there's a ton of entries like this: 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache projecting to [d345,d346] n(v1638 rc2022-12-11T18:20:49.317400+0200 b787972591 694=484+210) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache result [d345,d346] n(v1638 rc2022-12-11T18:20:49.321400+0200 b787972591 695=484+211) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache projecting to [d343,d344] n(v1638 rc2022-12-11T18:20:49.317400+0200 b787972591 694=484+210) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache result [d343,d344] n(v1638 rc2022-12-11T18:20:49.321400+0200 b787972591 695=484+211) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache projecting to [d341,d342] n(v1638 rc2022-12-11T18:20:49.317400+0200 b787972591 694=484+210) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache result [d341,d342] n(v1638 rc2022-12-11T18:20:49.321400+0200 b787972591 695=484+211) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache projecting to [d33f,d340] n(v1638 rc2022-12-11T18:20:49.317400+0200 b787972591 694=484+210) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache result [d33f,d340] n(v1638 rc2022-12-11T18:20:49.321400+0200 b787972591 695=484+211) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache projecting to [d33d,d33e] n(v1638 rc2022-12-11T18:20:49.317400+0200 b787972591 694=484+210) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache result [d33d,d33e] n(v1638 rc2022-12-11T18:20:49.321400+0200 b787972591 695=484+211)
...and after dropping the caches considerably less of those - normal, abnormal, typical, atypical? ...or is that just something that starts happening after the cache gets filled?
Tnx, --------------------------- Olli Rajala - Lead TD Anima Vitae Ltd. www.anima.fi ---------------------------
On Sun, Dec 11, 2022 at 9:07 PM Olli Rajala <olli.rajala@anima.fi> wrote:
Hi,
I'm still totally lost with this issue. And now lately I've had a couple of incidents where the write bw has suddenly jumped to even crazier levels. See the graph here: https://gist.github.com/olliRJL/3e97e15a37e8e801a785a1bd5358120d
The points where it drops to something manageable again are when I have dropped the mds caches. Usually after the drop there is steady rise but now these sudden jumps are something new and even more scary :E
Here's a fresh 2sec level 20 mds log: https://gist.github.com/olliRJL/074bec65787085e70db8af0ec35f8148
Any help and ideas greatly appreciated. Is there any tool or procedure to safely check or rebuild the mds data? ...if this behaviour could be caused by some hidden issue with the data itself.
Tnx, --------------------------- Olli Rajala - Lead TD Anima Vitae Ltd. www.anima.fi ---------------------------
On Fri, Nov 11, 2022 at 9:14 AM Venky Shankar <vshankar@redhat.com> wrote:
On Fri, Nov 11, 2022 at 3:06 AM Olli Rajala <olli.rajala@anima.fi> wrote:
Hi Venky,
I have indeed observed the output of the different sections of perf
dump like so:
watch -n 1 ceph tell mds.`hostname` perf dump objecter watch -n 1 ceph tell mds.`hostname` perf dump mds_cache ...etc...
...but without any proper understanding of what is a normal rate for some number to go up it's really difficult to make anything from that.
btw - is there some convenient way to capture this kind of temporal output for others to view. Sure, I could just dump once a second to a file or sequential files but is there some tool or convention that is easy to look at and analyze?
Not really - you'd have to do it yourself.
Tnx, --------------------------- Olli Rajala - Lead TD Anima Vitae Ltd. www.anima.fi ---------------------------
On Thu, Nov 10, 2022 at 8:18 AM Venky Shankar <vshankar@redhat.com>
Hi Olli,
On Mon, Oct 17, 2022 at 1:08 PM Olli Rajala <olli.rajala@anima.fi>
wrote:
Hi Patrick,
With "objecter_ops" did you mean "ceph tell mds.pve-core-1 ops"
and/or
"ceph tell mds.pve-core-1 objecter_requests"? Both these show very few requests/ops - many times just returning empty lists. I'm pretty sure that this I/O isn't generated by any clients - I've earlier tried to isolate this by shutting down all cephfs clients and this didn't have any noticeable effect.
I tried to watch what is going on with that "perf dump" but to be honest all I can see is some numbers going up in the different sections :) ...don't have a clue what to focus on and how to interpret that.
Here's a perf dump if you or anyone could make something out of
https://gist.github.com/olliRJL/43c10173aafd82be22c080a9cd28e673
You'd need to capture this over a period of time to see what ops might be going through and what the mds is doing.
Tnx! o.
--------------------------- Olli Rajala - Lead TD Anima Vitae Ltd. www.anima.fi ---------------------------
On Fri, Oct 14, 2022 at 8:32 PM Patrick Donnelly <
wrote:
> Hello Olli, > > On Thu, Oct 13, 2022 at 5:01 AM Olli Rajala <olli.rajala@anima.fi> wrote: > > > > Hi, > > > > I'm seeing constant 25-50MB/s writes to the metadata pool even when all > > clients and the cluster is idling and in clean state. This surely can't > be > > normal? > > > > There's no apparent issues with the performance of the cluster but this > > write rate seems excessive and I don't know where to look for
wrote: that: pdonnell@redhat.com> the
> culprit. > > > > The setup is Ceph 16.2.9 running in hyperconverged 3 node core cluster > and > > 6 hdd osd nodes. > > > > Here's typical status when pretty much all clients are idling. Most of > that > > write bandwidth and maybe fifth of the write iops is hitting the > > metadata pool. > > > > >
> > root@pve-core-1:~# ceph -s > > cluster: > > id: 2088b4b1-8de1-44d4-956e-aa3d3afff77f > > health: HEALTH_OK > > > > services: > > mon: 3 daemons, quorum pve-core-1,pve-core-2,pve-core-3 (age 2w) > > mgr: pve-core-1(active, since 4w), standbys: pve-core-2, pve-core-3 > > mds: 1/1 daemons up, 2 standby > > osd: 48 osds: 48 up (since 5h), 48 in (since 4M) > > > > data: > > volumes: 1/1 healthy > > pools: 10 pools, 625 pgs > > objects: 70.06M objects, 46 TiB > > usage: 95 TiB used, 182 TiB / 278 TiB avail > > pgs: 625 active+clean > > > > io: > > client: 45 KiB/s rd, 38 MiB/s wr, 6 op/s rd, 287 op/s wr > > >
> > > > Here's some daemonperf dump: > > > > >
> > root@pve-core-1:~# ceph daemonperf mds.`hostname -s` > > > ----------------------------------------mds----------------------------------------- > > --mds_cache--- ------mds_log------ -mds_mem- -------mds_server------- > mds_ > > -----objecter------ purg > > req rlat fwd inos caps exi imi hifc crev cgra ctru cfsa cfa hcc > hccd > > hccr prcr|stry recy recd|subm evts segs repl|ino dn |hcr hcs hsr cre > > cat |sess|actv rd wr rdwr|purg| > > 40 0 0 767k 78k 0 0 0 1 6 1 0 0 5 5 > > 3 7 |1.1k 0 0 | 17 3.7k 134 0 |767k 767k| 40 5 0 0 > > 0 |110 | 4 2 21 0 | 2 > > 57 2 0 767k 78k 0 0 0 3 16 3 0 0 11 11 > > 0 17 |1.1k 0 0 | 45 3.7k 137 0 |767k 767k| 57 8 0 0 > > 0 |110 | 0 2 28 0 | 4 > > 57 4 0 767k 78k 0 0 0 4 34 4 0 0 34 33 > > 2 26 |1.0k 0 0 |134 3.9k 139 0 |767k 767k| 57 13 0 0 > > 0 |110 | 0 2 112 0 | 19 > > 67 3 0 767k 78k 0 0 0 6 32 6 0 0 22 22 > > 0 32 |1.1k 0 0 | 78 3.9k 141 0 |767k 768k| 67 4 0 0 > > 0 |110 | 0 2 56 0 | 2 > > >
> > Any ideas where to look at? > > Check the perf dump output of the mds: > > ceph tell mds.<fs_name>:0 perf dump > > over a period of time to identify what's going on. You can also look > at the objecter_ops (another tell command) for the MDS. > > -- > Patrick Donnelly, Ph.D. > He / Him / His > Principal Software Engineer > Red Hat, Inc. > GPG: 19F28A586F808C2402351B93C3301A3E258DD79D > > _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
-- Cheers, Venky
-- Cheers, Venky
This was common in the NFS days, and some Linux distribution deliberately slew the execution time. find over an NFS mount was a sure-fire way to horque the server. (e.g. Convex C1) IMHO since the tool relies on a static index it isn't very useful, and I routinely remove any variant from my systems. ymmv
On Jul 2, 2024, at 10:20, Olli Rajala <olli.rajala@anima.fi> wrote:
Hi - mostly as a note to future me and if anyone else looking for the same issue...
I finally solved this a couple of months ago. No idea what is wrong with Ceph but the root cause that was triggering this MDS issue was that I had several workstations and a couple servers where the updatedb of "locate" was getting run by daily cron exactly the same time every night causing high momentary strain on the MDS which then somehow screwed up the metadata caching and flushing creating this cumulative write io.
The thing to note here is that there's a difference with "locate" and "mlocate" packages. The default config (on Ubuntu atleast) of updatedb for "mlocate" does skip scanning cephfs filesystems but not so for "locate" which happily ventures onto all of your cephfs mounts :|
--------------------------- Olli Rajala - Lead TD Anima Vitae Ltd. www.anima.fi ---------------------------
On Wed, Dec 14, 2022 at 7:41 PM Olli Rajala <olli.rajala@anima.fi> wrote:
Hi,
One thing I now noticed in the mds logs is that there's a ton of entries like this: 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache projecting to [d345,d346] n(v1638 rc2022-12-11T18:20:49.317400+0200 b787972591 694=484+210) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache result [d345,d346] n(v1638 rc2022-12-11T18:20:49.321400+0200 b787972591 695=484+211) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache projecting to [d343,d344] n(v1638 rc2022-12-11T18:20:49.317400+0200 b787972591 694=484+210) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache result [d343,d344] n(v1638 rc2022-12-11T18:20:49.321400+0200 b787972591 695=484+211) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache projecting to [d341,d342] n(v1638 rc2022-12-11T18:20:49.317400+0200 b787972591 694=484+210) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache result [d341,d342] n(v1638 rc2022-12-11T18:20:49.321400+0200 b787972591 695=484+211) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache projecting to [d33f,d340] n(v1638 rc2022-12-11T18:20:49.317400+0200 b787972591 694=484+210) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache result [d33f,d340] n(v1638 rc2022-12-11T18:20:49.321400+0200 b787972591 695=484+211) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache projecting to [d33d,d33e] n(v1638 rc2022-12-11T18:20:49.317400+0200 b787972591 694=484+210) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache result [d33d,d33e] n(v1638 rc2022-12-11T18:20:49.321400+0200 b787972591 695=484+211)
...and after dropping the caches considerably less of those - normal, abnormal, typical, atypical? ...or is that just something that starts happening after the cache gets filled?
Tnx, --------------------------- Olli Rajala - Lead TD Anima Vitae Ltd. www.anima.fi ---------------------------
On Sun, Dec 11, 2022 at 9:07 PM Olli Rajala <olli.rajala@anima.fi> wrote:
Hi,
I'm still totally lost with this issue. And now lately I've had a couple of incidents where the write bw has suddenly jumped to even crazier levels. See the graph here: https://gist.github.com/olliRJL/3e97e15a37e8e801a785a1bd5358120d
The points where it drops to something manageable again are when I have dropped the mds caches. Usually after the drop there is steady rise but now these sudden jumps are something new and even more scary :E
Here's a fresh 2sec level 20 mds log: https://gist.github.com/olliRJL/074bec65787085e70db8af0ec35f8148
Any help and ideas greatly appreciated. Is there any tool or procedure to safely check or rebuild the mds data? ...if this behaviour could be caused by some hidden issue with the data itself.
Tnx, --------------------------- Olli Rajala - Lead TD Anima Vitae Ltd. www.anima.fi ---------------------------
On Fri, Nov 11, 2022 at 9:14 AM Venky Shankar <vshankar@redhat.com> wrote:
On Fri, Nov 11, 2022 at 3:06 AM Olli Rajala <olli.rajala@anima.fi> wrote:
Hi Venky,
I have indeed observed the output of the different sections of perf
dump like so:
watch -n 1 ceph tell mds.`hostname` perf dump objecter watch -n 1 ceph tell mds.`hostname` perf dump mds_cache ...etc...
...but without any proper understanding of what is a normal rate for some number to go up it's really difficult to make anything from that.
btw - is there some convenient way to capture this kind of temporal output for others to view. Sure, I could just dump once a second to a file or sequential files but is there some tool or convention that is easy to look at and analyze?
Not really - you'd have to do it yourself.
Tnx, --------------------------- Olli Rajala - Lead TD Anima Vitae Ltd. www.anima.fi ---------------------------
On Thu, Nov 10, 2022 at 8:18 AM Venky Shankar <vshankar@redhat.com>
Hi Olli,
On Mon, Oct 17, 2022 at 1:08 PM Olli Rajala <olli.rajala@anima.fi>
wrote:
> > Hi Patrick, > > With "objecter_ops" did you mean "ceph tell mds.pve-core-1 ops" and/or > "ceph tell mds.pve-core-1 objecter_requests"? Both these show very few > requests/ops - many times just returning empty lists. I'm pretty sure that > this I/O isn't generated by any clients - I've earlier tried to isolate > this by shutting down all cephfs clients and this didn't have any > noticeable effect. > > I tried to watch what is going on with that "perf dump" but to be honest > all I can see is some numbers going up in the different sections :) > ...don't have a clue what to focus on and how to interpret that. > > Here's a perf dump if you or anyone could make something out of
> https://gist.github.com/olliRJL/43c10173aafd82be22c080a9cd28e673
You'd need to capture this over a period of time to see what ops might be going through and what the mds is doing.
> > Tnx! > o. > > --------------------------- > Olli Rajala - Lead TD > Anima Vitae Ltd. > www.anima.fi > --------------------------- > > > On Fri, Oct 14, 2022 at 8:32 PM Patrick Donnelly <
> wrote: > >> Hello Olli, >> >> On Thu, Oct 13, 2022 at 5:01 AM Olli Rajala <olli.rajala@anima.fi> wrote: >>> >>> Hi, >>> >>> I'm seeing constant 25-50MB/s writes to the metadata pool even when all >>> clients and the cluster is idling and in clean state. This surely can't >> be >>> normal? >>> >>> There's no apparent issues with the performance of the cluster but this >>> write rate seems excessive and I don't know where to look for
wrote: that: pdonnell@redhat.com> the
>> culprit. >>> >>> The setup is Ceph 16.2.9 running in hyperconverged 3 node core cluster >> and >>> 6 hdd osd nodes. >>> >>> Here's typical status when pretty much all clients are idling. Most of >> that >>> write bandwidth and maybe fifth of the write iops is hitting the >>> metadata pool. >>> >>> >>
>>> root@pve-core-1:~# ceph -s >>> cluster: >>> id: 2088b4b1-8de1-44d4-956e-aa3d3afff77f >>> health: HEALTH_OK >>> >>> services: >>> mon: 3 daemons, quorum pve-core-1,pve-core-2,pve-core-3 (age 2w) >>> mgr: pve-core-1(active, since 4w), standbys: pve-core-2, pve-core-3 >>> mds: 1/1 daemons up, 2 standby >>> osd: 48 osds: 48 up (since 5h), 48 in (since 4M) >>> >>> data: >>> volumes: 1/1 healthy >>> pools: 10 pools, 625 pgs >>> objects: 70.06M objects, 46 TiB >>> usage: 95 TiB used, 182 TiB / 278 TiB avail >>> pgs: 625 active+clean >>> >>> io: >>> client: 45 KiB/s rd, 38 MiB/s wr, 6 op/s rd, 287 op/s wr >>> >>
>>> >>> Here's some daemonperf dump: >>> >>> >>
>>> root@pve-core-1:~# ceph daemonperf mds.`hostname -s` >>> >> ----------------------------------------mds----------------------------------------- >>> --mds_cache--- ------mds_log------ -mds_mem- -------mds_server------- >> mds_ >>> -----objecter------ purg >>> req rlat fwd inos caps exi imi hifc crev cgra ctru cfsa cfa hcc >> hccd >>> hccr prcr|stry recy recd|subm evts segs repl|ino dn |hcr hcs hsr cre >>> cat |sess|actv rd wr rdwr|purg| >>> 40 0 0 767k 78k 0 0 0 1 6 1 0 0 5 5 >>> 3 7 |1.1k 0 0 | 17 3.7k 134 0 |767k 767k| 40 5 0 0 >>> 0 |110 | 4 2 21 0 | 2 >>> 57 2 0 767k 78k 0 0 0 3 16 3 0 0 11 11 >>> 0 17 |1.1k 0 0 | 45 3.7k 137 0 |767k 767k| 57 8 0 0 >>> 0 |110 | 0 2 28 0 | 4 >>> 57 4 0 767k 78k 0 0 0 4 34 4 0 0 34 33 >>> 2 26 |1.0k 0 0 |134 3.9k 139 0 |767k 767k| 57 13 0 0 >>> 0 |110 | 0 2 112 0 | 19 >>> 67 3 0 767k 78k 0 0 0 6 32 6 0 0 22 22 >>> 0 32 |1.1k 0 0 | 78 3.9k 141 0 |767k 768k| 67 4 0 0 >>> 0 |110 | 0 2 56 0 | 2 >>> >>
>>> Any ideas where to look at? >> >> Check the perf dump output of the mds: >> >> ceph tell mds.<fs_name>:0 perf dump >> >> over a period of time to identify what's going on. You can also look >> at the objecter_ops (another tell command) for the MDS. >> >> -- >> Patrick Donnelly, Ph.D. >> He / Him / His >> Principal Software Engineer >> Red Hat, Inc. >> GPG: 19F28A586F808C2402351B93C3301A3E258DD79D >> >> > _______________________________________________ > ceph-users mailing list -- ceph-users@ceph.io > To unsubscribe send an email to ceph-users-leave@ceph.io >
-- Cheers, Venky
-- Cheers, Venky
ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
Hi Olli, On Tue, Jul 2, 2024 at 7:51 PM Olli Rajala <olli.rajala@anima.fi> wrote:
Hi - mostly as a note to future me and if anyone else looking for the same issue...
I finally solved this a couple of months ago. No idea what is wrong with Ceph but the root cause that was triggering this MDS issue was that I had several workstations and a couple servers where the updatedb of "locate" was getting run by daily cron exactly the same time every night causing high momentary strain on the MDS which then somehow screwed up the metadata caching and flushing creating this cumulative write io.
That's probably due to updatedb walking the ceph file system and also possibly triggering cap recalls from other clients.
The thing to note here is that there's a difference with "locate" and "mlocate" packages. The default config (on Ubuntu atleast) of updatedb for "mlocate" does skip scanning cephfs filesystems but not so for "locate" which happily ventures onto all of your cephfs mounts :|
--------------------------- Olli Rajala - Lead TD Anima Vitae Ltd. www.anima.fi ---------------------------
On Wed, Dec 14, 2022 at 7:41 PM Olli Rajala <olli.rajala@anima.fi> wrote:
Hi,
One thing I now noticed in the mds logs is that there's a ton of entries like this: 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache projecting to [d345,d346] n(v1638 rc2022-12-11T18:20:49.317400+0200 b787972591 694=484+210) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache result [d345,d346] n(v1638 rc2022-12-11T18:20:49.321400+0200 b787972591 695=484+211) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache projecting to [d343,d344] n(v1638 rc2022-12-11T18:20:49.317400+0200 b787972591 694=484+210) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache result [d343,d344] n(v1638 rc2022-12-11T18:20:49.321400+0200 b787972591 695=484+211) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache projecting to [d341,d342] n(v1638 rc2022-12-11T18:20:49.317400+0200 b787972591 694=484+210) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache result [d341,d342] n(v1638 rc2022-12-11T18:20:49.321400+0200 b787972591 695=484+211) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache projecting to [d33f,d340] n(v1638 rc2022-12-11T18:20:49.317400+0200 b787972591 694=484+210) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache result [d33f,d340] n(v1638 rc2022-12-11T18:20:49.321400+0200 b787972591 695=484+211) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache projecting to [d33d,d33e] n(v1638 rc2022-12-11T18:20:49.317400+0200 b787972591 694=484+210) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache result [d33d,d33e] n(v1638 rc2022-12-11T18:20:49.321400+0200 b787972591 695=484+211)
...and after dropping the caches considerably less of those - normal, abnormal, typical, atypical? ...or is that just something that starts happening after the cache gets filled?
Tnx, --------------------------- Olli Rajala - Lead TD Anima Vitae Ltd. www.anima.fi ---------------------------
On Sun, Dec 11, 2022 at 9:07 PM Olli Rajala <olli.rajala@anima.fi> wrote:
Hi,
I'm still totally lost with this issue. And now lately I've had a couple of incidents where the write bw has suddenly jumped to even crazier levels. See the graph here: https://gist.github.com/olliRJL/3e97e15a37e8e801a785a1bd5358120d
The points where it drops to something manageable again are when I have dropped the mds caches. Usually after the drop there is steady rise but now these sudden jumps are something new and even more scary :E
Here's a fresh 2sec level 20 mds log: https://gist.github.com/olliRJL/074bec65787085e70db8af0ec35f8148
Any help and ideas greatly appreciated. Is there any tool or procedure to safely check or rebuild the mds data? ...if this behaviour could be caused by some hidden issue with the data itself.
Tnx, --------------------------- Olli Rajala - Lead TD Anima Vitae Ltd. www.anima.fi ---------------------------
On Fri, Nov 11, 2022 at 9:14 AM Venky Shankar <vshankar@redhat.com> wrote:
On Fri, Nov 11, 2022 at 3:06 AM Olli Rajala <olli.rajala@anima.fi> wrote:
Hi Venky,
I have indeed observed the output of the different sections of perf
dump like so:
watch -n 1 ceph tell mds.`hostname` perf dump objecter watch -n 1 ceph tell mds.`hostname` perf dump mds_cache ...etc...
...but without any proper understanding of what is a normal rate for some number to go up it's really difficult to make anything from that.
btw - is there some convenient way to capture this kind of temporal output for others to view. Sure, I could just dump once a second to a file or sequential files but is there some tool or convention that is easy to look at and analyze?
Not really - you'd have to do it yourself.
Tnx, --------------------------- Olli Rajala - Lead TD Anima Vitae Ltd. www.anima.fi ---------------------------
On Thu, Nov 10, 2022 at 8:18 AM Venky Shankar <vshankar@redhat.com>
Hi Olli,
On Mon, Oct 17, 2022 at 1:08 PM Olli Rajala <olli.rajala@anima.fi>
wrote:
> > Hi Patrick, > > With "objecter_ops" did you mean "ceph tell mds.pve-core-1 ops" and/or > "ceph tell mds.pve-core-1 objecter_requests"? Both these show very few > requests/ops - many times just returning empty lists. I'm pretty sure that > this I/O isn't generated by any clients - I've earlier tried to isolate > this by shutting down all cephfs clients and this didn't have any > noticeable effect. > > I tried to watch what is going on with that "perf dump" but to be honest > all I can see is some numbers going up in the different sections :) > ...don't have a clue what to focus on and how to interpret that. > > Here's a perf dump if you or anyone could make something out of
> https://gist.github.com/olliRJL/43c10173aafd82be22c080a9cd28e673
You'd need to capture this over a period of time to see what ops might be going through and what the mds is doing.
> > Tnx! > o. > > --------------------------- > Olli Rajala - Lead TD > Anima Vitae Ltd. > www.anima.fi > --------------------------- > > > On Fri, Oct 14, 2022 at 8:32 PM Patrick Donnelly <
> wrote: > > > Hello Olli, > > > > On Thu, Oct 13, 2022 at 5:01 AM Olli Rajala <olli.rajala@anima.fi> wrote: > > > > > > Hi, > > > > > > I'm seeing constant 25-50MB/s writes to the metadata pool even when all > > > clients and the cluster is idling and in clean state. This surely can't > > be > > > normal? > > > > > > There's no apparent issues with the performance of the cluster but this > > > write rate seems excessive and I don't know where to look for
wrote: that: pdonnell@redhat.com> the
> > culprit. > > > > > > The setup is Ceph 16.2.9 running in hyperconverged 3 node core cluster > > and > > > 6 hdd osd nodes. > > > > > > Here's typical status when pretty much all clients are idling. Most of > > that > > > write bandwidth and maybe fifth of the write iops is hitting the > > > metadata pool. > > > > > > > >
> > > root@pve-core-1:~# ceph -s > > > cluster: > > > id: 2088b4b1-8de1-44d4-956e-aa3d3afff77f > > > health: HEALTH_OK > > > > > > services: > > > mon: 3 daemons, quorum pve-core-1,pve-core-2,pve-core-3 (age 2w) > > > mgr: pve-core-1(active, since 4w), standbys: pve-core-2, pve-core-3 > > > mds: 1/1 daemons up, 2 standby > > > osd: 48 osds: 48 up (since 5h), 48 in (since 4M) > > > > > > data: > > > volumes: 1/1 healthy > > > pools: 10 pools, 625 pgs > > > objects: 70.06M objects, 46 TiB > > > usage: 95 TiB used, 182 TiB / 278 TiB avail > > > pgs: 625 active+clean > > > > > > io: > > > client: 45 KiB/s rd, 38 MiB/s wr, 6 op/s rd, 287 op/s wr > > > > >
> > > > > > Here's some daemonperf dump: > > > > > > > >
> > > root@pve-core-1:~# ceph daemonperf mds.`hostname -s` > > > > > ----------------------------------------mds----------------------------------------- > > > --mds_cache--- ------mds_log------ -mds_mem- -------mds_server------- > > mds_ > > > -----objecter------ purg > > > req rlat fwd inos caps exi imi hifc crev cgra ctru cfsa cfa hcc > > hccd > > > hccr prcr|stry recy recd|subm evts segs repl|ino dn |hcr hcs hsr cre > > > cat |sess|actv rd wr rdwr|purg| > > > 40 0 0 767k 78k 0 0 0 1 6 1 0 0 5 5 > > > 3 7 |1.1k 0 0 | 17 3.7k 134 0 |767k 767k| 40 5 0 0 > > > 0 |110 | 4 2 21 0 | 2 > > > 57 2 0 767k 78k 0 0 0 3 16 3 0 0 11 11 > > > 0 17 |1.1k 0 0 | 45 3.7k 137 0 |767k 767k| 57 8 0 0 > > > 0 |110 | 0 2 28 0 | 4 > > > 57 4 0 767k 78k 0 0 0 4 34 4 0 0 34 33 > > > 2 26 |1.0k 0 0 |134 3.9k 139 0 |767k 767k| 57 13 0 0 > > > 0 |110 | 0 2 112 0 | 19 > > > 67 3 0 767k 78k 0 0 0 6 32 6 0 0 22 22 > > > 0 32 |1.1k 0 0 | 78 3.9k 141 0 |767k 768k| 67 4 0 0 > > > 0 |110 | 0 2 56 0 | 2 > > > > >
> > > Any ideas where to look at? > > > > Check the perf dump output of the mds: > > > > ceph tell mds.<fs_name>:0 perf dump > > > > over a period of time to identify what's going on. You can also look > > at the objecter_ops (another tell command) for the MDS. > > > > -- > > Patrick Donnelly, Ph.D. > > He / Him / His > > Principal Software Engineer > > Red Hat, Inc. > > GPG: 19F28A586F808C2402351B93C3301A3E258DD79D > > > > > _______________________________________________ > ceph-users mailing list -- ceph-users@ceph.io > To unsubscribe send an email to ceph-users-leave@ceph.io >
-- Cheers, Venky
-- Cheers, Venky
ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
-- Cheers, Venky
Hi Venky, Yep that's what I figured out too - but it also must have triggered some underlying issue where the mds goes into some state where each of these updatedb runs accumulate more and more of that constant write io to the metadata pool which never settles. Feels like it was constantly flushing the mds cache even tho there is no equivalent amount of read io to fill up the cache. In this graph that I posted earlier: https://gist.github.com/olliRJL/3e97e15a37e8e801a785a1bd5358120d ...you can see those updatedb runs as those spikes on the read side - but other than those the read io is almost zero. And those points where the write io drops were times when I dopped the mds caches. --------------------------- Olli Rajala - Lead TD Anima Vitae Ltd. www.anima.fi --------------------------- On Wed, Jul 3, 2024 at 7:49 PM Venky Shankar <vshankar@redhat.com> wrote:
Hi Olli,
On Tue, Jul 2, 2024 at 7:51 PM Olli Rajala <olli.rajala@anima.fi> wrote:
Hi - mostly as a note to future me and if anyone else looking for the
issue...
I finally solved this a couple of months ago. No idea what is wrong with Ceph but the root cause that was triggering this MDS issue was that I had several workstations and a couple servers where the updatedb of "locate" was getting run by daily cron exactly the same time every night causing high momentary strain on the MDS which then somehow screwed up the
same metadata
caching and flushing creating this cumulative write io.
That's probably due to updatedb walking the ceph file system and also possibly triggering cap recalls from other clients.
The thing to note here is that there's a difference with "locate" and "mlocate" packages. The default config (on Ubuntu atleast) of updatedb
"mlocate" does skip scanning cephfs filesystems but not so for "locate" which happily ventures onto all of your cephfs mounts :|
--------------------------- Olli Rajala - Lead TD Anima Vitae Ltd. www.anima.fi ---------------------------
On Wed, Dec 14, 2022 at 7:41 PM Olli Rajala <olli.rajala@anima.fi> wrote:
Hi,
One thing I now noticed in the mds logs is that there's a ton of entries like this: 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache projecting to [d345,d346] n(v1638 rc2022-12-11T18:20:49.317400+0200 b787972591 694=484+210) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache result [d345,d346] n(v1638 rc2022-12-11T18:20:49.321400+0200 b787972591 695=484+211) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache projecting to [d343,d344] n(v1638 rc2022-12-11T18:20:49.317400+0200 b787972591 694=484+210) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache result [d343,d344] n(v1638 rc2022-12-11T18:20:49.321400+0200 b787972591 695=484+211) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache projecting to [d341,d342] n(v1638 rc2022-12-11T18:20:49.317400+0200 b787972591 694=484+210) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache result [d341,d342] n(v1638 rc2022-12-11T18:20:49.321400+0200 b787972591 695=484+211) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache projecting to [d33f,d340] n(v1638 rc2022-12-11T18:20:49.317400+0200 b787972591 694=484+210) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache result [d33f,d340] n(v1638 rc2022-12-11T18:20:49.321400+0200 b787972591 695=484+211) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache projecting to [d33d,d33e] n(v1638 rc2022-12-11T18:20:49.317400+0200 b787972591 694=484+210) 2022-12-11T18:20:49.321+0200 7fdd0edde700 20 mds.0.cache result [d33d,d33e] n(v1638 rc2022-12-11T18:20:49.321400+0200 b787972591 695=484+211)
...and after dropping the caches considerably less of those - normal, abnormal, typical, atypical? ...or is that just something that starts happening after the cache gets filled?
Tnx, --------------------------- Olli Rajala - Lead TD Anima Vitae Ltd. www.anima.fi ---------------------------
On Sun, Dec 11, 2022 at 9:07 PM Olli Rajala <olli.rajala@anima.fi> wrote:
Hi,
I'm still totally lost with this issue. And now lately I've had a couple of incidents where the write bw has suddenly jumped to even crazier levels. See the graph here: https://gist.github.com/olliRJL/3e97e15a37e8e801a785a1bd5358120d
The points where it drops to something manageable again are when I have dropped the mds caches. Usually after the drop there is steady rise but now these sudden jumps are something new and even more scary :E
Here's a fresh 2sec level 20 mds log: https://gist.github.com/olliRJL/074bec65787085e70db8af0ec35f8148
Any help and ideas greatly appreciated. Is there any tool or
safely check or rebuild the mds data? ...if this behaviour could be caused by some hidden issue with the data itself.
Tnx, --------------------------- Olli Rajala - Lead TD Anima Vitae Ltd. www.anima.fi ---------------------------
On Fri, Nov 11, 2022 at 9:14 AM Venky Shankar <vshankar@redhat.com> wrote:
On Fri, Nov 11, 2022 at 3:06 AM Olli Rajala <olli.rajala@anima.fi> wrote:
Hi Venky,
I have indeed observed the output of the different sections of perf
dump like so:
watch -n 1 ceph tell mds.`hostname` perf dump objecter watch -n 1 ceph tell mds.`hostname` perf dump mds_cache ...etc...
...but without any proper understanding of what is a normal rate for some number to go up it's really difficult to make anything from
btw - is there some convenient way to capture this kind of temporal
output for others to view. Sure, I could just dump once a second to a file or sequential files but is there some tool or convention that is easy to look at and analyze?
Not really - you'd have to do it yourself.
Tnx, --------------------------- Olli Rajala - Lead TD Anima Vitae Ltd. www.anima.fi ---------------------------
On Thu, Nov 10, 2022 at 8:18 AM Venky Shankar <vshankar@redhat.com
wrote:
> > Hi Olli, > > On Mon, Oct 17, 2022 at 1:08 PM Olli Rajala <olli.rajala@anima.fi
wrote:
> > > > Hi Patrick, > > > > With "objecter_ops" did you mean "ceph tell mds.pve-core-1 ops" and/or > > "ceph tell mds.pve-core-1 objecter_requests"? Both these show very few > > requests/ops - many times just returning empty lists. I'm pretty sure that > > this I/O isn't generated by any clients - I've earlier tried to isolate > > this by shutting down all cephfs clients and this didn't have any > > noticeable effect. > > > > I tried to watch what is going on with that "perf dump" but to be honest > > all I can see is some numbers going up in the different
> > ...don't have a clue what to focus on and how to interpret that. > > > > Here's a perf dump if you or anyone could make something out of that: > > https://gist.github.com/olliRJL/43c10173aafd82be22c080a9cd28e673 > > You'd need to capture this over a period of time to see what ops might > be going through and what the mds is doing. > > > > > Tnx! > > o. > > > > --------------------------- > > Olli Rajala - Lead TD > > Anima Vitae Ltd. > > www.anima.fi > > --------------------------- > > > > > > On Fri, Oct 14, 2022 at 8:32 PM Patrick Donnelly < pdonnell@redhat.com> > > wrote: > > > > > Hello Olli, > > > > > > On Thu, Oct 13, 2022 at 5:01 AM Olli Rajala <
for procedure to that. sections :) olli.rajala@anima.fi>
> > > > > > > > Hi, > > > > > > > > I'm seeing constant 25-50MB/s writes to the metadata pool even when all > > > > clients and the cluster is idling and in clean state. This surely can't > > > be > > > > normal? > > > > > > > > There's no apparent issues with the performance of the cluster but this > > > > write rate seems excessive and I don't know where to look for
wrote: the
> > > culprit. > > > > > > > > The setup is Ceph 16.2.9 running in hyperconverged 3 node core cluster > > > and > > > > 6 hdd osd nodes. > > > > > > > > Here's typical status when pretty much all clients are idling. Most of > > > that > > > > write bandwidth and maybe fifth of the write iops is hitting the > > > > metadata pool. > > > > > > > > > > >
> > > > root@pve-core-1:~# ceph -s > > > > cluster: > > > > id: 2088b4b1-8de1-44d4-956e-aa3d3afff77f > > > > health: HEALTH_OK > > > > > > > > services: > > > > mon: 3 daemons, quorum pve-core-1,pve-core-2,pve-core-3 (age 2w) > > > > mgr: pve-core-1(active, since 4w), standbys: pve-core-2, pve-core-3 > > > > mds: 1/1 daemons up, 2 standby > > > > osd: 48 osds: 48 up (since 5h), 48 in (since 4M) > > > > > > > > data: > > > > volumes: 1/1 healthy > > > > pools: 10 pools, 625 pgs > > > > objects: 70.06M objects, 46 TiB > > > > usage: 95 TiB used, 182 TiB / 278 TiB avail > > > > pgs: 625 active+clean > > > > > > > > io: > > > > client: 45 KiB/s rd, 38 MiB/s wr, 6 op/s rd, 287 op/s wr > > > > > > >
> > > > > > > > Here's some daemonperf dump: > > > > > > > > > > >
> > > > root@pve-core-1:~# ceph daemonperf mds.`hostname -s` > > > > > > >
----------------------------------------mds-----------------------------------------
> > > > --mds_cache--- ------mds_log------ -mds_mem- -------mds_server------- > > > mds_ > > > > -----objecter------ purg > > > > req rlat fwd inos caps exi imi hifc crev cgra ctru cfsa cfa hcc > > > hccd > > > > hccr prcr|stry recy recd|subm evts segs repl|ino dn |hcr hcs hsr cre > > > > cat |sess|actv rd wr rdwr|purg| > > > > 40 0 0 767k 78k 0 0 0 1 6 1 0 0 5 5 > > > > 3 7 |1.1k 0 0 | 17 3.7k 134 0 |767k 767k| 40 5 0 0 > > > > 0 |110 | 4 2 21 0 | 2 > > > > 57 2 0 767k 78k 0 0 0 3 16 3 0 0 11 11 > > > > 0 17 |1.1k 0 0 | 45 3.7k 137 0 |767k 767k| 57 8 0 0 > > > > 0 |110 | 0 2 28 0 | 4 > > > > 57 4 0 767k 78k 0 0 0 4 34 4 0 0 34 33 > > > > 2 26 |1.0k 0 0 |134 3.9k 139 0 |767k 767k| 57 13 0 0 > > > > 0 |110 | 0 2 112 0 | 19 > > > > 67 3 0 767k 78k 0 0 0 6 32 6 0 0 22 22 > > > > 0 32 |1.1k 0 0 | 78 3.9k 141 0 |767k 768k| 67 4 0 0 > > > > 0 |110 | 0 2 56 0 | 2 > > > > > > >
> > > > Any ideas where to look at? > > > > > > Check the perf dump output of the mds: > > > > > > ceph tell mds.<fs_name>:0 perf dump > > > > > > over a period of time to identify what's going on. You can also look > > > at the objecter_ops (another tell command) for the MDS. > > > > > > -- > > > Patrick Donnelly, Ph.D. > > > He / Him / His > > > Principal Software Engineer > > > Red Hat, Inc. > > > GPG: 19F28A586F808C2402351B93C3301A3E258DD79D > > > > > > > > _______________________________________________ > > ceph-users mailing list -- ceph-users@ceph.io > > To unsubscribe send an email to ceph-users-leave@ceph.io > > > > > -- > Cheers, > Venky >
-- Cheers, Venky
ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
-- Cheers, Venky
participants (3)
-
Anthony D'Atri
-
Olli Rajala
-
Venky Shankar