* ptp_vclock bug: Obtaining a mutex during RCU lock
@ 2025-06-03 12:19 Florian Zeitz
2026-05-19 15:32 ` Kurt Kanzenbach
0 siblings, 1 reply; 2+ messages in thread
From: Florian Zeitz @ 2025-06-03 12:19 UTC (permalink / raw)
To: yangbo.lu; +Cc: netdev
Hi,
I believe I have found a bug in the PTP vclock implementation.
Occasionally, when running ptp4l and phc2sys on a virtual clock, I
encounter the following warning from within the ptp4l process (full
backtrace below):
"Voluntary context switch within RCU read-side critical section!"
As the backtrace shows the warning originates from
`ptp_convert_timestamp()` in drivers/ptp/ptp_vclock.c, specifically line
203 where `mutex_lock_interruptible()` is called inside an RCU read-side
critical section.
Having read up on RCU, it seems to me that trying to obtain a mutex
during an RCU lock is generally not allowed and voids the RCU lock
should scheduling happen.
This can occur whenever a timestamped packet is received while the mutex
is still held by another call, in my case `ptp_vclock_gettime()`.
To make this easier to reproduce, I've written a small test program that
triggers frequent locking:
```c
#define _GNU_SOURCE
#include <fcntl.h>
#include <sys/stat.h>
#include <sys/timex.h>
#include <time.h>
#define CLOCKFD 3
#define FD_TO_CLOCKID(fd) ((~(clockid_t)(fd) << 3) | CLOCKFD)
int main(void) {
struct timespec time;
struct timex tmx = {0};
int fd = open("/dev/ptp1", O_RDWR);
clockid_t clock = FD_TO_CLOCKID(fd);
while (1) {
clock_gettime(clock, &time);
clock_adjtime(clock, &tmx);
}
}
```
Running this in parallel with ptp4l (in a gPTP setup, which sends SYNC
messages at a higher rate than the default profile) typically reproduces
the issue within a few minutes.
Best Regards,
Florian Zeitz
```
[ 1084.825057] ------------[ cut here ]------------
[ 1084.825072] Voluntary context switch within RCU read-side critical
section!
[ 1084.825091] WARNING: CPU: 1 PID: 677 at kernel/rcu/tree_plugin.h:331
rcu_note_context_switch+0x4e4/0x
530
[ 1084.825118] Modules linked in: rfkill rtc_pcf85063 regmap_i2c emc2305
v3d vc4 snd_soc_hdmi_codec binf
mt_misc gpu_sched drm_display_helper cec drm_shmem_helper drm_dma_helper
bcm2835_codec(C) bcm2835_isp(C) rpi_hevc_dec bcm2835_v4l2(C)
snd_soc_core drm_kms_helper bcm2835_mmal_vchiq(C) videobuf2_vmalloc
snd_compress vc_sm_cma(C) v4l2_mem2mem snd_pcm_dmaengine
videobuf2_dma_contig raspberrypi_hwmon i2c_mux_pinctrl videobuf2_memops
videobuf2_v4l2 i2c_mux videodev snd_bcm2835(C) i2c_brcmstb snd_pcm
snd_timer raspberrypi_gpiomem i2c_bcm2835 videobuf2_common mc snd
pps_gpio nvmem_rmem uio_pdrv_genirq uio drm fuse
drm_panel_orientation_quirks backlight dm_mod ip_tables x_tables ipv6
[ 1084.825259] CPU: 1 UID: 0 PID: 677 Comm: ptp4l Tainted: G C
6.12.30-v8-ptpfix+ #2
[ 1084.825269] Tainted: [C]=CRAP
[ 1084.825272] Hardware name: Raspberry Pi Compute Module 4 Rev 1.1 (DT)
[ 1084.825277] pstate: 600000c5 (nZCv daIF -PAN -UAO -TCO -DIT -SSBS
BTYPE=--)
[ 1084.825283] pc : rcu_note_context_switch+0x4e4/0x530
[ 1084.825291] lr : rcu_note_context_switch+0x4e4/0x530
[ 1084.825298] sp : ffffffc08162b7e0
[ 1084.825302] x29: ffffffc08162b7e0 x28: ffffff8046414200 x27:
ffffff807fb78c40
[ 1084.825313] x26: 0000000000000001 x25: 0000000000000000 x24:
0000000000000000
[ 1084.825324] x23: ffffff8046414200 x22: 0000000000000000 x21:
ffffff8046414200
[ 1084.825335] x20: 0000000000000000 x19: ffffff807fb79a40 x18:
0000000000000000
[ 1084.825345] x17: 0000000000000000 x16: 0000000000000000 x15:
0000000000000000
[ 1084.825355] x14: fffffffffffc78ef x13: 216e6f6974636573 x12:
206c616369746972
[ 1084.825365] x11: ffffffd7ed4c54f8 x10: 00000000000001a8 x9 :
ffffffd7ec11e494
[ 1084.825375] x8 : 0000000000017fe8 x7 : 00000000fffff1a7 x6 :
ffffffd7ed51d4f8
[ 1084.825386] x5 : ffffff807fb663c8 x4 : 0000000000000000 x3 :
0000000000000027
[ 1084.825396] x2 : 0000000000000000 x1 : 0000000000000000 x0 :
ffffff8046414200
[ 1084.825406] Call trace:
[ 1084.825410] rcu_note_context_switch+0x4e4/0x530
[ 1084.825418] __schedule+0xac/0xb58
[ 1084.825425] schedule+0x3c/0x150
[ 1084.825429] schedule_preempt_disabled+0x2c/0x58
[ 1084.825435] __mutex_lock.constprop.0+0x464/0x940
[ 1084.825440] __mutex_lock_interruptible_slowpath+0x1c/0x30
[ 1084.825446] mutex_lock_interruptible+0x68/0x80
[ 1084.825452] ptp_convert_timestamp+0x8c/0xd0
[ 1084.825459] __sock_recv_timestamp+0x2f0/0x490
[ 1084.825466] __sock_recv_cmsgs+0x5c/0x168
[ 1084.825472] packet_recvmsg+0x130/0x540
[ 1084.825482] sock_recvmsg+0x78/0xd0
[ 1084.825487] ____sys_recvmsg+0xb0/0x250
[ 1084.825494] ___sys_recvmsg+0xd8/0x100
[ 1084.825500] __sys_recvmsg+0x8c/0x100
[ 1084.825507] __arm64_sys_recvmsg+0x2c/0x40
[ 1084.825513] invoke_syscall+0x50/0x120
[ 1084.825522] el0_svc_common.constprop.0+0x48/0xf0
[ 1084.825529] do_el0_svc+0x24/0x38
[ 1084.825536] el0_svc+0x30/0xd0
[ 1084.825543] el0t_64_sync_handler+0x120/0x130
[ 1084.825550] el0t_64_sync+0x190/0x198
[ 1084.825556] ---[ end trace 0000000000000000 ]---
```
^ permalink raw reply [flat|nested] 2+ messages in thread* Re: ptp_vclock bug: Obtaining a mutex during RCU lock
2025-06-03 12:19 ptp_vclock bug: Obtaining a mutex during RCU lock Florian Zeitz
@ 2026-05-19 15:32 ` Kurt Kanzenbach
0 siblings, 0 replies; 2+ messages in thread
From: Kurt Kanzenbach @ 2026-05-19 15:32 UTC (permalink / raw)
To: Florian Zeitz, yangbo.lu
Cc: Íñigo Huguet, Richard Cochran, Miroslav Lichvar,
Blanco Alcaine Hector, Christopher S. Hall,
Sebastian Andrzej Siewior, netdev
[-- Attachment #1: Type: text/plain, Size: 5659 bytes --]
Hi,
On Tue Jun 03 2025, Florian Zeitz wrote:
> Hi,
>
> I believe I have found a bug in the PTP vclock implementation.
>
> Occasionally, when running ptp4l and phc2sys on a virtual clock, I
> encounter the following warning from within the ptp4l process (full
> backtrace below):
> "Voluntary context switch within RCU read-side critical section!"
>
> As the backtrace shows the warning originates from
> `ptp_convert_timestamp()` in drivers/ptp/ptp_vclock.c, specifically line
> 203 where `mutex_lock_interruptible()` is called inside an RCU read-side
> critical section.
> Having read up on RCU, it seems to me that trying to obtain a mutex
> during an RCU lock is generally not allowed and voids the RCU lock
> should scheduling happen.
>
> This can occur whenever a timestamped packet is received while the mutex
> is still held by another call, in my case `ptp_vclock_gettime()`.
Yes. We're seeing exactly the same issue. Using a mutex in a RCU read
lock section is not allowed. Commit 67d93ffc0f3c ("ptp: vclock: use
mutex to fix "sleep on atomic" bug") introduced the mutex in the first
place.
Adding a few more people to Cc and keeping the context intact.
Any idea how to solve this? For example, using SRCU instead? Reverting
the commit in question?
Thanks,
Kurt
> To make this easier to reproduce, I've written a small test program that
> triggers frequent locking:
> ```c
> #define _GNU_SOURCE
>
> #include <fcntl.h>
> #include <sys/stat.h>
> #include <sys/timex.h>
> #include <time.h>
>
> #define CLOCKFD 3
> #define FD_TO_CLOCKID(fd) ((~(clockid_t)(fd) << 3) | CLOCKFD)
>
> int main(void) {
> struct timespec time;
> struct timex tmx = {0};
>
> int fd = open("/dev/ptp1", O_RDWR);
> clockid_t clock = FD_TO_CLOCKID(fd);
>
> while (1) {
> clock_gettime(clock, &time);
> clock_adjtime(clock, &tmx);
> }
> }
> ```
>
> Running this in parallel with ptp4l (in a gPTP setup, which sends SYNC
> messages at a higher rate than the default profile) typically reproduces
> the issue within a few minutes.
>
> Best Regards,
>
> Florian Zeitz
>
> ```
> [ 1084.825057] ------------[ cut here ]------------
> [ 1084.825072] Voluntary context switch within RCU read-side critical
> section!
> [ 1084.825091] WARNING: CPU: 1 PID: 677 at kernel/rcu/tree_plugin.h:331
> rcu_note_context_switch+0x4e4/0x
> 530
> [ 1084.825118] Modules linked in: rfkill rtc_pcf85063 regmap_i2c emc2305
> v3d vc4 snd_soc_hdmi_codec binf
> mt_misc gpu_sched drm_display_helper cec drm_shmem_helper drm_dma_helper
> bcm2835_codec(C) bcm2835_isp(C) rpi_hevc_dec bcm2835_v4l2(C)
> snd_soc_core drm_kms_helper bcm2835_mmal_vchiq(C) videobuf2_vmalloc
> snd_compress vc_sm_cma(C) v4l2_mem2mem snd_pcm_dmaengine
> videobuf2_dma_contig raspberrypi_hwmon i2c_mux_pinctrl videobuf2_memops
> videobuf2_v4l2 i2c_mux videodev snd_bcm2835(C) i2c_brcmstb snd_pcm
> snd_timer raspberrypi_gpiomem i2c_bcm2835 videobuf2_common mc snd
> pps_gpio nvmem_rmem uio_pdrv_genirq uio drm fuse
> drm_panel_orientation_quirks backlight dm_mod ip_tables x_tables ipv6
> [ 1084.825259] CPU: 1 UID: 0 PID: 677 Comm: ptp4l Tainted: G C
> 6.12.30-v8-ptpfix+ #2
> [ 1084.825269] Tainted: [C]=CRAP
> [ 1084.825272] Hardware name: Raspberry Pi Compute Module 4 Rev 1.1 (DT)
> [ 1084.825277] pstate: 600000c5 (nZCv daIF -PAN -UAO -TCO -DIT -SSBS
> BTYPE=--)
> [ 1084.825283] pc : rcu_note_context_switch+0x4e4/0x530
> [ 1084.825291] lr : rcu_note_context_switch+0x4e4/0x530
> [ 1084.825298] sp : ffffffc08162b7e0
> [ 1084.825302] x29: ffffffc08162b7e0 x28: ffffff8046414200 x27:
> ffffff807fb78c40
> [ 1084.825313] x26: 0000000000000001 x25: 0000000000000000 x24:
> 0000000000000000
> [ 1084.825324] x23: ffffff8046414200 x22: 0000000000000000 x21:
> ffffff8046414200
> [ 1084.825335] x20: 0000000000000000 x19: ffffff807fb79a40 x18:
> 0000000000000000
> [ 1084.825345] x17: 0000000000000000 x16: 0000000000000000 x15:
> 0000000000000000
> [ 1084.825355] x14: fffffffffffc78ef x13: 216e6f6974636573 x12:
> 206c616369746972
> [ 1084.825365] x11: ffffffd7ed4c54f8 x10: 00000000000001a8 x9 :
> ffffffd7ec11e494
> [ 1084.825375] x8 : 0000000000017fe8 x7 : 00000000fffff1a7 x6 :
> ffffffd7ed51d4f8
> [ 1084.825386] x5 : ffffff807fb663c8 x4 : 0000000000000000 x3 :
> 0000000000000027
> [ 1084.825396] x2 : 0000000000000000 x1 : 0000000000000000 x0 :
> ffffff8046414200
> [ 1084.825406] Call trace:
> [ 1084.825410] rcu_note_context_switch+0x4e4/0x530
> [ 1084.825418] __schedule+0xac/0xb58
> [ 1084.825425] schedule+0x3c/0x150
> [ 1084.825429] schedule_preempt_disabled+0x2c/0x58
> [ 1084.825435] __mutex_lock.constprop.0+0x464/0x940
> [ 1084.825440] __mutex_lock_interruptible_slowpath+0x1c/0x30
> [ 1084.825446] mutex_lock_interruptible+0x68/0x80
> [ 1084.825452] ptp_convert_timestamp+0x8c/0xd0
> [ 1084.825459] __sock_recv_timestamp+0x2f0/0x490
> [ 1084.825466] __sock_recv_cmsgs+0x5c/0x168
> [ 1084.825472] packet_recvmsg+0x130/0x540
> [ 1084.825482] sock_recvmsg+0x78/0xd0
> [ 1084.825487] ____sys_recvmsg+0xb0/0x250
> [ 1084.825494] ___sys_recvmsg+0xd8/0x100
> [ 1084.825500] __sys_recvmsg+0x8c/0x100
> [ 1084.825507] __arm64_sys_recvmsg+0x2c/0x40
> [ 1084.825513] invoke_syscall+0x50/0x120
> [ 1084.825522] el0_svc_common.constprop.0+0x48/0xf0
> [ 1084.825529] do_el0_svc+0x24/0x38
> [ 1084.825536] el0_svc+0x30/0xd0
> [ 1084.825543] el0t_64_sync_handler+0x120/0x130
> [ 1084.825550] el0t_64_sync+0x190/0x198
> [ 1084.825556] ---[ end trace 0000000000000000 ]---
> ```
>
[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 861 bytes --]
^ permalink raw reply [flat|nested] 2+ messages in thread
end of thread, other threads:[~2026-05-19 15:32 UTC | newest]
Thread overview: 2+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2025-06-03 12:19 ptp_vclock bug: Obtaining a mutex during RCU lock Florian Zeitz
2026-05-19 15:32 ` Kurt Kanzenbach
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox