PTP vclock: BUG: scheduling while atomic

PTP vclock: BUG: scheduling while atomic

[Íñigo Huguet]

Hello,

Our QA team was testing PTP vclocks, and they've found this error with sfc NIC/driver:
  BUG: scheduling while atomic: ptp5/25223/0x00000002

The reason seems to be that vclocks disable interrupts with `spin_lock_irqsave` in
`ptp_vclock_gettime`, and then read the timecounter, which in turns ends calling to
the driver's `gettime64` callback.

Vclock framework was added in commit 5d43f951b1ac ("ptp: add ptp virtual clock driver
framework").

At first glance, it seems that vclock framework is reusing the already existing callbacks
of the drivers' ptp clocks, but it's imposing a new limitation that didn't exist before:
now they can't sleep (due the spin_lock_irqsave). Sfc driver might sleep waiting for the
fw response.

Sfc driver can be fixed to avoid this issue, but I wonder if something might not be
correct in the vclock framework. I don't have enough knowledge about how clocks
synchronization should work regarding this, so I leave it to your consideration.

These are the logs with stack traces:
 BUG: scheduling while atomic: ptp5/25223/0x00000002
 [...skip...]
 Call Trace:
  dump_stack_lvl+0x34/0x48
  __schedule_bug.cold+0x47/0x53
  __schedule+0x40e/0x580
  schedule+0x43/0xa0
  schedule_timeout+0x88/0x160
  ? __bpf_trace_tick_stop+0x10/0x10
  _efx_mcdi_rpc_finish+0x2a9/0x480 [sfc]
  ? efx_mcdi_send_request+0x1d5/0x260 [sfc]
  ? dequeue_task_stop+0x70/0x70
  _efx_mcdi_rpc.constprop.0+0xcd/0x3d0 [sfc]
  ? update_load_avg+0x7e/0x730
  _efx_mcdi_rpc_evb_retry+0x5d/0x1d0 [sfc]
  efx_mcdi_rpc+0x10/0x20 [sfc]
  efx_phc_gettime+0x5f/0xc0 [sfc]
  ptp_vclock_read+0xa3/0xc0
  timecounter_read+0x11/0x60
  ptp_vclock_refresh+0x31/0x60
  ? ptp_clock_release+0x50/0x50
  ptp_aux_kworker+0x19/0x40
  kthread_worker_fn+0xa9/0x250
  ? kthread_should_park+0x30/0x30
  kthread+0x146/0x170
  ? set_kthread_struct+0x50/0x50
  ret_from_fork+0x1f/0x30
 BUG: scheduling while atomic: ptp5/25223/0x00000000
 [...skip...]
 Call Trace:
  dump_stack_lvl+0x34/0x48
  __schedule_bug.cold+0x47/0x53
  __schedule+0x40e/0x580
  ? ptp_clock_release+0x50/0x50
  schedule+0x43/0xa0
  kthread_worker_fn+0x128/0x250
  ? kthread_should_park+0x30/0x30
  kthread+0x146/0x170
  ? set_kthread_struct+0x50/0x50
  ret_from_fork+0x1f/0x30

Re: PTP vclock: BUG: scheduling while atomic

[Miroslav Lichvar]

On Thu, Feb 02, 2023 at 05:02:07PM +0100, Íñigo Huguet wrote:
> Our QA team was testing PTP vclocks, and they've found this error with sfc NIC/driver:
>   BUG: scheduling while atomic: ptp5/25223/0x00000002
> 
> The reason seems to be that vclocks disable interrupts with `spin_lock_irqsave` in
> `ptp_vclock_gettime`, and then read the timecounter, which in turns ends calling to
> the driver's `gettime64` callback.

The same issue was observed with the ice driver:
https://lists.osuosl.org/pipermail/intel-wired-lan/Week-of-Mon-20221107/030633.html

I tried to fix it generally in the vclock support, but was not
successful. There was a hint it would be fixed in the driver. I'm not
sure what is the best approach here.

-- 
Miroslav Lichvar

Re: PTP vclock: BUG: scheduling while atomic

[Jacob Keller]

On 2/2/2023 8:33 AM, Miroslav Lichvar wrote:
> On Thu, Feb 02, 2023 at 05:02:07PM +0100, Íñigo Huguet wrote:
>> Our QA team was testing PTP vclocks, and they've found this error with sfc NIC/driver:
>>   BUG: scheduling while atomic: ptp5/25223/0x00000002
>>
>> The reason seems to be that vclocks disable interrupts with `spin_lock_irqsave` in
>> `ptp_vclock_gettime`, and then read the timecounter, which in turns ends calling to
>> the driver's `gettime64` callback.
> 
> The same issue was observed with the ice driver:
> https://lists.osuosl.org/pipermail/intel-wired-lan/Week-of-Mon-20221107/030633.html
> 
> I tried to fix it generally in the vclock support, but was not
> successful. There was a hint it would be fixed in the driver. I'm not
> sure what is the best approach here.
> 

This slipped through the cracks. The root cause (for ice) is that the
.gettime callback might sleep while waiting for the HW semaphore registers.

We had a change that fixed this (though we had done it for other
reasons) by simply not blocking gettime access with the semaphore, but
Richard didn't like this approach and NAK'd the patch on netdev:

https://lore.kernel.org/intel-wired-lan/877d0yt0ns.fsf@intel.com/

Alternatives are challenging here as the semaphore is used across
multiple PFs which makes using a spinlock difficult, as the PFs don't
share any references.

We could switch the part that does usleep to udelay instead, so we
wouldn't cause this scheduling bug... not sure if that has any other
side effects.

I'm not sure if there's another way to drop the semaphore and assuage
concerns over correctness. We need to read the time registers and its
possible another thread (or in principle another PF) is modifying the
time. We only expose a single PTP clock device, but all PFs can access
the time for the purpose of caching value used for extending 40bit
timestamps.

Re: PTP vclock: BUG: scheduling while atomic

[Richard Cochran]

On Thu, Feb 02, 2023 at 05:33:15PM +0100, Miroslav Lichvar wrote:
> On Thu, Feb 02, 2023 at 05:02:07PM +0100, Íñigo Huguet wrote:
> > Our QA team was testing PTP vclocks, and they've found this error with sfc NIC/driver:
> >   BUG: scheduling while atomic: ptp5/25223/0x00000002
> > 
> > The reason seems to be that vclocks disable interrupts with `spin_lock_irqsave` in
> > `ptp_vclock_gettime`, and then read the timecounter, which in turns ends calling to
> > the driver's `gettime64` callback.
> 
> The same issue was observed with the ice driver:
> https://lists.osuosl.org/pipermail/intel-wired-lan/Week-of-Mon-20221107/030633.html
> 
> I tried to fix it generally in the vclock support, but was not
> successful. There was a hint it would be fixed in the driver. I'm not
> sure what is the best approach here.

Can ptp_vclock_gettime use a mutex instead?

Thanks,
Richard

Re: PTP vclock: BUG: scheduling while atomic

[Martin Habets]

On Thu, Feb 02, 2023 at 05:02:07PM +0100, Íñigo Huguet wrote:
> Hello,
> 
> Our QA team was testing PTP vclocks, and they've found this error with sfc NIC/driver:
>   BUG: scheduling while atomic: ptp5/25223/0x00000002
> 
> The reason seems to be that vclocks disable interrupts with `spin_lock_irqsave` in
> `ptp_vclock_gettime`, and then read the timecounter, which in turns ends calling to
> the driver's `gettime64` callback.
> 
> Vclock framework was added in commit 5d43f951b1ac ("ptp: add ptp virtual clock driver
> framework").

Looking at that commit we'll face the same spinlock issue in
ptp_vclock_adjfine and ptp_vclock_adjtime.

> At first glance, it seems that vclock framework is reusing the already existing callbacks
> of the drivers' ptp clocks, but it's imposing a new limitation that didn't exist before:
> now they can't sleep (due the spin_lock_irqsave). Sfc driver might sleep waiting for the
> fw response.
> 
> Sfc driver can be fixed to avoid this issue, but I wonder if something might not be
> correct in the vclock framework. I don't have enough knowledge about how clocks
> synchronization should work regarding this, so I leave it to your consideration.

If the timer hardware is local to the CPU core a spinlock could work.
But if it global across CPUs, or like in our case remote behind a PCI bus,
using a spinlock is too much of a restriction.
I also wonder why the spinlock was used, and if that limitation can be
reduced.

Martin

> These are the logs with stack traces:
>  BUG: scheduling while atomic: ptp5/25223/0x00000002
>  [...skip...]
>  Call Trace:
>   dump_stack_lvl+0x34/0x48
>   __schedule_bug.cold+0x47/0x53
>   __schedule+0x40e/0x580
>   schedule+0x43/0xa0
>   schedule_timeout+0x88/0x160
>   ? __bpf_trace_tick_stop+0x10/0x10
>   _efx_mcdi_rpc_finish+0x2a9/0x480 [sfc]
>   ? efx_mcdi_send_request+0x1d5/0x260 [sfc]
>   ? dequeue_task_stop+0x70/0x70
>   _efx_mcdi_rpc.constprop.0+0xcd/0x3d0 [sfc]
>   ? update_load_avg+0x7e/0x730
>   _efx_mcdi_rpc_evb_retry+0x5d/0x1d0 [sfc]
>   efx_mcdi_rpc+0x10/0x20 [sfc]
>   efx_phc_gettime+0x5f/0xc0 [sfc]
>   ptp_vclock_read+0xa3/0xc0
>   timecounter_read+0x11/0x60
>   ptp_vclock_refresh+0x31/0x60
>   ? ptp_clock_release+0x50/0x50
>   ptp_aux_kworker+0x19/0x40
>   kthread_worker_fn+0xa9/0x250
>   ? kthread_should_park+0x30/0x30
>   kthread+0x146/0x170
>   ? set_kthread_struct+0x50/0x50
>   ret_from_fork+0x1f/0x30
>  BUG: scheduling while atomic: ptp5/25223/0x00000000
>  [...skip...]
>  Call Trace:
>   dump_stack_lvl+0x34/0x48
>   __schedule_bug.cold+0x47/0x53
>   __schedule+0x40e/0x580
>   ? ptp_clock_release+0x50/0x50
>   schedule+0x43/0xa0
>   kthread_worker_fn+0x128/0x250
>   ? kthread_should_park+0x30/0x30
>   kthread+0x146/0x170
>   ? set_kthread_struct+0x50/0x50
>   ret_from_fork+0x1f/0x30

Re: PTP vclock: BUG: scheduling while atomic

[Íñigo Huguet]

On Fri, Feb 3, 2023 at 1:10 AM Richard Cochran <richardcochran@gmail.com> wrote:
>
> On Thu, Feb 02, 2023 at 05:33:15PM +0100, Miroslav Lichvar wrote:
> > On Thu, Feb 02, 2023 at 05:02:07PM +0100, Íñigo Huguet wrote:
> > > Our QA team was testing PTP vclocks, and they've found this error with sfc NIC/driver:
> > >   BUG: scheduling while atomic: ptp5/25223/0x00000002
> > >
> > > The reason seems to be that vclocks disable interrupts with `spin_lock_irqsave` in
> > > `ptp_vclock_gettime`, and then read the timecounter, which in turns ends calling to
> > > the driver's `gettime64` callback.
> >
> > The same issue was observed with the ice driver:
> > https://lists.osuosl.org/pipermail/intel-wired-lan/Week-of-Mon-20221107/030633.html
> >
> > I tried to fix it generally in the vclock support, but was not
> > successful. There was a hint it would be fixed in the driver. I'm not
> > sure what is the best approach here.
>
> Can ptp_vclock_gettime use a mutex instead?

I don't see any place where these vclock functions are called in
atomic context, so it might be possible, but there are many callback
indirections and I'm not sure if I might have missed any.

>
> Thanks,
> Richard
>


-- 
Íñigo Huguet