[Xenomai-core] [bug] don't try this at home...

[Xenomai-core] [bug] don't try this at home...

[Jan Kiszka]

[-- Attachment #1.1: Type: text/plain, Size: 691 bytes --]

Hi Philippe,

I'm afraid this one is serious: let the attached migration stress test
run on likely any Xenomai since 2.0, preferably with
CONFIG_XENO_OPT_DEBUG on. Will give a nice crash sooner or later (I'm
trying to set up a serial console now). To be more precisely:

Setup 1:
    xeno 2.0, kernel 2.6.13.5, ipipe-1.0-09
    on Thinkpad R40

Setup 2:
    xeno svn-trunk, kernel 2.6.14.3, ipipe-1.0-11
    on Thinkpad R40 & P-III embedded PC

I have no clue yet what happens, I just nailed various strange
behaviours and latencies down to this issue.

ALARM! ;)

Jan


PS: I suggest including this test for future regression checks into the
upcoming(?) testsuite.

[-- Attachment #1.2: nat_migration.c --]
[-- Type: text/plain, Size: 756 bytes --]

#include <stdio.h>
#include <sys/mman.h>
#include <semaphore.h>

#include <native/task.h>
#include <native/sem.h>

sem_t sem;


static void simple_thread(void *arg)
{
    sem_post(&sem);
}


int main (int ac, char **av)
{
    RT_TASK task;
    int     ret;


    mlockall(MCL_CURRENT | MCL_FUTURE);

    sem_init(&sem, 0, 0);

    while (1) {
        ret = rt_task_create(&task, "migration", 0, 1, 0);
        if (ret != 0)
            printf("(%s) error creating task: %d\n", __FUNCTION__, ret);

        ret = rt_task_start(&task, &simple_thread, NULL);
        if (ret != 0)
            printf("(%s) error starting task: %d\n", __FUNCTION__, ret);

        sem_wait(&sem);

        rt_task_delete(&task);
    }
}

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

Re: [Xenomai-core] [bug] don't try this at home...

[Jan Kiszka]

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

Jan Kiszka wrote:
> Hi Philippe,
> 
> I'm afraid this one is serious: let the attached migration stress test
> run on likely any Xenomai since 2.0, preferably with
> CONFIG_XENO_OPT_DEBUG on. Will give a nice crash sooner or later (I'm
> trying to set up a serial console now).
> 

As it took some time to persuade my box to not just reboot but to give a
message, I'm posting here the kernel dump of the P-III running
nat_migration:

[...]
Xenomai: starting native API services.
ce649fb4 ce648000 00000b17 00000202 c0139246 cdf2819c cdf28070 0b12d310
       00000037 ce648000 00000000 c02f0700 00009a28 00000000 b7e94a70
bfed63c8
       00000000 ce648000 c0102fcb b7e94a70 bfed63dc b7faf4b0 bfed63c8
00000000
Call Trace:
 [<c0139246>] __ipipe_dispatch_event+0x96/0x130
 [<c0102fcb>] work_resched+0x6/0x1c
Xenomai: fatal: blocked thread migration[22175] rescheduled?!
(status=0x300010, sig=0, prev=watchdog/0[3])
 CPU  PID    PRI  TIMEOUT  STAT      NAME
>  0  0      0    0        00500080  ROOT
   0  22175  1    0        00300110  migration
Timer: none

cea05ee4 d0842c62 cdcb0000 cea6d030 c02f0700 c035cbec c02f0700 00000286
       c0139246 00000022 c02f0700 cdf28070 cdf28070 00000022 00000001
c02f0700
       cea6d030 cdf28070 cea6d158 cea05f78 c02b26c0 cea04000 00000238
d1244537
Call Trace:
 [<c0139246>] __ipipe_dispatch_event+0x96/0x130
 [<c02b26c0>] schedule+0x2d0/0x720
 [<c0137b20>] watchdog+0x0/0x80
 [<c02b3967>] schedule_timeout+0x47/0xb0
 [<c0120070>] process_timeout+0x0/0x10
 [<c0120492>] msleep_interruptible+0x42/0x60
 [<c0137b70>] watchdog+0x50/0x80
 [<c012d0ab>] kthread+0x8b/0x90
 [<c012d020>] kthread+0x0/0x90
 [<c0100ef5>] kernel_thread_helper+0x5/0x10


Jan


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

Re: [Xenomai-core] [bug] don't try this at home...

[Philippe Gerum]

Jan Kiszka wrote:
> Jan Kiszka wrote:
> 
>>Hi Philippe,
>>
>>I'm afraid this one is serious: let the attached migration stress test
>>run on likely any Xenomai since 2.0, preferably with
>>CONFIG_XENO_OPT_DEBUG on. Will give a nice crash sooner or later (I'm
>>trying to set up a serial console now).
>>

Confirmed here. My test box went through some nifty triple salto out of 
the window running this frag for 2mn or so. Actually, the semop 
handshake is not even needed to cause the crash. At first sight, it 
looks like a migration issue taking place during the critical phase when 
a shadow thread switches back to Linux to terminate.

> 
> 
> As it took some time to persuade my box to not just reboot but to give a
> message, I'm posting here the kernel dump of the P-III running
> nat_migration:
> 
> [...]
> Xenomai: starting native API services.
> ce649fb4 ce648000 00000b17 00000202 c0139246 cdf2819c cdf28070 0b12d310
>        00000037 ce648000 00000000 c02f0700 00009a28 00000000 b7e94a70
> bfed63c8
>        00000000 ce648000 c0102fcb b7e94a70 bfed63dc b7faf4b0 bfed63c8
> 00000000
> Call Trace:
>  [<c0139246>] __ipipe_dispatch_event+0x96/0x130
>  [<c0102fcb>] work_resched+0x6/0x1c
> Xenomai: fatal: blocked thread migration[22175] rescheduled?!
> (status=0x300010, sig=0, prev=watchdog/0[3])

This babe is awaken by Linux while Xeno sees it in a dormant state, 
likely after it has terminated. No wonder why things are going wild 
after that... Ok, job queued. Thanks.

>  CPU  PID    PRI  TIMEOUT  STAT      NAME
> 
>> 0  0      0    0        00500080  ROOT
> 
>    0  22175  1    0        00300110  migration
> Timer: none
> 
> cea05ee4 d0842c62 cdcb0000 cea6d030 c02f0700 c035cbec c02f0700 00000286
>        c0139246 00000022 c02f0700 cdf28070 cdf28070 00000022 00000001
> c02f0700
>        cea6d030 cdf28070 cea6d158 cea05f78 c02b26c0 cea04000 00000238
> d1244537
> Call Trace:
>  [<c0139246>] __ipipe_dispatch_event+0x96/0x130
>  [<c02b26c0>] schedule+0x2d0/0x720
>  [<c0137b20>] watchdog+0x0/0x80
>  [<c02b3967>] schedule_timeout+0x47/0xb0
>  [<c0120070>] process_timeout+0x0/0x10
>  [<c0120492>] msleep_interruptible+0x42/0x60
>  [<c0137b70>] watchdog+0x50/0x80
>  [<c012d0ab>] kthread+0x8b/0x90
>  [<c012d020>] kthread+0x0/0x90
>  [<c0100ef5>] kernel_thread_helper+0x5/0x10
> 
> 
> Jan
> 


-- 

Philippe.

Re: [Xenomai-core] [bug] don't try this at home...

[Jan Kiszka]

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

Philippe Gerum wrote:
> Jan Kiszka wrote:
>> Jan Kiszka wrote:
>>
>>> Hi Philippe,
>>>
>>> I'm afraid this one is serious: let the attached migration stress test
>>> run on likely any Xenomai since 2.0, preferably with
>>> CONFIG_XENO_OPT_DEBUG on. Will give a nice crash sooner or later (I'm
>>> trying to set up a serial console now).
>>>
> 
> Confirmed here. My test box went through some nifty triple salto out of
> the window running this frag for 2mn or so. Actually, the semop
> handshake is not even needed to cause the crash. At first sight, it
> looks like a migration issue taking place during the critical phase when
> a shadow thread switches back to Linux to terminate.
> 
>>
>>
>> As it took some time to persuade my box to not just reboot but to give a
>> message, I'm posting here the kernel dump of the P-III running
>> nat_migration:
>>
>> [...]
>> Xenomai: starting native API services.
>> ce649fb4 ce648000 00000b17 00000202 c0139246 cdf2819c cdf28070 0b12d310
>>        00000037 ce648000 00000000 c02f0700 00009a28 00000000 b7e94a70
>> bfed63c8
>>        00000000 ce648000 c0102fcb b7e94a70 bfed63dc b7faf4b0 bfed63c8
>> 00000000
>> Call Trace:
>>  [<c0139246>] __ipipe_dispatch_event+0x96/0x130
>>  [<c0102fcb>] work_resched+0x6/0x1c
>> Xenomai: fatal: blocked thread migration[22175] rescheduled?!
>> (status=0x300010, sig=0, prev=watchdog/0[3])
> 
> This babe is awaken by Linux while Xeno sees it in a dormant state,
> likely after it has terminated. No wonder why things are going wild
> after that... Ok, job queued. Thanks.
> 

I think I can explain this warning now: This happens during creation of
a new userspace real-time thread. In the context of the newly created
Linux pthread that is to become a real-time thread, Xenomai first sets
up the real-time part and then calls xnshadow_map. The latter function
does further init and then signals via xnshadow_signal_completion to the
parent Linux thread (the caller of rt_task_create e.g.) that the thread
is up. This happens before xnshadow_harden, i.e. still in preemptible
linux context.

The signalling should normally do not cause a reschedule as the caller -
the to-be-mapped linux pthread - has higher prio than the woken up
thread. And Xenomai implicitly assumes with this fatal-test above that
there is no preemption! But it can happen: the watchdog thread of linux
does preempt here. So, I think it's a false positive.

I disabled this particular warning and came a bit further:

I-pipe: Domain Xenomai registered.
Xenomai: hal/x86 started.
Xenomai: real-time nucleus v2.1 (Surfing With The Alien) loaded.
Xenomai: starting native API services.
Unable to handle kernel paging request at virtual address 75c08732
 printing eip:
d0acec80
*pde = 00000000
Oops: 0000 [#1]
PREEMPT
Modules linked in: xeno_native xeno_nucleus eepro100 mii
CPU:    0
EIP:    0060:[<d0acec80>]    Not tainted VLI
EFLAGS: 00010086   (2.6.14.3)
EIP is at xnpod_schedule+0x790/0xcf0 [xeno_nucleus]
eax: 8005003b   ebx: d09c1a60   ecx: 75c08500   edx: d0ae441c
esi: d0ae4210   edi: ceab1f28   ebp: ceab1f28   esp: ceab1ef4
ds: 007b   es: 007b   ss: 0068
I-pipe domain Xenomai
Stack: 00000096 00000001 c039cce0 0000000e ceab1f28 00000002 ceab1f20
c010e080
       00000000 cee1ba90 0000000e 00000004 c0103224 00000000 cee00000
cee1ba90
       cee1ba90 ce86f700 00000004 cee1b570 0000007b cee1007b ffffffff
c028450c
Call Trace:
 [<c0103606>] show_stack+0x86/0xc0
 [<c01037a4>] show_registers+0x144/0x200
 [<c01039c7>] die+0xd7/0x1e0
 [<c0286994>] do_page_fault+0x1e4/0x667
 [<c010e094>] __ipipe_handle_exception+0x34/0x80
 [<c0103224>] error_code+0x54/0x70
 [<cee00000>] 0xcee00000
Code: b8 05 e4 01 00 00 39 82 18 02 00 00 74 68 0f 20 c0 83 c8 08 0f 22
c0 8b 4d e8 8b 7d c4 85 ff 8b 49 04 89 4d b8
0f 84 37 fa ff ff <f6> 81 32 02 00 00 40 0f 84 2a fa ff ff b8 00 e0 ff
ff 21 e0 8b
scheduling while atomic: migration/0x00000002/17646
 [<c0103655>] dump_stack+0x15/0x20
 [<c02847fb>] schedule+0x63b/0x720
 [<d0ad6573>] xnshadow_harden+0x83/0x140 [xeno_nucleus]
 [<d0ad6d7a>] xnshadow_wait_barrier+0x7a/0x130 [xeno_nucleus]
 [<d0ad7287>] exec_nucleus_syscall+0x77/0xa0 [xeno_nucleus]
 [<d0ad7769>] losyscall_event+0x139/0x1a0 [xeno_nucleus]
 [<c0139296>] __ipipe_dispatch_event+0x96/0x130
 [<c010dfb7>] __ipipe_syscall_root+0x27/0xc0
 [<c0102e82>] sysenter_past_esp+0x3b/0x67
Xenomai: Switching migration to secondary mode after exception #14 from
user-space at 0xc028450c (pid 17646)
 <3>Debug: sleeping function called from invalid context at
include/linux/rwsem.h:43
in_atomic():1, irqs_disabled():0
 [<c0103655>] dump_stack+0x15/0x20
 [<c01120b8>] __might_sleep+0x88/0xb0
 [<c01315ad>] futex_wait+0xed/0x2f0
 [<c0131a35>] do_futex+0x45/0x80
 [<c0131ab0>] sys_futex+0x40/0x110
 [<c0102f28>] syscall_call+0x7/0xb


Still problems ahead. I got the impression that the migration path is
not yet well reviewed. :(

Any further ideas welcome!

Jan


PS: Tests performed with splhigh/splexit removed from __rt_task_create
(and splnone from gatekeeper_thread) as Philippe privately acknowledged
to be ok. This removes some critical latency source.


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

Re: [Xenomai-core] [bug] don't try this at home...

[Philippe Gerum]

Jan Kiszka wrote:
> Philippe Gerum wrote:
> 
>>Jan Kiszka wrote:
>>
>>>Jan Kiszka wrote:
>>>
>>>
>>>>Hi Philippe,
>>>>
>>>>I'm afraid this one is serious: let the attached migration stress test
>>>>run on likely any Xenomai since 2.0, preferably with
>>>>CONFIG_XENO_OPT_DEBUG on. Will give a nice crash sooner or later (I'm
>>>>trying to set up a serial console now).
>>>>
>>
>>Confirmed here. My test box went through some nifty triple salto out of
>>the window running this frag for 2mn or so. Actually, the semop
>>handshake is not even needed to cause the crash. At first sight, it
>>looks like a migration issue taking place during the critical phase when
>>a shadow thread switches back to Linux to terminate.
>>
>>
>>>
>>>As it took some time to persuade my box to not just reboot but to give a
>>>message, I'm posting here the kernel dump of the P-III running
>>>nat_migration:
>>>
>>>[...]
>>>Xenomai: starting native API services.
>>>ce649fb4 ce648000 00000b17 00000202 c0139246 cdf2819c cdf28070 0b12d310
>>>       00000037 ce648000 00000000 c02f0700 00009a28 00000000 b7e94a70
>>>bfed63c8
>>>       00000000 ce648000 c0102fcb b7e94a70 bfed63dc b7faf4b0 bfed63c8
>>>00000000
>>>Call Trace:
>>> [<c0139246>] __ipipe_dispatch_event+0x96/0x130
>>> [<c0102fcb>] work_resched+0x6/0x1c
>>>Xenomai: fatal: blocked thread migration[22175] rescheduled?!
>>>(status=0x300010, sig=0, prev=watchdog/0[3])
>>
>>This babe is awaken by Linux while Xeno sees it in a dormant state,
>>likely after it has terminated. No wonder why things are going wild
>>after that... Ok, job queued. Thanks.
>>
> 
> 
> I think I can explain this warning now: This happens during creation of
> a new userspace real-time thread. In the context of the newly created
> Linux pthread that is to become a real-time thread, Xenomai first sets
> up the real-time part and then calls xnshadow_map. The latter function
> does further init and then signals via xnshadow_signal_completion to the
> parent Linux thread (the caller of rt_task_create e.g.) that the thread
> is up. This happens before xnshadow_harden, i.e. still in preemptible
> linux context.
> 
> The signalling should normally do not cause a reschedule as the caller -
> the to-be-mapped linux pthread - has higher prio than the woken up
> thread.

Xeno never assumes this.

  And Xenomai implicitly assumes with this fatal-test above that
> there is no preemption! But it can happen: the watchdog thread of linux
> does preempt here. So, I think it's a false positive.
> 

This is wrong. This check is not related to Linux preemption at all; it 
makes sure that control over any shadow is shared in a strictly 
_mutually exclusive_ way, so that a thread blocked at Xenomai level may 
not not be seen as runnable by Linux either. Disabling it only makes 
things worse since the scheduling state is obviously corrupted when it 
triggers, and that's the root bug we are chasing right now. You should 
not draw any conclusion beyond that. Additionally, keep in mind that 
Xeno has already run over some PREEMPT_RT patches, for which an infinite 
number of CPUs is assumed over a fine-grained code base, which induces 
maximum preemption probabilities.

> I disabled this particular warning and came a bit further:
> 
> I-pipe: Domain Xenomai registered.
> Xenomai: hal/x86 started.
> Xenomai: real-time nucleus v2.1 (Surfing With The Alien) loaded.
> Xenomai: starting native API services.
> Unable to handle kernel paging request at virtual address 75c08732
>  printing eip:
> d0acec80
> *pde = 00000000
> Oops: 0000 [#1]
> PREEMPT
> Modules linked in: xeno_native xeno_nucleus eepro100 mii
> CPU:    0
> EIP:    0060:[<d0acec80>]    Not tainted VLI
> EFLAGS: 00010086   (2.6.14.3)
> EIP is at xnpod_schedule+0x790/0xcf0 [xeno_nucleus]
> eax: 8005003b   ebx: d09c1a60   ecx: 75c08500   edx: d0ae441c
> esi: d0ae4210   edi: ceab1f28   ebp: ceab1f28   esp: ceab1ef4
> ds: 007b   es: 007b   ss: 0068
> I-pipe domain Xenomai
> Stack: 00000096 00000001 c039cce0 0000000e ceab1f28 00000002 ceab1f20
> c010e080
>        00000000 cee1ba90 0000000e 00000004 c0103224 00000000 cee00000
> cee1ba90
>        cee1ba90 ce86f700 00000004 cee1b570 0000007b cee1007b ffffffff
> c028450c
> Call Trace:
>  [<c0103606>] show_stack+0x86/0xc0
>  [<c01037a4>] show_registers+0x144/0x200
>  [<c01039c7>] die+0xd7/0x1e0
>  [<c0286994>] do_page_fault+0x1e4/0x667
>  [<c010e094>] __ipipe_handle_exception+0x34/0x80
>  [<c0103224>] error_code+0x54/0x70
>  [<cee00000>] 0xcee00000
> Code: b8 05 e4 01 00 00 39 82 18 02 00 00 74 68 0f 20 c0 83 c8 08 0f 22
> c0 8b 4d e8 8b 7d c4 85 ff 8b 49 04 89 4d b8
> 0f 84 37 fa ff ff <f6> 81 32 02 00 00 40 0f 84 2a fa ff ff b8 00 e0 ff
> ff 21 e0 8b
> scheduling while atomic: migration/0x00000002/17646
>  [<c0103655>] dump_stack+0x15/0x20
>  [<c02847fb>] schedule+0x63b/0x720
>  [<d0ad6573>] xnshadow_harden+0x83/0x140 [xeno_nucleus]
>  [<d0ad6d7a>] xnshadow_wait_barrier+0x7a/0x130 [xeno_nucleus]
>  [<d0ad7287>] exec_nucleus_syscall+0x77/0xa0 [xeno_nucleus]
>  [<d0ad7769>] losyscall_event+0x139/0x1a0 [xeno_nucleus]
>  [<c0139296>] __ipipe_dispatch_event+0x96/0x130
>  [<c010dfb7>] __ipipe_syscall_root+0x27/0xc0
>  [<c0102e82>] sysenter_past_esp+0x3b/0x67
> Xenomai: Switching migration to secondary mode after exception #14 from
> user-space at 0xc028450c (pid 17646)
>  <3>Debug: sleeping function called from invalid context at
> include/linux/rwsem.h:43
> in_atomic():1, irqs_disabled():0
>  [<c0103655>] dump_stack+0x15/0x20
>  [<c01120b8>] __might_sleep+0x88/0xb0
>  [<c01315ad>] futex_wait+0xed/0x2f0
>  [<c0131a35>] do_futex+0x45/0x80
>  [<c0131ab0>] sys_futex+0x40/0x110
>  [<c0102f28>] syscall_call+0x7/0xb
> 
> 
> Still problems ahead. I got the impression that the migration path is
> not yet well reviewed. :(
> 
> Any further ideas welcome!
> 
> Jan
> 
> 
> PS: Tests performed with splhigh/splexit removed from __rt_task_create
> (and splnone from gatekeeper_thread) as Philippe privately acknowledged
> to be ok. This removes some critical latency source.
> 


-- 

Philippe.

Re: [Xenomai-core] [bug] don't try this at home...

[Jan Kiszka]

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

Philippe Gerum wrote:
> Jan Kiszka wrote:
>> Philippe Gerum wrote:
>>
>>> Jan Kiszka wrote:
>>>
>>>> Jan Kiszka wrote:
>>>>
>>>>
>>>>> Hi Philippe,
>>>>>
>>>>> I'm afraid this one is serious: let the attached migration stress test
>>>>> run on likely any Xenomai since 2.0, preferably with
>>>>> CONFIG_XENO_OPT_DEBUG on. Will give a nice crash sooner or later (I'm
>>>>> trying to set up a serial console now).
>>>>>
>>>
>>> Confirmed here. My test box went through some nifty triple salto out of
>>> the window running this frag for 2mn or so. Actually, the semop
>>> handshake is not even needed to cause the crash. At first sight, it
>>> looks like a migration issue taking place during the critical phase when
>>> a shadow thread switches back to Linux to terminate.
>>>
>>>
>>>>
>>>> As it took some time to persuade my box to not just reboot but to
>>>> give a
>>>> message, I'm posting here the kernel dump of the P-III running
>>>> nat_migration:
>>>>
>>>> [...]
>>>> Xenomai: starting native API services.
>>>> ce649fb4 ce648000 00000b17 00000202 c0139246 cdf2819c cdf28070 0b12d310
>>>>       00000037 ce648000 00000000 c02f0700 00009a28 00000000 b7e94a70
>>>> bfed63c8
>>>>       00000000 ce648000 c0102fcb b7e94a70 bfed63dc b7faf4b0 bfed63c8
>>>> 00000000
>>>> Call Trace:
>>>> [<c0139246>] __ipipe_dispatch_event+0x96/0x130
>>>> [<c0102fcb>] work_resched+0x6/0x1c
>>>> Xenomai: fatal: blocked thread migration[22175] rescheduled?!
>>>> (status=0x300010, sig=0, prev=watchdog/0[3])
>>>
>>> This babe is awaken by Linux while Xeno sees it in a dormant state,
>>> likely after it has terminated. No wonder why things are going wild
>>> after that... Ok, job queued. Thanks.
>>>
>>
>>
>> I think I can explain this warning now: This happens during creation of
>> a new userspace real-time thread. In the context of the newly created
>> Linux pthread that is to become a real-time thread, Xenomai first sets
>> up the real-time part and then calls xnshadow_map. The latter function
>> does further init and then signals via xnshadow_signal_completion to the
>> parent Linux thread (the caller of rt_task_create e.g.) that the thread
>> is up. This happens before xnshadow_harden, i.e. still in preemptible
>> linux context.
>>
>> The signalling should normally do not cause a reschedule as the caller -
>> the to-be-mapped linux pthread - has higher prio than the woken up
>> thread.
> 
> Xeno never assumes this.
> 
>  And Xenomai implicitly assumes with this fatal-test above that
>> there is no preemption! But it can happen: the watchdog thread of linux
>> does preempt here. So, I think it's a false positive.
>>
> 
> This is wrong. This check is not related to Linux preemption at all; it
> makes sure that control over any shadow is shared in a strictly
> _mutually exclusive_ way, so that a thread blocked at Xenomai level may
> not not be seen as runnable by Linux either. Disabling it only makes
> things worse since the scheduling state is obviously corrupted when it
> triggers, and that's the root bug we are chasing right now. You should
> not draw any conclusion beyond that. Additionally, keep in mind that
> Xeno has already run over some PREEMPT_RT patches, for which an infinite
> number of CPUs is assumed over a fine-grained code base, which induces
> maximum preemption probabilities.
> 

Ok, may explanation was a quick hack before some meeting here, I should
have elaborated it more thoroughly. Let's try to do it step by step so
that you can say where I go of the right path:

1. We enter xnshadow_map. The linux thread is happily running, the
   shadow thread is in XNDORMANT state and not yet linked to its linux
   mate. Any linux preemption hitting us here and causing a reactivation
   of this particular linux thread later will not cause any activity of
   do_schedule_event related to this thread because [1] is NULL. That's
   important, we will see later why.

2. After some init stuff, xnshadow_map links the shadow to the linux
   thread [2] and then calls xnshadow_signal_completion. This call would
   normally wake up the sleeping parent of our linux thread, performing
   a direct standard linux schedule from the new born thread to the
   parent. Again, nothing here about which do_schedule_event could
   complain.

3. Now let's consider some preemption by a third linux task after [2]
   but before [3]. Scheduling away the new linux thread is no issue. But
   when it comes back again, we will see those nice xnpod_fatal. The
   reason: our shadow thread is now linked to its linux mate, thus [1]
   will evaluate non-NULL, and later also [4] will hit as XNDORMANT is
   part of XNTHREAD_BLOCK_BITS (and the thread is not ptraced).

Ok, this is how I see THIS particular issue so far. For me the question
is now:

 a) I'm right?
 b) If yes, is this preemption uncritical, thus the warning in the
    described context a false positive?
 c) If it is not, can this cause the following crash?

Jan

[1]http://www.rts.uni-hannover.de/xenomai/lxr/source/ksrc/nucleus/shadow.c?v=SVN-trunk#L1515
[2]http://www.rts.uni-hannover.de/xenomai/lxr/source/ksrc/nucleus/shadow.c?v=SVN-trunk#L765
[3]http://www.rts.uni-hannover.de/xenomai/lxr/source/ksrc/nucleus/shadow.c?v=SVN-trunk#L621
[4]http://www.rts.uni-hannover.de/xenomai/lxr/source/ksrc/nucleus/shadow.c?v=SVN-trunk#L1555


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

Re: [Xenomai-core] [bug] don't try this at home...

[Philippe Gerum]

Jan Kiszka wrote:
> Philippe Gerum wrote:
> 
>>Jan Kiszka wrote:
>>
>>>Philippe Gerum wrote:
>>>
>>>
>>>>Jan Kiszka wrote:
>>>>
>>>>
>>>>>Jan Kiszka wrote:
>>>>>
>>>>>
>>>>>
>>>>>>Hi Philippe,
>>>>>>
>>>>>>I'm afraid this one is serious: let the attached migration stress test
>>>>>>run on likely any Xenomai since 2.0, preferably with
>>>>>>CONFIG_XENO_OPT_DEBUG on. Will give a nice crash sooner or later (I'm
>>>>>>trying to set up a serial console now).
>>>>>>
>>>>
>>>>Confirmed here. My test box went through some nifty triple salto out of
>>>>the window running this frag for 2mn or so. Actually, the semop
>>>>handshake is not even needed to cause the crash. At first sight, it
>>>>looks like a migration issue taking place during the critical phase when
>>>>a shadow thread switches back to Linux to terminate.
>>>>
>>>>
>>>>
>>>>>As it took some time to persuade my box to not just reboot but to
>>>>>give a
>>>>>message, I'm posting here the kernel dump of the P-III running
>>>>>nat_migration:
>>>>>
>>>>>[...]
>>>>>Xenomai: starting native API services.
>>>>>ce649fb4 ce648000 00000b17 00000202 c0139246 cdf2819c cdf28070 0b12d310
>>>>>      00000037 ce648000 00000000 c02f0700 00009a28 00000000 b7e94a70
>>>>>bfed63c8
>>>>>      00000000 ce648000 c0102fcb b7e94a70 bfed63dc b7faf4b0 bfed63c8
>>>>>00000000
>>>>>Call Trace:
>>>>>[<c0139246>] __ipipe_dispatch_event+0x96/0x130
>>>>>[<c0102fcb>] work_resched+0x6/0x1c
>>>>>Xenomai: fatal: blocked thread migration[22175] rescheduled?!
>>>>>(status=0x300010, sig=0, prev=watchdog/0[3])
>>>>
>>>>This babe is awaken by Linux while Xeno sees it in a dormant state,
>>>>likely after it has terminated. No wonder why things are going wild
>>>>after that... Ok, job queued. Thanks.
>>>>
>>>
>>>
>>>I think I can explain this warning now: This happens during creation of
>>>a new userspace real-time thread. In the context of the newly created
>>>Linux pthread that is to become a real-time thread, Xenomai first sets
>>>up the real-time part and then calls xnshadow_map. The latter function
>>>does further init and then signals via xnshadow_signal_completion to the
>>>parent Linux thread (the caller of rt_task_create e.g.) that the thread
>>>is up. This happens before xnshadow_harden, i.e. still in preemptible
>>>linux context.
>>>
>>>The signalling should normally do not cause a reschedule as the caller -
>>>the to-be-mapped linux pthread - has higher prio than the woken up
>>>thread.
>>
>>Xeno never assumes this.
>>
>> And Xenomai implicitly assumes with this fatal-test above that
>>
>>>there is no preemption! But it can happen: the watchdog thread of linux
>>>does preempt here. So, I think it's a false positive.
>>>
>>
>>This is wrong. This check is not related to Linux preemption at all; it
>>makes sure that control over any shadow is shared in a strictly
>>_mutually exclusive_ way, so that a thread blocked at Xenomai level may
>>not not be seen as runnable by Linux either. Disabling it only makes
>>things worse since the scheduling state is obviously corrupted when it
>>triggers, and that's the root bug we are chasing right now. You should
>>not draw any conclusion beyond that. Additionally, keep in mind that
>>Xeno has already run over some PREEMPT_RT patches, for which an infinite
>>number of CPUs is assumed over a fine-grained code base, which induces
>>maximum preemption probabilities.
>>
> 
> 
> Ok, may explanation was a quick hack before some meeting here, I should
> have elaborated it more thoroughly. Let's try to do it step by step so
> that you can say where I go of the right path:
> 
> 1. We enter xnshadow_map. The linux thread is happily running, the
>    shadow thread is in XNDORMANT state and not yet linked to its linux
>    mate. Any linux preemption hitting us here and causing a reactivation
>    of this particular linux thread later will not cause any activity of
>    do_schedule_event related to this thread because [1] is NULL. That's
>    important, we will see later why.
> 
> 2. After some init stuff, xnshadow_map links the shadow to the linux
>    thread [2] and then calls xnshadow_signal_completion. This call would
>    normally wake up the sleeping parent of our linux thread, performing
>    a direct standard linux schedule from the new born thread to the
>    parent. Again, nothing here about which do_schedule_event could
>    complain.
> 
> 3. Now let's consider some preemption by a third linux task after [2]
>    but before [3]. Scheduling away the new linux thread is no issue. But
>    when it comes back again, we will see those nice xnpod_fatal. The
>    reason: our shadow thread is now linked to its linux mate, thus [1]
>    will evaluate non-NULL, and later also [4] will hit as XNDORMANT is
>    part of XNTHREAD_BLOCK_BITS (and the thread is not ptraced).
> 
> Ok, this is how I see THIS particular issue so far. For me the question
> is now:
> 
>  a) I'm right?

Yes.

>  b) If yes, is this preemption uncritical, thus the warning in the
>     described context a false positive?

