Ceph » RADOS

Here is the log of an osd that restarted and made a few pgs into the snaptrim state.

ceph-post-file: 88808267-4ec6-416e-b61c-11da74a4d68e

I reproduced the issue by doing a `ceph pg repeer` on a pg with a non-zero snaptrimq_len. After the pg has been repeered, it switched into the snaptrim state.

I searched a bit through the log I sent and I don't see any traces of a pg into the snaptrim state, probably because it was not the primary osd.

We tested the repeer on a pg which has a non zero snaptrimq_len from our nautilus prod RBD cluster (which use replicated pool as well). In this cluster the repeer and the snaptrim was just too fast to be noticeable without looking at the log.

Here is the log of the primary osd (which is much smaller than the previous logs I sent!):
ceph-post-file: f0208568-fbf4-48fa-a758-0c85ab4a6cdc

The repeer makes the snaptrimq_len of the pg go to zero. I am guessing that sometimes it doesn't go into the snaptrim state and snaptrimq_len can increase to a number which could be noticeable if we do a repeer (which happens while I was stress-testing snapshots). However, I don't have any logs showing this (buggy?) state transition.

I don't have the logs right now but it prints the state of the PG so if you search for`snaptrim` in `f0208568-fbf4-48fa-a758-0c85ab4a6cdc` you should be able to find the PG that I repeered. I can check tomorrow if necessary.

Just wanted to note that we recently encountered what appears to be the same issue on some Luminous (12.2.12) clusters that we're preparing for upgrade. At least two clusters, if not three of them, have had some OSDs in a destroyed state for many weeks, awaiting disk replacement. This has naturally led to a significant pileup of osdmaps. (Not sure if that's relevant to this problem.) In each case, restarting certain OSDs (we're not sure which ones - we went host-at-a-time and not all hosts triggered the problem) caused all PGs to go into snaptrim_wait. snaptrimq_len was as high as 1mil.

We carefully cleared this issue (took several days), and in one of the clusters another OSD restart caused the problem to happen again.

Given that this is on Luminous, we weren't going to report this issue, but given the similarity to the issue in this ticket I thought it worth mentioning.

We are also seeing this issue on 16.2.5. We schedule cephfs snapshots via cron in a 24h7d2w rotation schedule. Over several months we observed unexplained storage consumption which grew without explanation until we eventually received the following error:

[WRN] PG_SLOW_SNAP_TRIMMING: snap trim queue for 1 pg(s) >= 32768 (mon_osd_snap_trim_queue_warn_on)

We examined our system and found roughly 499 PGs with queues over 32768 and a total cumulative snaptrim queue length across all PGs of over 12 Million. We took the following actions:

1. Stopped the snapshot schedule
2. Systematically repeered all PGs which had non-zero snaptrim queue lenghts.
3. Verified that no PGs listed anything remaining in their snaptrim queues.
4. Re-enabled snapshots.

The above resulted in reclaiming > 94T of raw capacity.

We have now been running our snapshot schedule for 2 days and currently see 109 PGs with non-zero snaptrim queues totaling 33,806 items in the snaptrim queues across those PGs.

It would seem, as best as we can tell, as if snapshot trimming is not occurring unless we manually repeer the associated PGs.

We are more than happy to provide any information that would prove useful.

Can you collect and share OSD logs (with debug_osd=20 and debug_ms=1) when you are encountering this issue?

Christopher Hoffman wrote:

Can you collect and share OSD logs (with debug_osd=20 and debug_ms=1) when you are encountering this issue?

I'd be more than happy to, but could you please provide me the following guidance:

1. Do you want logs from ALL OSDs or would a single OSD suffice?
2. You've asked for logs "when I'm encountering this issue". I believe snapshot trimming is not occurring automatically. We currently are continuing to rotate snapshots and the queue lengths are continuing to grow. For what time period would you like logs collected: Any time, as you would expect the logs to continuously be reporting what you are looking for? At the time immediately following a snapshot duration? Any clarification you could provide would be helpful.

David Prude wrote:

Christopher Hoffman wrote:

Can you collect and share OSD logs (with debug_osd=20 and debug_ms=1) when you are encountering this issue?

I'd be more than happy to, but could you please provide me the following guidance:

1. Do you want logs from ALL OSDs or would a single OSD suffice?
2. You've asked for logs "when I'm encountering this issue". I believe snapshot trimming is not occurring automatically. We currently are continuing to rotate snapshots and the queue lengths are continuing to grow. For what time period would you like logs collected: Any time, as you would expect the logs to continuously be reporting what you are looking for? At the time immediately following a snapshot duration? Any clarification you could provide would be helpful.

1. A single OSD will be fine, just ensure it is one exhibiting the issue.
2. Can you collect the logs just before the repeer and 12h time afterwards (adjust time, if needed to gather logs during a snapshot trim)?

Christopher Hoffman wrote:

1. A single OSD will be fine, just ensure it is one exhibiting the issue.
2. Can you collect the logs just before the repeer and 12h time afterwards (adjust time, if needed to gather logs during a snapshot trim)?

Just to clarify, you want a section of log just before I manually repeer? As far as I can tell no snapshot trim is occurring except when I manually repeer so for "logs during snapshot trim" you would like this while trimming is occurring as a result of a manual repeer? If this is the case, I can:

1. collect logs prior to repeer
2. manually repeer
3. collect logs as the snapshot trimming initiated by the repeer is progressing.

How large of a time window would you like for each of the above?

Yes that is the case.

Can you collect the log starting at the manual repeer? The intent was to capture the logs starting at this point. Also include logs while the snaptrim is underway for 12h.

I will collect these logs as you've requested. As an update: I am now seeing snaptrim occurring automatically without intervention. This was not the case before exhaustively manually re-peering as described.

Fortunately (or perhaps not so fortunately), in the process of dealing with this issue we performed a full restart of all OSDs. Since this restart, this behavior has resolved. We now see regular snap trimming and it would seem we have not re-entered this state.

We are having the same issue with ceph 15.2.13. We take RBD snapshots that gets deleted after 3 days.
The problem gets so bad that the cluster falls behind with deep scrub and scrub.
We have to restart OSDs individually for it to resume snaptrim and scrubbing.
Our cluster so far freed about 111 TB of space.

Could you please collect the logs exactly like mentioned in the comment #14 (https://tracker.ceph.com/issues/52026#note-14)?

https://github.com/ceph/ceph/pull/45785 merged