2006-09-11 15:32:34

by Andrew Bird

[permalink] [raw]
Subject: Spinlock debugging

Hi all,
this is my first post to the list, so please be kind. I am working on the
nozomi (UMTS modem) driver, which is not in the main kernel.
I have a issue with the tty code. Currently the driver defines a 'put_char'
tty function but it is empty, except for a debug message. Now I know that
this means that the tty layer will use it to write single chars and so data
will be lost. But if I comment out the line that tells the tty layer that
it's implemented, I end up with a BUG - spinlock recursion. Can anybody tell
me how to interpret the output?

Thanks and please CC as I'm not subscribed to the list

Andrew


[856] nozomi_read_config_table(): Initialization OK!
BUG: spinlock recursion on CPU#0, minicom/1918
lock: dc4fade4, .magic: dead4ead, .owner: minicom/1918, .owner_cpu: 0
[<c01bb897>] _raw_spin_lock+0x31/0x65
[<c02c5fd6>] _spin_lock_irqsave+0x9/0xd
[<e08b7de7>] ntty_write+0x35/0xf2 [nozomi]
[<c0116672>] scheduler_tick+0x9d/0x2af
[<c0106792>] timer_interrupt+0x73/0x7a
[<c01fa505>] tty_default_put_char+0x15/0x18
[<c01facfd>] opost+0x93/0x1ce
[<c01fb96e>] n_tty_receive_buf+0x52b/0xb37
[<c0103542>] common_interrupt+0x1a/0x20
[<c011007b>] wakeup_code+0x7b/0xba
[<c0119e01>] release_console_sem+0x74/0xa9
[<c0119ce8>] vprintk+0x1d1/0x1f5
[<c0106792>] timer_interrupt+0x73/0x7a
[<c01ba361>] vsnprintf+0x45a/0x497
[<c01fa14f>] flush_to_ldisc+0xd4/0xeb
[<e08b67c3>] receive_data+0x1a6/0x1b6 [nozomi]
[<c02c5fd6>] _spin_lock_irqsave+0x9/0xd
[<c01204d3>] lock_timer_base+0x15/0x2f
[<c02c5fd6>] _spin_lock_irqsave+0x9/0xd
[<c01f64f0>] __add_entropy_words+0x58/0x167
[<e08b6f92>] interrupt_handler+0x52c/0x723 [nozomi]
[<c01addca>] __freed_request+0x1c/0x65
[<c01ade30>] freed_request+0x1d/0x37
[<c022d951>] __ide_end_request+0xb1/0xba
[<c01ac11e>] elv_queue_empty+0x1b/0x21
[<c022e922>] ide_do_request+0x89/0x2f8
[<c022efa0>] ide_intr+0x10e/0x11a
[<c02348ef>] ide_dma_intr+0x0/0x92
[<c0133918>] handle_IRQ_event+0x21/0x4a
[<c01339ba>] __do_IRQ+0x79/0xcb
[<c010472a>] do_IRQ+0x5e/0x79
=======================
[<c0103542>] common_interrupt+0x1a/0x20
[<c01f931a>] tty_open+0x276/0x2ac
[<c0154f8c>] chrdev_open+0x111/0x127
[<c0154e7b>] chrdev_open+0x0/0x127
[<c014cc35>] __dentry_open+0xb6/0x185
[<c014cdaa>] nameidata_to_filp+0x19/0x28
[<c014cd2a>] filp_open+0x26/0x2c
[<c014ceb0>] get_unused_fd+0xac/0xb4
[<c014cf75>] do_sys_open+0x31/0x9c
[<c0102b75>] syscall_call+0x7/0xb
BUG: spinlock lockup on CPU#0, minicom/1918, dc4fade4
[<c01bb85d>] __spin_lock_debug+0x66/0x6f
[<c01bb8bc>] _raw_spin_lock+0x56/0x65
[<c02c5fd6>] _spin_lock_irqsave+0x9/0xd
[<e08b7de7>] ntty_write+0x35/0xf2 [nozomi]
[<c0116672>] scheduler_tick+0x9d/0x2af
[<c0106792>] timer_interrupt+0x73/0x7a
[<c01fa505>] tty_default_put_char+0x15/0x18
[<c01facfd>] opost+0x93/0x1ce
[<c01fb96e>] n_tty_receive_buf+0x52b/0xb37
[<c0103542>] common_interrupt+0x1a/0x20
[<c011007b>] wakeup_code+0x7b/0xba
[<c0119e01>] release_console_sem+0x74/0xa9
[<c0119ce8>] vprintk+0x1d1/0x1f5
[<c0106792>] timer_interrupt+0x73/0x7a
[<c01ba361>] vsnprintf+0x45a/0x497
[<c01fa14f>] flush_to_ldisc+0xd4/0xeb
[<e08b67c3>] receive_data+0x1a6/0x1b6 [nozomi]
[<c02c5fd6>] _spin_lock_irqsave+0x9/0xd
[<c01204d3>] lock_timer_base+0x15/0x2f
[<c02c5fd6>] _spin_lock_irqsave+0x9/0xd
[<c01f64f0>] __add_entropy_words+0x58/0x167
[<e08b6f92>] interrupt_handler+0x52c/0x723 [nozomi]
[<c01addca>] __freed_request+0x1c/0x65
[<c01ade30>] freed_request+0x1d/0x37
[<c022d951>] __ide_end_request+0xb1/0xba
[<c01ac11e>] elv_queue_empty+0x1b/0x21
[<c022e922>] ide_do_request+0x89/0x2f8
[<c022efa0>] ide_intr+0x10e/0x11a
[<c02348ef>] ide_dma_intr+0x0/0x92
[<c0133918>] handle_IRQ_event+0x21/0x4a
[<c01339ba>] __do_IRQ+0x79/0xcb
[<c010472a>] do_IRQ+0x5e/0x79
=======================
[<c0103542>] common_interrupt+0x1a/0x20
[<c01f931a>] tty_open+0x276/0x2ac
[<c0154f8c>] chrdev_open+0x111/0x127
[<c0154e7b>] chrdev_open+0x0/0x127
[<c014cc35>] __dentry_open+0xb6/0x185
[<c014cdaa>] nameidata_to_filp+0x19/0x28
[<c014cd2a>] filp_open+0x26/0x2c
[<c014ceb0>] get_unused_fd+0xac/0xb4
[<c014cf75>] do_sys_open+0x31/0x9c
[<c0102b75>] syscall_call+0x7/0xb