No.

>  c) If it is not, can this cause the following crash?
>

Since the only preemption opportunity that exists between [2] and [3] 
would come from a Linux IRQ, I remember now that we very recently played 
with the splhigh section around xnshadow_map() in native/syscall.c 
(rt_task_create)... Operations in xnshadow_map need to be reorganized 
now in order to put back part of the protection that was once brought by 
the former splhigh section. But, there is more than just calling the ptd 
setup code and xnshadow_signal_completion under IRQ stall, because since 
we could trigger a Linux rescheduling in the latter, we would keep 
Xenomai starved from IRQs across Linux context switches, which is also 
wrong.

> Jan
> 
> [1]http://www.rts.uni-hannover.de/xenomai/lxr/source/ksrc/nucleus/shadow.c?v=SVN-trunk#L1515
> [2]http://www.rts.uni-hannover.de/xenomai/lxr/source/ksrc/nucleus/shadow.c?v=SVN-trunk#L765
> [3]http://www.rts.uni-hannover.de/xenomai/lxr/source/ksrc/nucleus/shadow.c?v=SVN-trunk#L621
> [4]http://www.rts.uni-hannover.de/xenomai/lxr/source/ksrc/nucleus/shadow.c?v=SVN-trunk#L1555
> 


-- 

Philippe.

