[Xenomai-core] soft lockup detected on AT91RM9200

[Xenomai-core] soft lockup detected on AT91RM9200

[Steven Scholz]

Hi Gilles,

I am running xenomai (svn 22.02.2007) with adeos-ipipe-2.6.19-arm-1.6-02.patch
on our AT91RM9200 board. (# CONFIG_PREEMPT is not set)

When starting latency with 100µs period I get

~ # latency
== Sampling period: 100 us
== Test mode: periodic user-mode task
== All results in microseconds
warming up...
BUG: soft lockup detected on CPU#0!
[<c001dce8>] (dump_stack+0x0/0x14) from [<c004ce50>] (softlockup_tick+0x98/0xb8)
[<c004cdb8>] (softlockup_tick+0x0/0xb8) from [<c0037cf8>] (run_local_timers+0x18/0x1c) r7 = 00000011  r6 = 00000000  r5 = 00000000  r4 = C02F8940
[<c0037ce0>] (run_local_timers+0x0/0x1c) from [<c0037d40>] (update_process_times+0x44/0x6c)[<c0037cfc>] (update_process_times+0x0/0x6c) from [<c001db4c>] (timer_tick+0xf8/0x120) r5 = C01F9DE0  r4 = C01F0660
[<c001da54>] (timer_tick+0x0/0x120) from [<c0023a8c>] (at91rm9200_timer_interrupt+0x34/0xf8) r5 = C01F9DE0  r4 = C01F0660
[<c0023a58>] (at91rm9200_timer_interrupt+0x0/0xf8) from [<c004d320>] (handle_IRQ_event+0x38/0x6c) r5 = 00000000  r4 = C01AD8F0
[<c004d2e8>] (handle_IRQ_event+0x0/0x6c) from [<c004e5e8>] (handle_level_irq+0x74/0xcc) r7 = 00000011  r6 = C01AF2C0  r5 = 00000011  r4 = C01A8440
[<c004e574>] (handle_level_irq+0x0/0xcc) from [<c001a6c0>] (asm_do_IRQ+0x48/0x60) r5 = 00000000  r4 = C0213930
[<c001a678>] (asm_do_IRQ+0x0/0x60) from [<c004f2c0>] (__ipipe_sync_stage+0x208/0x290) r5 = 00000000  r4 = C01AF2C8
[<c004f0b8>] (__ipipe_sync_stage+0x0/0x290) from [<c004f86c>] (__ipipe_walk_pipeline+0xa4/0xc8)
[<c004f7c8>] (__ipipe_walk_pipeline+0x0/0xc8) from [<c001f004>] (__ipipe_handle_irq+0x18c/0x19c) r7 = 00000011  r6 = C01FC2C0  r5 = 00000011  r4 = FFFFFFFF
[<c001ee78>] (__ipipe_handle_irq+0x0/0x19c) from [<c001f140>] (__ipipe_grab_irq+0xbc/0x120)
[<c001f084>] (__ipipe_grab_irq+0x0/0x120) from [<c00199a4>] (__irq_svc+0x24/0x4c)
[<c004f578>] (__ipipe_unstall_root+0x0/0x4c) from [<c004f5e4>] (__ipipe_restore_root+0x20/0x24)
[<c004f5c4>] (__ipipe_restore_root+0x0/0x24) from [<c0045a20>] (hrtimer_try_to_cancel+0x6c/0x74)
[<c00459b4>] (hrtimer_try_to_cancel+0x0/0x74) from [<c0045a40>] (hrtimer_cancel+0x18/0x24) r7 = 00000000  r6 = 00000001  r5 = C1D82000  r4 = C1D83F3C
[<c0045a28>] (hrtimer_cancel+0x0/0x24) from [<c0179b08>] (do_nanosleep+0x50/0x80) r4 = C1D83F3C
[<c0179ab8>] (do_nanosleep+0x0/0x80) from [<c0045d6c>] (hrtimer_nanosleep+0x4c/0x16c) r6 = 00000001  r5 = C1D83F3C  r4 = 00000000
[<c0045d20>] (hrtimer_nanosleep+0x0/0x16c) from [<c0045f28>] (sys_nanosleep+0x9c/0xb0)[<c0045e8c>] (sys_nanosleep+0x0/0xb0) from [<c0019d84>] (ret_fast_syscall+0x0/0x10) r6 = 00000000  r5 = BEAB9D5E  r4 = 00000000


This text is printed very slowly onto teh serial console. Also the timer leds blinks very slowly.
I'd say 10 times slower.

Ideas? How can I help with debugging this?

-- 
Steven

[Xenomai-core] Re: soft lockup detected on AT91RM9200

[Gilles Chanteperdrix]

Steven Scholz wrote:
> Hi Gilles,
> 
> I am running xenomai (svn 22.02.2007) with adeos-ipipe-2.6.19-arm-1.6-02.patch
> on our AT91RM9200 board. (# CONFIG_PREEMPT is not set)
> 
> When starting latency with 100µs period I get
> 
> ~ # latency
> == Sampling period: 100 us
> == Test mode: periodic user-mode task
> == All results in microseconds
> warming up...
> BUG: soft lockup detected on CPU#0!
> [<c001dce8>] (dump_stack+0x0/0x14) from [<c004ce50>] (softlockup_tick+0x98/0xb8)
> [<c004cdb8>] (softlockup_tick+0x0/0xb8) from [<c0037cf8>] (run_local_timers+0x18/0x1c) r7 = 00000011  r6 = 00000000  r5 = 00000000  r4 = C02F8940
> [<c0037ce0>] (run_local_timers+0x0/0x1c) from [<c0037d40>] (update_process_times+0x44/0x6c)[<c0037cfc>] (update_process_times+0x0/0x6c) from [<c001db4c>] (timer_tick+0xf8/0x120) r5 = C01F9DE0  r4 = C01F0660
> [<c001da54>] (timer_tick+0x0/0x120) from [<c0023a8c>] (at91rm9200_timer_interrupt+0x34/0xf8) r5 = C01F9DE0  r4 = C01F0660
> [<c0023a58>] (at91rm9200_timer_interrupt+0x0/0xf8) from [<c004d320>] (handle_IRQ_event+0x38/0x6c) r5 = 00000000  r4 = C01AD8F0
> [<c004d2e8>] (handle_IRQ_event+0x0/0x6c) from [<c004e5e8>] (handle_level_irq+0x74/0xcc) r7 = 00000011  r6 = C01AF2C0  r5 = 00000011  r4 = C01A8440
> [<c004e574>] (handle_level_irq+0x0/0xcc) from [<c001a6c0>] (asm_do_IRQ+0x48/0x60) r5 = 00000000  r4 = C0213930
> [<c001a678>] (asm_do_IRQ+0x0/0x60) from [<c004f2c0>] (__ipipe_sync_stage+0x208/0x290) r5 = 00000000  r4 = C01AF2C8
> [<c004f0b8>] (__ipipe_sync_stage+0x0/0x290) from [<c004f86c>] (__ipipe_walk_pipeline+0xa4/0xc8)
> [<c004f7c8>] (__ipipe_walk_pipeline+0x0/0xc8) from [<c001f004>] (__ipipe_handle_irq+0x18c/0x19c) r7 = 00000011  r6 = C01FC2C0  r5 = 00000011  r4 = FFFFFFFF
> [<c001ee78>] (__ipipe_handle_irq+0x0/0x19c) from [<c001f140>] (__ipipe_grab_irq+0xbc/0x120)
> [<c001f084>] (__ipipe_grab_irq+0x0/0x120) from [<c00199a4>] (__irq_svc+0x24/0x4c)
> [<c004f578>] (__ipipe_unstall_root+0x0/0x4c) from [<c004f5e4>] (__ipipe_restore_root+0x20/0x24)
> [<c004f5c4>] (__ipipe_restore_root+0x0/0x24) from [<c0045a20>] (hrtimer_try_to_cancel+0x6c/0x74)
> [<c00459b4>] (hrtimer_try_to_cancel+0x0/0x74) from [<c0045a40>] (hrtimer_cancel+0x18/0x24) r7 = 00000000  r6 = 00000001  r5 = C1D82000  r4 = C1D83F3C
> [<c0045a28>] (hrtimer_cancel+0x0/0x24) from [<c0179b08>] (do_nanosleep+0x50/0x80) r4 = C1D83F3C
> [<c0179ab8>] (do_nanosleep+0x0/0x80) from [<c0045d6c>] (hrtimer_nanosleep+0x4c/0x16c) r6 = 00000001  r5 = C1D83F3C  r4 = 00000000
> [<c0045d20>] (hrtimer_nanosleep+0x0/0x16c) from [<c0045f28>] (sys_nanosleep+0x9c/0xb0)[<c0045e8c>] (sys_nanosleep+0x0/0xb0) from [<c0019d84>] (ret_fast_syscall+0x0/0x10) r6 = 00000000  r5 = BEAB9D5E  r4 = 00000000
> 
> 
> This text is printed very slowly onto teh serial console. Also the timer leds blinks very slowly.
> I'd say 10 times slower.
> 
> Ideas? How can I help with debugging this?

100us is too small, as I already told you here:

https://mail.gna.org/public/xenomai-core/2007-02/msg00019.html

The latency process spend 100% of its time handling the timer ticks, and
the kernel detects a soft lockup.

The difference between I-pipe patch 1.6-01 and 1.6-02 is that the return
from exception is correctly handled. Maybe it is what allows the kernel
to print a clean message. Maybe it is because you now have enabled the
soft lockup detector whereas you previously did not.

-- 
                                                 Gilles Chanteperdrix

Re: [Xenomai-core] soft lockup detected on AT91RM9200

[Jan Kiszka]

[-- Attachment #1: Type: text/plain, Size: 3344 bytes --]

Steven Scholz wrote:
> Hi Gilles,
> 
> I am running xenomai (svn 22.02.2007) with adeos-ipipe-2.6.19-arm-1.6-02.patch
> on our AT91RM9200 board. (# CONFIG_PREEMPT is not set)
> 
> When starting latency with 100µs period I get
> 
> ~ # latency
> == Sampling period: 100 us
> == Test mode: periodic user-mode task
> == All results in microseconds
> warming up...
> BUG: soft lockup detected on CPU#0!
> [<c001dce8>] (dump_stack+0x0/0x14) from [<c004ce50>] (softlockup_tick+0x98/0xb8)
> [<c004cdb8>] (softlockup_tick+0x0/0xb8) from [<c0037cf8>] (run_local_timers+0x18/0x1c) r7 = 00000011  r6 = 00000000  r5 = 00000000  r4 = C02F8940
> [<c0037ce0>] (run_local_timers+0x0/0x1c) from [<c0037d40>] (update_process_times+0x44/0x6c)[<c0037cfc>] (update_process_times+0x0/0x6c) from [<c001db4c>] (timer_tick+0xf8/0x120) r5 = C01F9DE0  r4 = C01F0660
> [<c001da54>] (timer_tick+0x0/0x120) from [<c0023a8c>] (at91rm9200_timer_interrupt+0x34/0xf8) r5 = C01F9DE0  r4 = C01F0660
> [<c0023a58>] (at91rm9200_timer_interrupt+0x0/0xf8) from [<c004d320>] (handle_IRQ_event+0x38/0x6c) r5 = 00000000  r4 = C01AD8F0
> [<c004d2e8>] (handle_IRQ_event+0x0/0x6c) from [<c004e5e8>] (handle_level_irq+0x74/0xcc) r7 = 00000011  r6 = C01AF2C0  r5 = 00000011  r4 = C01A8440
> [<c004e574>] (handle_level_irq+0x0/0xcc) from [<c001a6c0>] (asm_do_IRQ+0x48/0x60) r5 = 00000000  r4 = C0213930
> [<c001a678>] (asm_do_IRQ+0x0/0x60) from [<c004f2c0>] (__ipipe_sync_stage+0x208/0x290) r5 = 00000000  r4 = C01AF2C8
> [<c004f0b8>] (__ipipe_sync_stage+0x0/0x290) from [<c004f86c>] (__ipipe_walk_pipeline+0xa4/0xc8)
> [<c004f7c8>] (__ipipe_walk_pipeline+0x0/0xc8) from [<c001f004>] (__ipipe_handle_irq+0x18c/0x19c) r7 = 00000011  r6 = C01FC2C0  r5 = 00000011  r4 = FFFFFFFF
> [<c001ee78>] (__ipipe_handle_irq+0x0/0x19c) from [<c001f140>] (__ipipe_grab_irq+0xbc/0x120)
> [<c001f084>] (__ipipe_grab_irq+0x0/0x120) from [<c00199a4>] (__irq_svc+0x24/0x4c)
> [<c004f578>] (__ipipe_unstall_root+0x0/0x4c) from [<c004f5e4>] (__ipipe_restore_root+0x20/0x24)
> [<c004f5c4>] (__ipipe_restore_root+0x0/0x24) from [<c0045a20>] (hrtimer_try_to_cancel+0x6c/0x74)
> [<c00459b4>] (hrtimer_try_to_cancel+0x0/0x74) from [<c0045a40>] (hrtimer_cancel+0x18/0x24) r7 = 00000000  r6 = 00000001  r5 = C1D82000  r4 = C1D83F3C
> [<c0045a28>] (hrtimer_cancel+0x0/0x24) from [<c0179b08>] (do_nanosleep+0x50/0x80) r4 = C1D83F3C
> [<c0179ab8>] (do_nanosleep+0x0/0x80) from [<c0045d6c>] (hrtimer_nanosleep+0x4c/0x16c) r6 = 00000001  r5 = C1D83F3C  r4 = 00000000
> [<c0045d20>] (hrtimer_nanosleep+0x0/0x16c) from [<c0045f28>] (sys_nanosleep+0x9c/0xb0)[<c0045e8c>] (sys_nanosleep+0x0/0xb0) from [<c0019d84>] (ret_fast_syscall+0x0/0x10) r6 = 00000000  r5 = BEAB9D5E  r4 = 00000000
> 
> 
> This text is printed very slowly onto teh serial console. Also the timer leds blinks very slowly.
> I'd say 10 times slower.
> 
> Ideas? How can I help with debugging this?
> 

ARM platforms have hardware-related worst-case latencies in the range of
200 us under Linux (or is the AT91 mmu-less?). So if you set up a task
with a 100 us period and load your system, you will more sooner than
later see a total overload of both RT and non-RT part - not to speak of
countless deadline misses.

What happens if you move your task period more in the range of, say, 500
down to 300 us?

Jan


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 250 bytes --]

[Xenomai-core] Re: soft lockup detected on AT91RM9200

[Steven Scholz]

Gilles,

>> When starting latency with 100µs period I get
>>
>> ~ # latency
>> == Sampling period: 100 us
>> == Test mode: periodic user-mode task
>> == All results in microseconds
>> warming up...
>> BUG: soft lockup detected on CPU#0!
>> ...
>>
>> Ideas? How can I help with debugging this?
> 
> 100us is too small, as I already told you here:
> 
> https://mail.gna.org/public/xenomai-core/2007-02/msg00019.html

No. That's probably a different thing. I am going to write a mail soon.

> The latency process spend 100% of its time handling the timer ticks, and
> the kernel detects a soft lockup.
> 
> The difference between I-pipe patch 1.6-01 and 1.6-02 is that the return
> from exception is correctly handled. Maybe it is what allows the kernel
> to print a clean message. Maybe it is because you now have enabled the
> soft lockup detector whereas you previously did not.
Ok. Maybe.

I don't care about missing deadlines. That's fine iff I overload the system.

But I still would have expected printout on the serial console. But ok,
maybe the print in latency is done in a non-realtime task. So fair enough.

Steven