Re: [PATCH v3] bcache: avoid holding bch_register_lock across cache_set recovery

[Jing Wu <realwujing@gmail.com>]

From: Qiliang Yuan <realwujing@gmail.com>

Hi Coly,

Thanks for the quick reply. You are right that I jumped straight to the
fix without explaining the problem well enough. Let me back up and
describe the actual production incident this patch comes from, with the
real call traces and the operational consequence, not just the timeout
message.

> I feel you should explain the problem you try to solve. Is it that some
> sysfs interfaces that you thought should not be blocked but blocked indeed?
>
> If yes, then it is better to list which bcache interfaces you think they should
> not not be blocked during the bcache device initialization.

This is from a Ceph OSD node: 2 NVMe drives, each partitioned into 6
partitions (12 cache_sets total), caching 12 HDD backing devices. At
boot, udev triggers a per-device script as each bcacheN device shows
up, which writes tuning values under its sysfs directory. Three
interfaces are concretely affected, all blocked in mutex_lock(&bch_register_lock)
while an unrelated cache_set is still in run_cache_set():

1. bch_cache_set_store(), writing congested_read_threshold_us /
   congested_write_threshold_us for an already-running, unrelated
   cache_set:

   task:bcache_cache_se state:D stack:    0 pid: 3492 ppid:     1
   Call trace:
    __mutex_lock.constprop.0+0x1d4/0x5ec
    __mutex_lock_slowpath+0x1c/0x30
    mutex_lock+0x50/0x60
    bch_cache_set_store+0x40/0x80 [bcache]
    sysfs_kf_write+0x4c/0x5c
    kernfs_fop_write_iter+0x130/0x1c0

2. bch_cached_dev_store(), writing sequential_cutoff for an already
   attached, unrelated backing device (same incident window).

3. register_cache() itself, i.e. registering a *different*, unrelated
   cache device, blocked behind the same lock:

   task:bcache          state:D stack:    0 pid: 8104 ppid:     1
   Call trace:
    __mutex_lock.constprop.0+0x1d4/0x5ec
    __mutex_lock_slowpath+0x1c/0x30
    mutex_lock+0x50/0x60
    register_cache+0x11c/0x1a0 [bcache]
    register_bcache+0x1d4/0x3cc [bcache]
    kobj_attr_store+0x18/0x30

So it is not just "show" vs "store", and it is not limited to the
device currently initializing: an unrelated device's own registration
can be blocked too.

> If your motivation is to get ride of the timeout trace message, it should be
> much simpler patch.
>
> If the issue to solve is to avoid blocking on some specific sysfs files for
> some purpose e.g. for the system monitoring processes to get some
> information from the bcache subsystem, then it is better to list the
> interfaces you are accessing (read or write), in which conditions the
> processes are blocked and what is the expected behavior.

It is not about the timeout message. The concrete, measurable
consequence in this incident is that systemd-udevd kills the udev
worker once it hits its own timeout, and the device add event fails
and gets retried:

  systemd-udevd: bcache7: Spawned process '/usr/sbin/bcache_cached_dev_conf.sh ...' timed out after 2min 59s, killing
  systemd-udevd: bcache7: Worker [1879] failed
  systemd-udevd: bcache7: Retry 1 times.

This is not a one-off: the same kill/retry cycle repeats roughly every
3 minutes (11:04:03, 11:07:04, 11:10:05, ...) and by 11:04:03 it hits
essentially every NVMe partition on the box (nvme0n1p7-12,
nvme1n1p8/10/11/12). So the whole bcache management plane on this node
fails to come up cleanly at boot and keeps retrying for several
minutes, which in turn delays the LVM PV activation / Ceph OSD startup
that depends on these devices being ready (interleaved in the same
log window).

Expected behavior: recovering one cache_set (journal replay + btree
check, whose duration scales with device capacity/health and is not
bounded) should only make operations on *that* device wait. It should
not block sysfs access to other, already-running cache_sets/cached_devs,
and it should not block registration of other, unrelated cache
devices.

> At the first glance, I feel this patch doesn't have enough testing. e.g. the
> race between bcache_reboot() and bcd_cache_set_recover().

That is a fair concern, and I want to be precise about what I have and
have not actually verified, rather than just argue from the code.

What I did check: bch_cache_set_recover() only runs unlocked on a
cache_set that was just allocated by bch_cache_set_alloc(). The
CACHE_SET_REGISTERING flag is set and the cache_set is list_add()'d
into bch_cache_sets in the *same* bch_register_lock critical section as
the allocation, before the lock is dropped for recovery. So
bcache_reboot()'s list_empty(&bch_cache_sets) checks and its
mutex_lock()-protected wait loop see this cache_set for its entire
recovery, the same as any other cache_set that takes a while to stop -
there is no window where it is invisible to bcache_reboot().

What I have not done is actually exercise this interleaving: trigger a
reboot while a cache_set is mid-recovery and confirm bcache_reboot()
waits for it correctly instead of assuming based on the code path. I'd
rather get that data than keep arguing from the source. If you have a
specific interleaving in mind that you think breaks this, please point
it out and I will either fix it or build a targeted reproduction
(e.g. an artificial delay inside bch_cache_set_recover() to widen the
window and drive bcache_reboot() through it) and report back with
results before asking you to look at the patch again.

Thanks,
Qiliang