Re: [Xenomai-core] [bug] don't try this at home...

[Philippe Gerum]

Philippe Gerum wrote:
> Jan Kiszka wrote:
> 
>> Jan Kiszka wrote:
>>
>>> Hi Philippe,
>>>
>>> I'm afraid this one is serious: let the attached migration stress test
>>> run on likely any Xenomai since 2.0, preferably with
>>> CONFIG_XENO_OPT_DEBUG on. Will give a nice crash sooner or later (I'm
>>> trying to set up a serial console now).
>>>
> 
> Confirmed here. My test box went through some nifty triple salto out of 
> the window running this frag for 2mn or so. Actually, the semop 
> handshake is not even needed to cause the crash. At first sight, it 
> looks like a migration issue taking place during the critical phase when 
> a shadow thread switches back to Linux to terminate.
> 
>>
>>
>> As it took some time to persuade my box to not just reboot but to give a
>> message, I'm posting here the kernel dump of the P-III running
>> nat_migration:
>>
>> [...]
>> Xenomai: starting native API services.
>> ce649fb4 ce648000 00000b17 00000202 c0139246 cdf2819c cdf28070 0b12d310
>>        00000037 ce648000 00000000 c02f0700 00009a28 00000000 b7e94a70
>> bfed63c8
>>        00000000 ce648000 c0102fcb b7e94a70 bfed63dc b7faf4b0 bfed63c8
>> 00000000
>> Call Trace:
>>  [<c0139246>] __ipipe_dispatch_event+0x96/0x130
>>  [<c0102fcb>] work_resched+0x6/0x1c
>> Xenomai: fatal: blocked thread migration[22175] rescheduled?!
>> (status=0x300010, sig=0, prev=watchdog/0[3])
> 
> 
> This babe is awaken by Linux while Xeno sees it in a dormant state, 
> likely after it has terminated. No wonder why things are going wild 
> after that... Ok, job queued. Thanks.
> 
>>  CPU  PID    PRI  TIMEOUT  STAT      NAME
>>
>>> 0  0      0    0        00500080  ROOT
>>
>>
>>    0  22175  1    0        00300110  migration
>> Timer: none
>>
>> cea05ee4 d0842c62 cdcb0000 cea6d030 c02f0700 c035cbec c02f0700 00000286
>>        c0139246 00000022 c02f0700 cdf28070 cdf28070 00000022 00000001
>> c02f0700
>>        cea6d030 cdf28070 cea6d158 cea05f78 c02b26c0 cea04000 00000238
>> d1244537
>> Call Trace:
>>  [<c0139246>] __ipipe_dispatch_event+0x96/0x130
>>  [<c02b26c0>] schedule+0x2d0/0x720
>>  [<c0137b20>] watchdog+0x0/0x80
>>  [<c02b3967>] schedule_timeout+0x47/0xb0
>>  [<c0120070>] process_timeout+0x0/0x10
>>  [<c0120492>] msleep_interruptible+0x42/0x60
>>  [<c0137b70>] watchdog+0x50/0x80
>>  [<c012d0ab>] kthread+0x8b/0x90
>>  [<c012d020>] kthread+0x0/0x90
>>  [<c0100ef5>] kernel_thread_helper+0x5/0x10

