Ceph » crimson

osd.0 crash is unrelated -- should be fixed by https://github.com/ceph/ceph/pull/55705

2024-02-22T09:56:52.307+0000 2b476bef4700 10 mon.a@0(leader).osd e16 update_pending_pgs pg 46.0 just added, up [2,0] p 2 acting [2,0] p 2 history ec=17/17 lis/c=0/0 les/c/f=0/0/0 sis=17 past_intervals ([0,0] all_participants={} intervals=[])

46.0 was actually created with same_interval_since set to 17.

DEBUG 2024-02-22 09:56:51,337 [shard 0:main] osd - client_request(id=2536, detail=m=[osd_op(client.4303.0:2 46.0 46.71d521c0 (undecoded) ondisk+write+known_if_redirected+supports_pool_eio e16) v8]): starting start_pg_operation

IO sent at epoch 16. Seems like a bug in OSDMonitor -- history.sis should have been initialized to 16.

Xuehan: how did you reproduce this? If the above is correct, it should reproduce just as easily on classic.

OSDMonitor::update_pending_pgs limits the number of pgs it's willing to process in each invocation -- mon_osd_max_creating_pgs. Thus, there may be several epochs between when the OSDMap with the pool is exposed to clients and when OSDMonitor::update_pending_pgs actually generates the history for the pg and sends creates to OSDs.

The trouble is:

      const pg_t pgid{ps, static_cast<uint64_t>(poolid)};
      // NOTE: use the *current* epoch as the PG creation epoch so that the
      // OSD does not have to generate a long set of PastIntervals.
      pending_creatings.pgs.emplace(
    pgid,
    creating_pgs_t::pg_create_info(inc.epoch,
                       p->second.modified));

If update_pending_pgs doesn't get to a particular PG in the epoch in which the pool was created, the pg will end up with a same_interval_since at that epoch rather than the pool creation epoch. Any entity other than the monitor, however, would consider the pool creation epoch to be the interval start. This latter value is correct, monitor internal execution details aren't visible externally and can't be part of the definition of an interval.

The simple solution is to entirely remove this config and require the monitor to initialized creating_pgs_t entries for each pg in the interval on which the pool is created.

In the logs above, it seems that pools 39 (8 pgs), 40 (8 pgs), 41 (32 pgs), 42 (32 pgs), 43 (32 pgs), 44 (32 pgs), 46 (32 pgs), 48 (32 pgs), and 49 (32 pgs) were all created in the same epoch (16) at the same timestamp (2024-02-22T09:56:51.296239+0000).

mon_osd_max_creating_pgs defaults to 1024 -- more than the sum of the above pg counts. However, pools 3-38 were created during epochs 13, 14, and 15 most with 32 pgs. That suffices to push the pg creation queue size over the configured 1024 limit.

What prompted so many pools to be created so close in time?

https://github.com/athanatos/ceph/tree/sjust/wip-64546-max-creating-pgs

Samuel Just wrote:

https://github.com/athanatos/ceph/tree/sjust/wip-64546-max-creating-pgs

We've just finished the test. This branch is effective in fixing this issue.

https://github.com/ceph/ceph/pull/55979