2006-09-11 16:12:58

by Alan

[permalink] [raw]
Subject: Re: Spinlock debugging

Ar Llu, 2006-09-11 am 16:32 +0100, ysgrifennodd Andrew Bird (Sphere
Systems):
> will be lost. But if I comment out the line that tells the tty layer that
> it's implemented, I end up with a BUG - spinlock recursion. Can anybody tell
> me how to interpret the output?

Looks like your driver calls flush_to_ldisc with low latency set and
then can't handle the flush_to_ldisc causing n_tty to call back into the
write method for flow control.

Alan

2006-09-11 16:38:28

by Andrew Bird

[permalink] [raw]
Subject: Re: Spinlock debugging

Alan
Yes, I have low_latency set for kernels lower than 2.6.17. I'm currently
testing using 2.6.15. When you mention 'write method for flow control' do you
mean for software XON/XOFF etc?
On a more generic note, is the spinlock debug output read as a stack and what
do the '=======' line breaks signify, looping?

Thanks


Andrew

On Monday 11 September 2006 17:36, Alan Cox wrote:
> Ar Llu, 2006-09-11 am 16:32 +0100, ysgrifennodd Andrew Bird (Sphere
>
> Systems):
> > will be lost. But if I comment out the line that tells the tty layer that
> > it's implemented, I end up with a BUG - spinlock recursion. Can anybody
> > tell me how to interpret the output?
>
> Looks like your driver calls flush_to_ldisc with low latency set and
> then can't handle the flush_to_ldisc causing n_tty to call back into the
> write method for flow control.
>
> Alan

2006-09-11 17:01:31

by Alan

[permalink] [raw]
Subject: Re: Spinlock debugging