Fixed. The cause was related to the thread migration routine to primary 
mode (xnshadow_harden), which would spuriously call the Linux 
rescheduling procedure from the primary domain under certain 
circumstances. This bug only triggers on preemptible kernels. This also 
fixes the spinlock recursion issue which is sometimes triggered when the 
spinlock debug option is active.

-- 

Philippe.

Re: [Xenomai-core] [bug] don't try this at home...

[Philippe Gerum]

Philippe Gerum wrote:
> Philippe Gerum wrote:
> 
>> Jan Kiszka wrote:
>>
>>> Jan Kiszka wrote:
>>>
>>>> Hi Philippe,
>>>>
>>>> I'm afraid this one is serious: let the attached migration stress test
>>>> run on likely any Xenomai since 2.0, preferably with
>>>> CONFIG_XENO_OPT_DEBUG on. Will give a nice crash sooner or later (I'm
>>>> trying to set up a serial console now).
>>>>
>>
>> Confirmed here. My test box went through some nifty triple salto out 
>> of the window running this frag for 2mn or so. Actually, the semop 
>> handshake is not even needed to cause the crash. At first sight, it 
>> looks like a migration issue taking place during the critical phase 
>> when a shadow thread switches back to Linux to terminate.
>>
>>>
>>>
>>> As it took some time to persuade my box to not just reboot but to give a
>>> message, I'm posting here the kernel dump of the P-III running
>>> nat_migration:
>>>
>>> [...]
>>> Xenomai: starting native API services.
>>> ce649fb4 ce648000 00000b17 00000202 c0139246 cdf2819c cdf28070 0b12d310
>>>        00000037 ce648000 00000000 c02f0700 00009a28 00000000 b7e94a70
>>> bfed63c8
>>>        00000000 ce648000 c0102fcb b7e94a70 bfed63dc b7faf4b0 bfed63c8
>>> 00000000
>>> Call Trace:
>>>  [<c0139246>] __ipipe_dispatch_event+0x96/0x130
>>>  [<c0102fcb>] work_resched+0x6/0x1c
>>> Xenomai: fatal: blocked thread migration[22175] rescheduled?!
>>> (status=0x300010, sig=0, prev=watchdog/0[3])
>>
>>
>>
>> This babe is awaken by Linux while Xeno sees it in a dormant state, 
>> likely after it has terminated. No wonder why things are going wild 
>> after that... Ok, job queued. Thanks.
>>
>>>  CPU  PID    PRI  TIMEOUT  STAT      NAME
>>>
>>>> 0  0      0    0        00500080  ROOT
>>>
>>>
>>>
>>>    0  22175  1    0        00300110  migration
>>> Timer: none
>>>
>>> cea05ee4 d0842c62 cdcb0000 cea6d030 c02f0700 c035cbec c02f0700 00000286
>>>        c0139246 00000022 c02f0700 cdf28070 cdf28070 00000022 00000001
>>> c02f0700
>>>        cea6d030 cdf28070 cea6d158 cea05f78 c02b26c0 cea04000 00000238
>>> d1244537
>>> Call Trace:
>>>  [<c0139246>] __ipipe_dispatch_event+0x96/0x130
>>>  [<c02b26c0>] schedule+0x2d0/0x720
>>>  [<c0137b20>] watchdog+0x0/0x80
>>>  [<c02b3967>] schedule_timeout+0x47/0xb0
>>>  [<c0120070>] process_timeout+0x0/0x10
>>>  [<c0120492>] msleep_interruptible+0x42/0x60
>>>  [<c0137b70>] watchdog+0x50/0x80
>>>  [<c012d0ab>] kthread+0x8b/0x90
>>>  [<c012d020>] kthread+0x0/0x90
>>>  [<c0100ef5>] kernel_thread_helper+0x5/0x10
> 
> 
> Fixed. The cause was related to the thread migration routine to primary 
> mode (xnshadow_harden), which would spuriously call the Linux 
> rescheduling procedure from the primary domain under certain 
> circumstances. This bug only triggers on preemptible kernels. This also 
> fixes the spinlock recursion issue which is sometimes triggered when the 
> spinlock debug option is active.
> 

