SIGSTOP logd causes panic?

Hi, we're seeing a panic when we SIGSTOP the logd pid.

panic(cpu 2 caller 0xfffffe0020e9a364): userspace watchdog timeout: no successful checkins from logd (0 induced crashes) in 120 seconds

You may ask "well why would you do that?" and the answer is that we're seeing panics from watchdog/logd when we hammer the diskIO for a download/write (APFS sparse file creation) operation in our software.

Is it normal to see this?

We hit userspace watchdog panics (logd unresponsive on firehose I/O) during sustained writes into a large APFS file that was created with clonefile and then overwritten at many offsets. The workload was high-rate, relatively small pwrites with F_NOCACHE (and F_NODIRECT) on the clone. That behaved like sparse/COW allocation pressure even though the logical file size looked fully populated. Only reproducible on 2TB AP2048Z SSD. Couldn't get it to panic on any other type of hardware we have :(

We understand clone + overwrite implies COW extent work similar to sparse writes. We’re mainly sharing this as a data point: under prolonged high-IOPS uncached pwrite into a clone, APFS metadata / system services (esp. logd/firehose) can fall far enough behind to trip the userspace watchdog, and the failure mode is easy to misread as a 'preallocated file should be fine' thing.

Unfortunately we had to use customer hardware don't have any 2TB drives, but two customers did) and they won't allow us to share anything else. If it changes, I'll submit a feedback report. Otherwise we can just close this. I found a way to work around it.

Thanks!

Some other logs to understand what we're seeing:

com.apple.logd.store in TH_WAIT | TH_UNINT for ~120–200s

com.apple.firehose.drain-io / io-wl blocked behind it

then watchdog: no logd checkins for 120s

userspace watchdog timeout: no successful checkins from logd ... 120 seconds
unresponsive dispatch queue(s): com.apple.firehose.io-wl

Watchdog timeout panics when logd is unresponsive for so long are completely expected yes. As for:

we're seeing panics from watchdog/logd when we hammer the diskIO for a download/write (APFS sparse file creation) operation in our software.

Is the file sparse during the download process only, or is it supposed to remain sparse afterwards too? If the former, you are encouraged to use fcntl(F_PREALLOCATE) to fully allocate the blocks before initiating the download; this will ease the filesystem metadata load while subsequently writing out the file data and hopefully prevent this sort of issue. (It should also result in a more optimal write/allocation pattern for the file.)

Is there a way to disable logd to test around it? We tried log config --mode "level:off" but it didn't seem to prevent the panic.

We're actually using F_PREALLOCATE already which is what's so odd about this.

Not that I’m aware of, logd is a critical system component.

If you’re preallocating and the file is therefore not sparse then the issue you’re observing is definitely surprising. Some followup questions:

  1. Do you clone the file in question and then write to either of the clones? Because this would have a similar effect as if it were sparse (every offset needs to be allocated separately).
  2. Similarly is the file perhaps captured by a snapshot at the time it’s written to, for example because Time Machine is active?

If neither of these is true I would encourage you to file a feedback report that includes an Instruments trace from the time period that logd is unable to make progress, and/or the core of the panic itself.

Accepted Answer

We hit userspace watchdog panics (logd unresponsive on firehose I/O) during sustained writes into a large APFS file that was created with clonefile and then overwritten at many offsets. The workload was high-rate, relatively small pwrites with F_NOCACHE (and F_NODIRECT) on the clone. That behaved like sparse/COW allocation pressure even though the logical file size looked fully populated. Only reproducible on 2TB AP2048Z SSD. Couldn't get it to panic on any other type of hardware we have :(

We understand clone + overwrite implies COW extent work similar to sparse writes. We’re mainly sharing this as a data point: under prolonged high-IOPS uncached pwrite into a clone, APFS metadata / system services (esp. logd/firehose) can fall far enough behind to trip the userspace watchdog, and the failure mode is easy to misread as a 'preallocated file should be fine' thing.

Unfortunately we had to use customer hardware don't have any 2TB drives, but two customers did) and they won't allow us to share anything else. If it changes, I'll submit a feedback report. Otherwise we can just close this. I found a way to work around it.

Thanks!

SIGSTOP logd causes panic?
 
 
Q