Valentine reported seeing:
[ 3.626638] INFO: trying to register non-static key.
[ 3.626639] the code is fine but needs lockdep annotation.
[ 3.626640] turning off the locking correctness validator.
[ 3.626644] CPU: 7 PID: 51 Comm: kworker/7:1 Not tainted 5.7.0-rc2-00115-g8c2e9790f196 #116
[ 3.626646] Hardware name: HiKey960 (DT)
[ 3.626656] Workqueue: events deferred_probe_work_func
[ 3.632476] sd 0:0:0:0: [sda] Optimal transfer size 8192 bytes not a multiple of physical block size (16384 bytes)
[ 3.640220] Call trace:
[ 3.640225] dump_backtrace+0x0/0x1b8
[ 3.640227] show_stack+0x20/0x30
[ 3.640230] dump_stack+0xec/0x158
[ 3.640234] register_lock_class+0x598/0x5c0
[ 3.640235] __lock_acquire+0x80/0x16c0
[ 3.640236] lock_acquire+0xf4/0x4a0
[ 3.640241] _raw_spin_lock_irqsave+0x70/0xa8
[ 3.640245] uart_add_one_port+0x388/0x4b8
[ 3.640248] pl011_register_port+0x70/0xf0
[ 3.640250] pl011_probe+0x184/0x1b8
[ 3.640254] amba_probe+0xdc/0x180
[ 3.640256] really_probe+0xe0/0x338
[ 3.640257] driver_probe_device+0x60/0xf8
[ 3.640259] __device_attach_driver+0x8c/0xd0
[ 3.640260] bus_for_each_drv+0x84/0xd8
[ 3.640261] __device_attach+0xe4/0x140
[ 3.640263] device_initial_probe+0x1c/0x28
[ 3.640265] bus_probe_device+0xa4/0xb0
[ 3.640266] deferred_probe_work_func+0x7c/0xb8
[ 3.640269] process_one_work+0x2c0/0x768
[ 3.640271] worker_thread+0x4c/0x498
[ 3.640272] kthread+0x14c/0x158
[ 3.640275] ret_from_fork+0x10/0x1c
Which seems to be due to the fact that after allocating the uap
structure, the pl011 code doesn't initialize the spinlock.
This patch fixes it by initializing the spinlock and the warning
has gone away.
CC: Valentin Schneider <[email protected]>
Cc: Russell King <[email protected]>
Cc: Greg Kroah-Hartman <[email protected]>
Cc: Jiri Slaby <[email protected]>
Cc: [email protected]
Reported-by: Valentin Schneider <[email protected]>
Signed-off-by: John Stultz <[email protected]>
---
drivers/tty/serial/amba-pl011.c | 1 +
1 file changed, 1 insertion(+)
diff --git a/drivers/tty/serial/amba-pl011.c b/drivers/tty/serial/amba-pl011.c
index 2296bb0f9578..458fc3d9d48c 100644
--- a/drivers/tty/serial/amba-pl011.c
+++ b/drivers/tty/serial/amba-pl011.c
@@ -2575,6 +2575,7 @@ static int pl011_setup_port(struct device *dev, struct uart_amba_port *uap,
uap->port.has_sysrq = IS_ENABLED(CONFIG_SERIAL_AMBA_PL011_CONSOLE);
uap->port.flags = UPF_BOOT_AUTOCONF;
uap->port.line = index;
+ spin_lock_init(&uap->port.lock);
amba_ports[index] = uap;
--
2.17.1
Hi John,
On 23/04/20 23:00, John Stultz wrote:
> Which seems to be due to the fact that after allocating the uap
> structure, the pl011 code doesn't initialize the spinlock.
>
> This patch fixes it by initializing the spinlock and the warning
> has gone away.
>
Thanks for having a look. It does seem like the reasonable thing to do, and
I no longer get the warning on h960.
That said, I got more curious as this doesn't show up on my Juno (same
Image). Digging into it I see that uart_add_one_port() has a call to
uart_port_spin_lock_init() a few lines before uart_configure_port() (in
which the above warning gets triggered). That thing says:
* Ensure that the serial console lock is initialised early.
* If this port is a console, then the spinlock is already initialised.
Which requires me to ask: are we doing the right thing here?
> CC: Valentin Schneider <[email protected]>
> Cc: Russell King <[email protected]>
> Cc: Greg Kroah-Hartman <[email protected]>
> Cc: Jiri Slaby <[email protected]>
> Cc: [email protected]
> Reported-by: Valentin Schneider <[email protected]>
> Signed-off-by: John Stultz <[email protected]>
> ---
> drivers/tty/serial/amba-pl011.c | 1 +
> 1 file changed, 1 insertion(+)
>
> diff --git a/drivers/tty/serial/amba-pl011.c b/drivers/tty/serial/amba-pl011.c
> index 2296bb0f9578..458fc3d9d48c 100644
> --- a/drivers/tty/serial/amba-pl011.c
> +++ b/drivers/tty/serial/amba-pl011.c
> @@ -2575,6 +2575,7 @@ static int pl011_setup_port(struct device *dev, struct uart_amba_port *uap,
> uap->port.has_sysrq = IS_ENABLED(CONFIG_SERIAL_AMBA_PL011_CONSOLE);
> uap->port.flags = UPF_BOOT_AUTOCONF;
> uap->port.line = index;
> + spin_lock_init(&uap->port.lock);
>
> amba_ports[index] = uap;
On Thu, Apr 23, 2020 at 4:14 PM Valentin Schneider
<[email protected]> wrote:
> On 23/04/20 23:00, John Stultz wrote:
> > Which seems to be due to the fact that after allocating the uap
> > structure, the pl011 code doesn't initialize the spinlock.
> >
> > This patch fixes it by initializing the spinlock and the warning
> > has gone away.
> >
>
> Thanks for having a look. It does seem like the reasonable thing to do, and
> I no longer get the warning on h960.
>
> That said, I got more curious as this doesn't show up on my Juno (same
> Image). Digging into it I see that uart_add_one_port() has a call to
> uart_port_spin_lock_init() a few lines before uart_configure_port() (in
> which the above warning gets triggered). That thing says:
>
> * Ensure that the serial console lock is initialised early.
> * If this port is a console, then the spinlock is already initialised.
>
> Which requires me to ask: are we doing the right thing here?
Hrm. All good points. Obviously from the details above the port->lock
initialization shouldn't be done in the way this patch proposes, but
I'm at a loss as to why we're hitting the issue. My guess is it is
tripping over the console case, but didn't get initialized there
properly?
I'll try to trace through the code to see more about what's going on.
thanks
-john
On Thu, Apr 23, 2020 at 4:14 PM Valentin Schneider
<[email protected]> wrote:
> On 23/04/20 23:00, John Stultz wrote:
> > Which seems to be due to the fact that after allocating the uap
> > structure, the pl011 code doesn't initialize the spinlock.
> >
> > This patch fixes it by initializing the spinlock and the warning
> > has gone away.
> >
>
> Thanks for having a look. It does seem like the reasonable thing to do, and
> I no longer get the warning on h960.
>
> That said, I got more curious as this doesn't show up on my Juno (same
> Image). Digging into it I see that uart_add_one_port() has a call to
> uart_port_spin_lock_init() a few lines before uart_configure_port() (in
> which the above warning gets triggered). That thing says:
>
> * Ensure that the serial console lock is initialised early.
> * If this port is a console, then the spinlock is already initialised.
>
> Which requires me to ask: are we doing the right thing here?
So I got a little bit of time to look at this before I got pulled off
to other things (and now its Friday night, so I figured I'd reply
before I forget it on Monday).
I did check and lockdep is tripping when we add ttyAMA6 which is the
serial console on the board. I wasn't able to trace back to why we
hadn't already called spin_lock_init() in the console code, but it
seems we haven't.
Also I checked on HiKey as well, and there I'm seeing the same lockdep
splat and this fix seems to resolve it. So more digging is needed. If
anyone has a better idea of what might be awry or if the lock does
need to be initialized in the driver (it's a bit inconsistent, I see
some drivers do but others don't), let me know.
thanks
-john
On 25/04/20 05:04, John Stultz wrote:
> On Thu, Apr 23, 2020 at 4:14 PM Valentin Schneider
> <[email protected]> wrote:
>> On 23/04/20 23:00, John Stultz wrote:
>> > Which seems to be due to the fact that after allocating the uap
>> > structure, the pl011 code doesn't initialize the spinlock.
>> >
>> > This patch fixes it by initializing the spinlock and the warning
>> > has gone away.
>> >
>>
>> Thanks for having a look. It does seem like the reasonable thing to do, and
>> I no longer get the warning on h960.
>>
>> That said, I got more curious as this doesn't show up on my Juno (same
>> Image). Digging into it I see that uart_add_one_port() has a call to
>> uart_port_spin_lock_init() a few lines before uart_configure_port() (in
>> which the above warning gets triggered). That thing says:
>>
>> * Ensure that the serial console lock is initialised early.
>> * If this port is a console, then the spinlock is already initialised.
>>
>> Which requires me to ask: are we doing the right thing here?
>
> So I got a little bit of time to look at this before I got pulled off
> to other things (and now its Friday night, so I figured I'd reply
> before I forget it on Monday).
>
> I did check and lockdep is tripping when we add ttyAMA6 which is the
> serial console on the board. I wasn't able to trace back to why we
> hadn't already called spin_lock_init() in the console code, but it
> seems we haven't.
>
So on the Juno (ttyAMA0), the first time I see us hitting
uart_port_spin_lock_init() is via:
uart_add_one_port() -> uart_port_spin_lock_init()
Since port->cons->(index, line) is (-1, 0) at this point in time,
uart_console(port) returns false and we init the spinlock. When then
happily trickle down to uart_configure_port() -> register_console()
On the Hikey960 (ttyAMA6) I see the same initial flow, but (index, line)
is (6, 6), so uart_console(port) returns true and we skip the
spin_lock_init(). When then hit the splat on the rest of the way down
uart_add_one_port().
I did a tiny bit of git spelunking; I found a commit that changed
uart_console_enabled() into uart_console() within
uart_port_spin_lock_init():
a3cb39d258ef ("serial: core: Allow detach and attach serial device for console")
Reverting just that one change in uart_port_spin_lock_init() seems to go
fine on both Juno & HiKey960, but I think that doesn't play well with the
rest of the aforementioned commit. I think that this initial (index, line)
tuple is to blame, though I've added Andy in Cc just in case.
> Also I checked on HiKey as well, and there I'm seeing the same lockdep
> splat and this fix seems to resolve it. So more digging is needed. If
> anyone has a better idea of what might be awry or if the lock does
> need to be initialized in the driver (it's a bit inconsistent, I see
> some drivers do but others don't), let me know.
>
> thanks
> -john
On Mon, Apr 27, 2020 at 2:29 AM Valentin Schneider
<[email protected]> wrote:
>
>
> On 25/04/20 05:04, John Stultz wrote:
> > On Thu, Apr 23, 2020 at 4:14 PM Valentin Schneider
> > <[email protected]> wrote:
> >> On 23/04/20 23:00, John Stultz wrote:
> >> > Which seems to be due to the fact that after allocating the uap
> >> > structure, the pl011 code doesn't initialize the spinlock.
> >> >
> >> > This patch fixes it by initializing the spinlock and the warning
> >> > has gone away.
> >> >
> >>
> >> Thanks for having a look. It does seem like the reasonable thing to do, and
> >> I no longer get the warning on h960.
> >>
> >> That said, I got more curious as this doesn't show up on my Juno (same
> >> Image). Digging into it I see that uart_add_one_port() has a call to
> >> uart_port_spin_lock_init() a few lines before uart_configure_port() (in
> >> which the above warning gets triggered). That thing says:
> >>
> >> * Ensure that the serial console lock is initialised early.
> >> * If this port is a console, then the spinlock is already initialised.
> >>
> >> Which requires me to ask: are we doing the right thing here?
> >
> > So I got a little bit of time to look at this before I got pulled off
> > to other things (and now its Friday night, so I figured I'd reply
> > before I forget it on Monday).
> >
> > I did check and lockdep is tripping when we add ttyAMA6 which is the
> > serial console on the board. I wasn't able to trace back to why we
> > hadn't already called spin_lock_init() in the console code, but it
> > seems we haven't.
> >
>
> So on the Juno (ttyAMA0), the first time I see us hitting
> uart_port_spin_lock_init() is via:
>
> uart_add_one_port() -> uart_port_spin_lock_init()
>
> Since port->cons->(index, line) is (-1, 0) at this point in time,
> uart_console(port) returns false and we init the spinlock. When then
> happily trickle down to uart_configure_port() -> register_console()
>
>
> On the Hikey960 (ttyAMA6) I see the same initial flow, but (index, line)
> is (6, 6), so uart_console(port) returns true and we skip the
> spin_lock_init(). When then hit the splat on the rest of the way down
> uart_add_one_port().
>
>
> I did a tiny bit of git spelunking; I found a commit that changed
> uart_console_enabled() into uart_console() within
> uart_port_spin_lock_init():
>
> a3cb39d258ef ("serial: core: Allow detach and attach serial device for console")
>
> Reverting just that one change in uart_port_spin_lock_init() seems to go
> fine on both Juno & HiKey960, but I think that doesn't play well with the
> rest of the aforementioned commit. I think that this initial (index, line)
> tuple is to blame, though I've added Andy in Cc just in case.
The above mentioned commit reveals the issue in the code which doesn't
register console properly.
See what I put in 0f87aa66e8c31 ("serial: sunhv: Initialize lock for
non-registered console").
--
With Best Regards,
Andy Shevchenko
On Fri, Apr 24, 2020 at 1:06 AM John Stultz <[email protected]> wrote:
>
> Valentine reported seeing:
>
> [ 3.626638] INFO: trying to register non-static key.
> [ 3.626639] the code is fine but needs lockdep annotation.
> [ 3.626640] turning off the locking correctness validator.
> [ 3.626644] CPU: 7 PID: 51 Comm: kworker/7:1 Not tainted 5.7.0-rc2-00115-g8c2e9790f196 #116
> [ 3.626646] Hardware name: HiKey960 (DT)
> [ 3.626656] Workqueue: events deferred_probe_work_func
> [ 3.632476] sd 0:0:0:0: [sda] Optimal transfer size 8192 bytes not a multiple of physical block size (16384 bytes)
> [ 3.640220] Call trace:
> [ 3.640225] dump_backtrace+0x0/0x1b8
> [ 3.640227] show_stack+0x20/0x30
> [ 3.640230] dump_stack+0xec/0x158
> [ 3.640234] register_lock_class+0x598/0x5c0
> [ 3.640235] __lock_acquire+0x80/0x16c0
> [ 3.640236] lock_acquire+0xf4/0x4a0
> [ 3.640241] _raw_spin_lock_irqsave+0x70/0xa8
> [ 3.640245] uart_add_one_port+0x388/0x4b8
> [ 3.640248] pl011_register_port+0x70/0xf0
> [ 3.640250] pl011_probe+0x184/0x1b8
> [ 3.640254] amba_probe+0xdc/0x180
> [ 3.640256] really_probe+0xe0/0x338
> [ 3.640257] driver_probe_device+0x60/0xf8
> [ 3.640259] __device_attach_driver+0x8c/0xd0
> [ 3.640260] bus_for_each_drv+0x84/0xd8
> [ 3.640261] __device_attach+0xe4/0x140
> [ 3.640263] device_initial_probe+0x1c/0x28
> [ 3.640265] bus_probe_device+0xa4/0xb0
> [ 3.640266] deferred_probe_work_func+0x7c/0xb8
> [ 3.640269] process_one_work+0x2c0/0x768
> [ 3.640271] worker_thread+0x4c/0x498
> [ 3.640272] kthread+0x14c/0x158
> [ 3.640275] ret_from_fork+0x10/0x1c
>
> Which seems to be due to the fact that after allocating the uap
> structure, the pl011 code doesn't initialize the spinlock.
>
> This patch fixes it by initializing the spinlock and the warning
> has gone away.
>
I think it's step to the right direction. FWIW,
Reviewed-by: Andy Shevchenko <[email protected]>
> CC: Valentin Schneider <[email protected]>
> Cc: Russell King <[email protected]>
> Cc: Greg Kroah-Hartman <[email protected]>
> Cc: Jiri Slaby <[email protected]>
> Cc: [email protected]
> Reported-by: Valentin Schneider <[email protected]>
> Signed-off-by: John Stultz <[email protected]>
> ---
> drivers/tty/serial/amba-pl011.c | 1 +
> 1 file changed, 1 insertion(+)
>
> diff --git a/drivers/tty/serial/amba-pl011.c b/drivers/tty/serial/amba-pl011.c
> index 2296bb0f9578..458fc3d9d48c 100644
> --- a/drivers/tty/serial/amba-pl011.c
> +++ b/drivers/tty/serial/amba-pl011.c
> @@ -2575,6 +2575,7 @@ static int pl011_setup_port(struct device *dev, struct uart_amba_port *uap,
> uap->port.has_sysrq = IS_ENABLED(CONFIG_SERIAL_AMBA_PL011_CONSOLE);
> uap->port.flags = UPF_BOOT_AUTOCONF;
> uap->port.line = index;
> + spin_lock_init(&uap->port.lock);
>
> amba_ports[index] = uap;
>
> --
> 2.17.1
>
--
With Best Regards,
Andy Shevchenko
On 27/04/20 10:02, Andy Shevchenko wrote:
>> I did a tiny bit of git spelunking; I found a commit that changed
>> uart_console_enabled() into uart_console() within
>> uart_port_spin_lock_init():
>>
>> a3cb39d258ef ("serial: core: Allow detach and attach serial device for console")
>>
>> Reverting just that one change in uart_port_spin_lock_init() seems to go
>> fine on both Juno & HiKey960, but I think that doesn't play well with the
>> rest of the aforementioned commit. I think that this initial (index, line)
>> tuple is to blame, though I've added Andy in Cc just in case.
>
> The above mentioned commit reveals the issue in the code which doesn't
> register console properly.
>
> See what I put in 0f87aa66e8c31 ("serial: sunhv: Initialize lock for
> non-registered console").
Thanks for the pointer. I'm still a puzzled as to why it goes fine on one
board and not on another, but at this point I don't have any better
suggestion than the unconditional init.
On Tue, Apr 28, 2020 at 11:54 AM Valentin Schneider
<[email protected]> wrote:
>
>
> On 27/04/20 10:02, Andy Shevchenko wrote:
> >> I did a tiny bit of git spelunking; I found a commit that changed
> >> uart_console_enabled() into uart_console() within
> >> uart_port_spin_lock_init():
> >>
> >> a3cb39d258ef ("serial: core: Allow detach and attach serial device for console")
> >>
> >> Reverting just that one change in uart_port_spin_lock_init() seems to go
> >> fine on both Juno & HiKey960, but I think that doesn't play well with the
> >> rest of the aforementioned commit. I think that this initial (index, line)
> >> tuple is to blame, though I've added Andy in Cc just in case.
> >
> > The above mentioned commit reveals the issue in the code which doesn't
> > register console properly.
> >
> > See what I put in 0f87aa66e8c31 ("serial: sunhv: Initialize lock for
> > non-registered console").
>
> Thanks for the pointer. I'm still a puzzled as to why it goes fine on one
> board and not on another, but at this point I don't have any better
> suggestion than the unconditional init.
My patch relied on the behaviour of 8250 [1] and that comment (near to
spin lock initialization routine).
It seems AMBA UART drivers unconditionally assign consoles ([2], [3])
without registering it properly at console_initcall().
Least invasive fix is what John's patch does, but real fix is to do
something like 8250 does.
So, the rule of thumb is simple: if we assign console to the port we
must initialize the lock even if we are not registering console.
I dunno the history of different behaviours among drivers and what
change(s) brought us to the messy spin lock initialization code in
them.
[1]: https://elixir.bootlin.com/linux/v5.7-rc3/source/drivers/tty/serial/8250/8250_core.c#L684
[2]: https://elixir.bootlin.com/linux/v5.7-rc3/source/drivers/tty/serial/amba-pl010.c#L691
[3]: https://elixir.bootlin.com/linux/v5.7-rc3/source/drivers/tty/serial/amba-pl011.c#L2496
--
With Best Regards,
Andy Shevchenko