Gasp. I've found a severe regression with this fix, so more work is 
needed. More later.

-- 

Philippe.

Re: [Xenomai-core] [bug] don't try this at home...

[Philippe Gerum]

Philippe Gerum wrote:
> Philippe Gerum wrote:
> 
>> Philippe Gerum wrote:
>>
>>> Jan Kiszka wrote:
>>>
>>>> Jan Kiszka wrote:
>>>>
>>>>> Hi Philippe,
>>>>>
>>>>> I'm afraid this one is serious: let the attached migration stress test
>>>>> run on likely any Xenomai since 2.0, preferably with
>>>>> CONFIG_XENO_OPT_DEBUG on. Will give a nice crash sooner or later (I'm
>>>>> trying to set up a serial console now).
>>>>>
>>>
>>> Confirmed here. My test box went through some nifty triple salto out 
>>> of the window running this frag for 2mn or so. Actually, the semop 
>>> handshake is not even needed to cause the crash. At first sight, it 
>>> looks like a migration issue taking place during the critical phase 
>>> when a shadow thread switches back to Linux to terminate.
>>>
>>>>
>>>>
>>>> As it took some time to persuade my box to not just reboot but to 
>>>> give a
>>>> message, I'm posting here the kernel dump of the P-III running
>>>> nat_migration:
>>>>
>>>> [...]
>>>> Xenomai: starting native API services.
>>>> ce649fb4 ce648000 00000b17 00000202 c0139246 cdf2819c cdf28070 0b12d310
>>>>        00000037 ce648000 00000000 c02f0700 00009a28 00000000 b7e94a70
>>>> bfed63c8
>>>>        00000000 ce648000 c0102fcb b7e94a70 bfed63dc b7faf4b0 bfed63c8
>>>> 00000000
>>>> Call Trace:
>>>>  [<c0139246>] __ipipe_dispatch_event+0x96/0x130
>>>>  [<c0102fcb>] work_resched+0x6/0x1c
>>>> Xenomai: fatal: blocked thread migration[22175] rescheduled?!
>>>> (status=0x300010, sig=0, prev=watchdog/0[3])
>>>
>>>
>>>
>>>
>>> This babe is awaken by Linux while Xeno sees it in a dormant state, 
>>> likely after it has terminated. No wonder why things are going wild 
>>> after that... Ok, job queued. Thanks.
>>>
>>>>  CPU  PID    PRI  TIMEOUT  STAT      NAME
>>>>
>>>>> 0  0      0    0        00500080  ROOT
>>>>
>>>>
>>>>
>>>>
>>>>    0  22175  1    0        00300110  migration
>>>> Timer: none
>>>>
>>>> cea05ee4 d0842c62 cdcb0000 cea6d030 c02f0700 c035cbec c02f0700 00000286
>>>>        c0139246 00000022 c02f0700 cdf28070 cdf28070 00000022 00000001
>>>> c02f0700
>>>>        cea6d030 cdf28070 cea6d158 cea05f78 c02b26c0 cea04000 00000238
>>>> d1244537
>>>> Call Trace:
>>>>  [<c0139246>] __ipipe_dispatch_event+0x96/0x130
>>>>  [<c02b26c0>] schedule+0x2d0/0x720
>>>>  [<c0137b20>] watchdog+0x0/0x80
>>>>  [<c02b3967>] schedule_timeout+0x47/0xb0
>>>>  [<c0120070>] process_timeout+0x0/0x10
>>>>  [<c0120492>] msleep_interruptible+0x42/0x60
>>>>  [<c0137b70>] watchdog+0x50/0x80
>>>>  [<c012d0ab>] kthread+0x8b/0x90
>>>>  [<c012d020>] kthread+0x0/0x90
>>>>  [<c0100ef5>] kernel_thread_helper+0x5/0x10
>>
>>
>>
>> Fixed. The cause was related to the thread migration routine to 
>> primary mode (xnshadow_harden), which would spuriously call the Linux 
>> rescheduling procedure from the primary domain under certain 
>> circumstances. This bug only triggers on preemptible kernels. This 
>> also fixes the spinlock recursion issue which is sometimes triggered 
>> when the spinlock debug option is active.
>>
> 
> Gasp. I've found a severe regression with this fix, so more work is 
> needed. More later.
> 

