rbd/libceph: ceph-msgr/RBD workers blocked on con->mutex and osd->lock under load

rbd/libceph: ceph-msgr/RBD workers blocked on con->mutex and osd->lock under load

[Sergei Monakhov]

Hi,

I'm debugging RBD stalls on a production workload. I don't have a small
reproducer yet, so this is not a clean benchmark report. The data below is from
bpftrace while the issue was happening naturally.

The affected host is on Ubuntu 6.14.0-35-generic. The path I captured is msgr1
/ ceph_con_v1_try_read().

At first I assumed this was some receive-side problem, but the off-CPU traces
don't really support that. In many samples the reply has already been received
and dispatched, and the ceph-msgr worker is sleeping inside the RBD completion
callback:

  ceph_con_v1_try_read
    ceph_con_process_message
      osd_dispatch
        handle_reply
          __complete_request
            rbd_osd_req_callback
              rbd_img_handle_request
                mutex_lock

The waiter there is blocked on the RBD image request state mutex. Tracing the
holder shows rbd_queue_workfn() holding that mutex while advancing the RBD
state machine and submitting follow-up OSD requests.

I then traced nested mutex waits while rbd_img_handle_request() is holding
img_req->state_mutex. There are two classes.

The first one is the messenger connection mutex:

  rbd_queue_workfn
    rbd_img_handle_request
      rbd_img_advance
        __rbd_obj_handle_request
          rbd_obj_advance_write
            rbd_osd_submit
              ceph_osdc_start_request
                __submit_request
                  send_request
                    ceph_con_send / ceph_msg_revoke
                      mutex_lock(con->mutex)

Example:

  NESTED MUTEX WAIT CLASSIFY time=15:30:20 tid=1988383 comm=kworker/66:2
    state_mutex=0xffff8aa3e36658d8
    nested_lock=0xffff8aa319c47108
    wait_us=153142
    state_hold_so_far_us=153258
    from_rbd_queue_workfn=1
    osd_req=0xffff8a066e142580

  CLASS con->mutex by callsite
    con=0xffff8aa319c47030
    paired_osd_lock=0xffff8aa319c477b0
    delta=0x6a8

  --- NESTED WAITER STACK ---

    mutex_lock+1
    send_request+332
    __submit_request+541
    ceph_osdc_start_request+53
    rbd_osd_submit+30
    rbd_obj_advance_write+820
    __rbd_obj_handle_request+91
    rbd_img_advance+254
    rbd_img_handle_request+82
    rbd_queue_workfn+597
    process_one_work+379
    worker_thread+734
    kthread+254
    ret_from_fork+71
    ret_from_fork_asm+26

This looks like the kind of issue that should be helped by Max Kellermann's
out_queue patch:

  fs/ceph/messenger: add separate lock for `out_queue`
  https://lore.kernel.org/ceph-devel/20260703193803.3689912-1-max.kellermann@ionos.com/

The second class is more concerning. Multiple RBD workers block on the same
ceph_osd.lock while each is holding a different img_req->state_mutex. In one
captured episode, the waits were around 50-51 seconds.

Example from that episode:

  NESTED MUTEX WAIT CLASSIFY time=15:42:22 tid=1907557 comm=kworker/206:12
    state_mutex=0xffff8aa34b09b598
    nested_lock=0xffff8aa319cfb7b0
    wait_us=51157147
    state_hold_so_far_us=51157170
    from_rbd_queue_workfn=1
    osd_req=0xffff8acfb2b9b840

  CLASS osd->lock by callsite
    paired_con_mutex=0xffff8aa319cfb108
    delta=0x6a8

  --- NESTED WAITER STACK ---

    mutex_lock+1
    ceph_osdc_start_request+53
    rbd_osd_submit+30
    rbd_obj_advance_write+820
    __rbd_obj_handle_request+91
    rbd_img_advance+254
    rbd_img_handle_request+82
    rbd_queue_workfn+597
    process_one_work+379
    worker_thread+734
    kthread+254
    ret_from_fork+71
    ret_from_fork_asm+26

Several more workers were waiting on the same nested_lock address in the same
time window:

  nested_lock=0xffff8aa319cfb7b0
  paired_con_mutex=0xffff8aa319cfb108
  delta=0x6a8

  wait_us=51156869
  wait_us=51156379
  wait_us=51156066
  wait_us=51155589
  wait_us=51155104
  wait_us=51148538
  wait_us=50723956
  wait_us=50723973
  wait_us=50722959
  wait_us=50690601
  wait_us=50689346
  wait_us=50676705
  wait_us=50535020
  wait_us=50534884

All of these had the same waiter stack:

  mutex_lock+1
  ceph_osdc_start_request+53
  rbd_osd_submit+30
  rbd_obj_advance_write+820
  __rbd_obj_handle_request+91
  rbd_img_advance+254
  rbd_img_handle_request+82
  rbd_queue_workfn+597
  process_one_work+379
  worker_thread+734
  kthread+254
  ret_from_fork+71
  ret_from_fork_asm+26

A few questions:

  1. Is the con->mutex class above expected to be fixed by the out_queue lock
     patch?

  2. Is it expected that successful OSD replies run the RBD callback inline
     from the ceph-msgr worker? In this workload rbd_img_handle_request() can
     block on img_req->state_mutex for hundreds of milliseconds, and in some
     cases much longer.

  3. Is holding img_req->state_mutex across
     ceph_osdc_start_request()/__submit_request() intentional? The traces show
     many RBD workers holding their image request state mutex while waiting on
     the same ceph_osd.lock.

I can send the bpftrace scripts and fuller logs if useful. The main thing I
wanted to check is whether this lock chain is known/expected.

Thanks,
Sergei