Ar Llu, 2006-09-11 am 17:38 +0100, ysgrifennodd Andrew Bird:
> Alan
> Yes, I have low_latency set for kernels lower than 2.6.17. I'm currently
> testing using 2.6.15. When you mention 'write method for flow control' do you
> mean for software XON/XOFF etc?

Yes

Basically in low_latency the following is valid


driver receives bytes
flush_to_ldisc
ldisc calls driver write methods


That means if you have a shared lock for read/write you want to drop it
after you've bashed the hardware and before you flush_to_ldisc. Remember
the IRQ handler is not re-entrant so another IRQ of the same number
won't cause further I/O and out of order receives.

Alan

2006-09-12 07:47:46

by Andrew Bird

[permalink] [raw]
Subject: Re: Spinlock debugging

Alan
thanks that did the trick.
One further question, on the later kernels 2.6.17+, I don't have low_latency
set. Can I still guarantee that after calling tty_flip_buffer_push() I have
made space in the tty for my buffer? For example, is this legal?

// in interrupt handler

if(tty_buffer_request_room(tty, size) < size) {

spin_unlock(&dc->lock);
spin_unlock(&port->lock);

tty_flip_buffer_push(tty);

spin_lock(&port->lock);
spin_lock(&dc->lock);

}
tty_insert_flip_string(tty, buf, size);

Thanks


Andrew

On Monday 11 September 2006 18:24, Alan Cox wrote:
> Ar Llu, 2006-09-11 am 17:38 +0100, ysgrifennodd Andrew Bird:
> > Alan
> > Yes, I have low_latency set for kernels lower than 2.6.17. I'm currently
> > testing using 2.6.15. When you mention 'write method for flow control' do
> > you mean for software XON/XOFF etc?
>
> Yes
>
> Basically in low_latency the following is valid
>
>
> driver receives bytes
> flush_to_ldisc
> ldisc calls driver write methods
>
>
> That means if you have a shared lock for read/write you want to drop it
> after you've bashed the hardware and before you flush_to_ldisc. Remember
> the IRQ handler is not re-entrant so another IRQ of the same number
> won't cause further I/O and out of order receives.
>
> Alan

2006-09-12 13:20:22

by Alan

[permalink] [raw]
Subject: Re: Spinlock debugging

Ar Maw, 2006-09-12 am 08:47 +0100, ysgrifennodd Andrew Bird:
> Alan
> thanks that did the trick.
> One further question, on the later kernels 2.6.17+, I don't have low_latency
> set. Can I still guarantee that after calling tty_flip_buffer_push() I have
> made space in the tty for my buffer? For example, is this legal?

It makes no guarantee in any kernel.

In the new tty case however tty_buffer_request_room() will only fail if
you have 64K queued or the box is completely out of atomic memory and
also doing stuff like dropping network packets and console keystrokes.

So all you need in your IRQ handler is

if (tty_insert_flip_string(tty, buf, size))
tty_flip_buffer_push(tty);

the rest will occur automatically. Hinting with tty_buffer_request_room
may improve performance for some workloads (notably virtualized uarts)
or when using DMA but otherwise the above should be fine.

Most existing drivers were a straight conversion so at the moment try
too hard.


2006-09-12 13:31:43

by Sergei Organov

[permalink] [raw]
Subject: Re: Spinlock debugging

Alan Cox <[email protected]> writes:
[...]
> So all you need in your IRQ handler is
>
> if (tty_insert_flip_string(tty, buf, size))
> tty_flip_buffer_push(tty);

What is the purpose of the "if" in the above code? is push with no data
in the buffer dangerous? Or is it just optimization of
almost-never-taken path? ;)

-- Sergei.

2006-09-12 13:41:03

by Alan

[permalink] [raw]
Subject: Re: Spinlock debugging

Ar Maw, 2006-09-12 am 17:31 +0400, ysgrifennodd Sergei Organov:
> Alan Cox <[email protected]> writes:
> [...]
> > So all you need in your IRQ handler is
> >
> > if (tty_insert_flip_string(tty, buf, size))
> > tty_flip_buffer_push(tty);
>
> What is the purpose of the "if" in the above code? is push with no data
> in the buffer dangerous? Or is it just optimization of
> almost-never-taken path? ;)

Sorry..replied to sender only

It's an optimisation and you are right it may well not even be worth
doing