End of alert. Should be ok now.

-- 

Philippe.

Re: [Xenomai-core] [bug] don't try this at home...

[Jan Kiszka]

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

Philippe Gerum wrote:
>>> ...
>>> Fixed. The cause was related to the thread migration routine to
>>> primary mode (xnshadow_harden), which would spuriously call the Linux
>>> rescheduling procedure from the primary domain under certain
>>> circumstances. This bug only triggers on preemptible kernels. This
>>> also fixes the spinlock recursion issue which is sometimes triggered
>>> when the spinlock debug option is active.
>>>
>>
>> Gasp. I've found a severe regression with this fix, so more work is
>> needed. More later.
>>
> 
> End of alert. Should be ok now.
> 

No crashes so far, looks good. But the final test, a box which always
went to hell very quickly, is still waiting in my office - more on Monday.

Anyway, there seems to be some latency issues pending. I discovered this
again with my migration test. Please give it a try on a mid- (800 MHz
Athlon in my case) to low-end box. On that Athlon I got peaks of over
100 us in the userspace latency test right on starting migration. The
Athlon does not support the NMI watchdog, but on my 1.4 GHz Notebook
there were alarms (>30 us) hitting in the native registry during
rt_task_create. I have no clue yet if anything is broken there. We need
that back-tracer soon - did I mentioned this before? ;)

BTW, a kernel timer latency test based on a RTDM device is half-done.
I'm able to dump kernel-based timed-task latencies via a patched
testsuite latency. Histograms need to be added as well as a timer
handler latency test. Will keep you posted.

Jan

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

Re: [Xenomai-core] [bug] don't try this at home...

[Philippe Gerum]

Jan Kiszka wrote:
> Philippe Gerum wrote:
> 
>>>>...
>>>>Fixed. The cause was related to the thread migration routine to
>>>>primary mode (xnshadow_harden), which would spuriously call the Linux
>>>>rescheduling procedure from the primary domain under certain
>>>>circumstances. This bug only triggers on preemptible kernels. This
>>>>also fixes the spinlock recursion issue which is sometimes triggered
>>>>when the spinlock debug option is active.
>>>>
>>>
>>>Gasp. I've found a severe regression with this fix, so more work is
>>>needed. More later.
>>>
>>
>>End of alert. Should be ok now.
>>
> 
> 
> No crashes so far, looks good. But the final test, a box which always
> went to hell very quickly, is still waiting in my office - more on Monday.
> 
> Anyway, there seems to be some latency issues pending. I discovered this
> again with my migration test. Please give it a try on a mid- (800 MHz
> Athlon in my case) to low-end box. On that Athlon I got peaks of over
> 100 us in the userspace latency test right on starting migration. The
> Athlon does not support the NMI watchdog, but on my 1.4 GHz Notebook
> there were alarms (>30 us) hitting in the native registry during
> rt_task_create. I have no clue yet if anything is broken there.

I suspect that rt_registry_enter() is inherently a long operation when 
considered as a non-preemptible sum of reasonably short ones. Since it 
is always called with interrupts enabled, we should split the work in 
there, releasing interrupts in the middle. The tricky thing is that we 
must ensure that the new registration slot is not exposed in a 
half-baked state during the preemptible section.

> We need
> that back-tracer soon - did I mentioned this before? ;)

Well, we have a backtrace support for detecting latency peaks, but it's 
dependent on NMI availability. The thing is that not every platform 
provides a programmable NMI support. A possible option would be to 
overload the existing LTT tracepoints in order to keep an execution 
backtrace, so that we would not have to rely on any hw support.

> 
> BTW, a kernel timer latency test based on a RTDM device is half-done.
> I'm able to dump kernel-based timed-task latencies via a patched
> testsuite latency. Histograms need to be added as well as a timer
> handler latency test. Will keep you posted.
> 

Ack. This would also cleanly solve the 
"where-am-i-going-to-put-that-stuff" issue wrt the latency kernel module 
the user-space section cannot/should not have to compile anymore in 2.1. 
I guess that moving it to the ksrc/drivers/ section would then be the 
most natural thing to do.

> Jan


-- 

Philippe.

Re: [Xenomai-core] [bug] don't try this at home...

[Jan Kiszka]

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

Philippe Gerum wrote:
> Jan Kiszka wrote:
> 
>> Philippe Gerum wrote:
>>
>>>>> ...
>>>>> Fixed. The cause was related to the thread migration routine to
>>>>> primary mode (xnshadow_harden), which would spuriously call the Linux
>>>>> rescheduling procedure from the primary domain under certain
>>>>> circumstances. This bug only triggers on preemptible kernels. This
>>>>> also fixes the spinlock recursion issue which is sometimes triggered
>>>>> when the spinlock debug option is active.
>>>>>
>>>>
>>>> Gasp. I've found a severe regression with this fix, so more work is
>>>> needed. More later.
>>>>
>>>
>>> End of alert. Should be ok now.
>>>
>>
>>
>> No crashes so far, looks good. But the final test, a box which always
>> went to hell very quickly, is still waiting in my office - more on
>> Monday.
>>
>> Anyway, there seems to be some latency issues pending. I discovered this
>> again with my migration test. Please give it a try on a mid- (800 MHz
>> Athlon in my case) to low-end box. On that Athlon I got peaks of over
>> 100 us in the userspace latency test right on starting migration. The
>> Athlon does not support the NMI watchdog, but on my 1.4 GHz Notebook
>> there were alarms (>30 us) hitting in the native registry during
>> rt_task_create. I have no clue yet if anything is broken there.
> 
> 
> I suspect that rt_registry_enter() is inherently a long operation when
> considered as a non-preemptible sum of reasonably short ones. Since it
> is always called with interrupts enabled, we should split the work in
> there, releasing interrupts in the middle. The tricky thing is that we
> must ensure that the new registration slot is not exposed in a
> half-baked state during the preemptible section.

Yea, I guess there are a few more of such complex call chains inside the
core lock, at least when looking at the native skin. For a regression
test suite, we should define load scenarios of low-prio realtime tasks
doing some init/cleanup and communication while e.g. the latency test is
running. This should give a clearer picture what numbers you can expect
in a normal application scenarios.

> 
>> We need
>> that back-tracer soon - did I mentioned this before? ;)
> 
> 
> Well, we have a backtrace support for detecting latency peaks, but it's
> dependent on NMI availability. The thing is that not every platform
> provides a programmable NMI support. A possible option would be to
> overload the existing LTT tracepoints in order to keep an execution
> backtrace, so that we would not have to rely on any hw support.
> 

The advantage of Fu's mcount-based tracer will be that is can capture
also functions you do not expect, e.g. accidentally called kernel
services. His patch, likely against Adeos, will enable kernel-wide
function tracing which you can use to instrument IRQ-off paths or (in a
second step or so) others things you are interested in. And it will
maintain a FULL calling history, something that NMI can't do.

NMI will still be useful for hard lock-ups, LTT for a more global view
what's happening, but the mcount-instrumentation should give deep
insights on the core's and skin's critical timing behaviours.

Jan

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

Re: [Xenomai-core] [bug] don't try this at home...

[Philippe Gerum]

Jan Kiszka wrote:
> Philippe Gerum wrote:
> 
>>Jan Kiszka wrote:
>>
>>
>>>Philippe Gerum wrote:
>>>
>>>
>>>>>>...
>>>>>>Fixed. The cause was related to the thread migration routine to
>>>>>>primary mode (xnshadow_harden), which would spuriously call the Linux
>>>>>>rescheduling procedure from the primary domain under certain
>>>>>>circumstances. This bug only triggers on preemptible kernels. This
>>>>>>also fixes the spinlock recursion issue which is sometimes triggered
>>>>>>when the spinlock debug option is active.
>>>>>>
>>>>>
>>>>>Gasp. I've found a severe regression with this fix, so more work is
>>>>>needed. More later.
>>>>>
>>>>
>>>>End of alert. Should be ok now.
>>>>
>>>
>>>
>>>No crashes so far, looks good. But the final test, a box which always
>>>went to hell very quickly, is still waiting in my office - more on
>>>Monday.
>>>
>>>Anyway, there seems to be some latency issues pending. I discovered this
>>>again with my migration test. Please give it a try on a mid- (800 MHz
>>>Athlon in my case) to low-end box. On that Athlon I got peaks of over
>>>100 us in the userspace latency test right on starting migration. The
>>>Athlon does not support the NMI watchdog, but on my 1.4 GHz Notebook
>>>there were alarms (>30 us) hitting in the native registry during
>>>rt_task_create. I have no clue yet if anything is broken there.
>>
>>
>>I suspect that rt_registry_enter() is inherently a long operation when
>>considered as a non-preemptible sum of reasonably short ones. Since it
>>is always called with interrupts enabled, we should split the work in
>>there, releasing interrupts in the middle. The tricky thing is that we
>>must ensure that the new registration slot is not exposed in a
>>half-baked state during the preemptible section.
> 
> 
> Yea, I guess there are a few more of such complex call chains inside the
> core lock, at least when looking at the native skin. For a regression
> test suite, we should define load scenarios of low-prio realtime tasks
> doing some init/cleanup and communication while e.g. the latency test is
> running. This should give a clearer picture what numbers you can expect
> in a normal application scenarios.
> 
> 
>>>We need
>>>that back-tracer soon - did I mentioned this before? ;)
>>
>>
>>Well, we have a backtrace support for detecting latency peaks, but it's
>>dependent on NMI availability. The thing is that not every platform
>>provides a programmable NMI support. A possible option would be to
>>overload the existing LTT tracepoints in order to keep an execution
>>backtrace, so that we would not have to rely on any hw support.
>>
> 
> 
> The advantage of Fu's mcount-based tracer will be that is can capture
> also functions you do not expect, e.g. accidentally called kernel
> services. His patch, likely against Adeos, will enable kernel-wide
> function tracing which you can use to instrument IRQ-off paths or (in a
> second step or so) others things you are interested in. And it will
> maintain a FULL calling history, something that NMI can't do.
> 
> NMI will still be useful for hard lock-ups, LTT for a more global view
> what's happening, but the mcount-instrumentation should give deep
> insights on the core's and skin's critical timing behaviours.
> 

No problem. I've just suggested to build a bicycle to go to the shop 
around the corner, but if you tell me that a spaceship to visit Venus is 
at hand, I'll wait for it: shopping can wait.

-- 

Philippe.

Re: [Xenomai-core] [bug] don't try this at home...

[Jan Kiszka]

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

Philippe Gerum wrote:
> Jan Kiszka wrote:
>> ...
>> Anyway, there seems to be some latency issues pending. I discovered this
>> again with my migration test. Please give it a try on a mid- (800 MHz
>> Athlon in my case) to low-end box. On that Athlon I got peaks of over
>> 100 us in the userspace latency test right on starting migration. The
>> Athlon does not support the NMI watchdog, but on my 1.4 GHz Notebook
>> there were alarms (>30 us) hitting in the native registry during
>> rt_task_create. I have no clue yet if anything is broken there.
> 
> 
> I suspect that rt_registry_enter() is inherently a long operation when
> considered as a non-preemptible sum of reasonably short ones. Since it
> is always called with interrupts enabled, we should split the work in
> there, releasing interrupts in the middle. The tricky thing is that we
> must ensure that the new registration slot is not exposed in a
> half-baked state during the preemptible section.
> 

Grr, I should stop profiling systems which have DEBUG options switched
on (e.g. Xenomain's queue debugging...). This totally skrewed up my
measurings - end of alarm, all fine!

Anyway, keeping the number of ops inside continues lock paths low is a
good thing. But if the task deletions path is already one of the most
critical points, needs some analysis first.

Jan

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