Re: RTAI 5.0-test2 released
Sebastian Kuzminsky <[email protected]>
| Newsgroups | gmane.linux.real-time.rtai |
|---|---|
| Message-ID | <[email protected]> |
On 06/28/2016 01:30 AM, Paolo Mantegazza wrote: > On 06/27/2016 05:27 PM, Sebastian Kuzminsky wrote: >> I've observed failures during unload in virtual machines. Here's a >> kernel log of two consecutive test cases from our test suite, where >> the machine locked up during unload on the second test case: >> >>> [ 8780.404223] I-pipe: head domain RTAI registered. >>> [ 8780.405262] RTAI[hal]: mounted. ISOL_CPUS_MASK: 1. >>> [ 8780.406019] SYSINFO - # CPUs: 2, TIMER NAME: 'lapic', >>> TIMER IRQ: 2305, TIMER FREQ: 62502000, CLOCK NAME: 'tsc', CLOCK FREQ: >>> 2000081000, CPU FREQ: 2000081000, LINUX TIMER IRQ: 2305. >>> [ 8780.414520] RTAI[malloc]: global heap size = 2097152 >>> bytes, <BSD>. >>> [ 8780.415838] , kstacks pool size = 524288 bytes. >>> [ 8780.416828] RTAI[sched]: hard timer type/freq = >>> lapic/62502000(Hz); timing: oneshot; linear timed lists. >>> [ 8780.418232] RTAI[sched]: Linux timer freq = 250 (Hz), >>> TimeBase freq = 2000081000 hz. >>> [ 8780.419350] RTAI[sched]: timer setup = 1504 ns, resched >>> latency = 0 ns. >>> [ 8780.449429] USERMODE CHECK: OK. >>> [ 8780.449941] USERMODE CHECK PROVIDED (ns): KernelLatency >>> 8897, UserLatency 9087. >>> [ 8780.451010] FINAL CALIBRATION SUMMARY (ns): KernelLatency >>> 8897, UserLatency 9087. >>> [ 8780.455566] RTAI[math]: loaded, using NEWLIB. >>> [ 8781.136562] RTAI[math]: unloaded. >>> [ 8781.148269] SCHED releases registered named ALIEN PEDV$D >>> [ 8781.169297] RTAI[malloc]: unloaded. >>> [ 8781.268150] RTAI[sched]: unloaded (forced hard/soft/hard >>> transitions: traps 0, syscalls 0). >>> [ 8781.273428] I-pipe: head domain RTAI unregistered. >>> [ 8781.275513] RTAI[hal]: unmounted. >> >>> [ 8781.356263] I-pipe: head domain RTAI registered. >>> [ 8781.357292] RTAI[hal]: mounted. ISOL_CPUS_MASK: 1. >>> [ 8781.358043] SYSINFO - # CPUs: 2, TIMER NAME: 'lapic', >>> TIMER IRQ: 2305, TIMER FREQ: 62502000, CLOCK NAME: 'tsc', CLOCK FREQ: >>> 2000081000, CPU FREQ: 2000081000, LINUX TIMER IRQ: 2305. >>> [ 8781.366385] RTAI[malloc]: global heap size = 2097152 >>> bytes, <BSD>. >>> [ 8781.367682] , kstacks pool size = 524288 bytes. >>> [ 8781.368639] RTAI[sched]: hard timer type/freq = >>> lapic/62502000(Hz); timing: oneshot; linear timed lists. >>> [ 8781.370053] RTAI[sched]: Linux timer freq = 250 (Hz), >>> TimeBase freq = 2000081000 hz. >>> [ 8781.371301] RTAI[sched]: timer setup = 1499 ns, resched >>> latency = 0 ns. >>> [ 8781.401245] USERMODE CHECK: OK. >>> [ 8781.401761] USERMODE CHECK PROVIDED (ns): KernelLatency >>> 8897, UserLatency 9087. >>> [ 8781.402845] FINAL CALIBRATION SUMMARY (ns): KernelLatency >>> 8897, UserLatency 9087. >>> [ 8781.407514] RTAI[math]: loaded, using NEWLIB. >>> [ 8781.488021] RTAI[math]: unloaded. >>> *** lockup here, while waiting for "SCHED releases registered >>> named ALIEN PEDV$D" >> > > OK I got it. From what you say, I see no reason for a running task to > work not. So, as a first step and sticking to what you show above, I > dare asking: what kind of object is "ALIEN PEDV$D"? Can you try to have > it closed by the code that uses it? > If that is not enough we'll see what else to do. The "SCHED releases registered named ALIENT PEDV$D" message comes from base/sched/api.c:krtai_objects_release(), called by rtai_sched.ko on module exit. It's not part of our code, it's printed (for example) when you ^C any of the testsuite/kern/* programs. While running the testsuite/kern/latency test, i see this in /proc/rtai/names: > RTAI LXRT Information. > > MAX_SLOTS = 150 > > Linux_Owner Parent PID > Slot Name ID Type RT_Handle Pointer Tsk_PID MEM_Sz USG Cnt > ------------------------------------------------------------------------------- > 158 THRSRV 0xb3b3a159 TASK 0xf871b220 0x (null) 0 2096 1 > 192 PEDV$D 0x9ac6d9e7 SHMEM 0xf871a000 0x (null) 0 2097152 1 I changed krtai_objects_release() to not call num2nam() on ALIEN objects, and instead print out the rt_registry_entry fields, and what's there looks totally bogus: > Jun 28 10:18:30 jessie-rtai-i386 kernel: [ 3133.151609] I-pipe: head domain RTAI registered. > Jun 28 10:18:30 jessie-rtai-i386 kernel: [ 3133.152660] RTAI[hal]: mounted. ISOL_CPUS_MASK: 1. > Jun 28 10:18:30 jessie-rtai-i386 kernel: [ 3133.153407] SYSINFO - # CPUs: 2, TIMER NAME: 'lapic', TIMER IRQ: 2305, TIMER FREQ: 62500999, CLOCK NAME: 'tsc', CLOCK FREQ: 2000053000, CPU FREQ: 2000053000, LINUX TIMER IRQ: 2305. > Jun 28 10:18:30 jessie-rtai-i386 kernel: [ 3133.164134] RTAI[malloc]: global heap size = 2097152 bytes, <BSD>. > Jun 28 10:18:30 jessie-rtai-i386 kernel: [ 3133.165450] , kstacks pool size = 524288 bytes. > Jun 28 10:18:30 jessie-rtai-i386 kernel: [ 3133.166155] RTAI[sched]: hard timer type/freq = lapic/62500999(Hz); timing: oneshot; linear timed lists. > Jun 28 10:18:30 jessie-rtai-i386 kernel: [ 3133.167629] RTAI[sched]: Linux timer freq = 250 (Hz), TimeBase freq = 2000053000 hz. > Jun 28 10:18:30 jessie-rtai-i386 kernel: [ 3133.169726] RTAI[sched]: timer setup = 1505 ns, resched latency = 0 ns. > Jun 28 10:18:30 jessie-rtai-i386 kernel: [ 3133.200643] USERMODE CHECK: OK. > Jun 28 10:18:30 jessie-rtai-i386 kernel: [ 3133.201146] USERMODE CHECK PROVIDED (ns): KernelLatency 8896, UserLatency 9086. > Jun 28 10:18:30 jessie-rtai-i386 kernel: [ 3133.202212] FINAL CALIBRATION SUMMARY (ns): KernelLatency 8896, UserLatency 9086. > Jun 28 10:18:30 jessie-rtai-i386 kernel: [ 3133.207419] RTAI[math]: loaded, using NEWLIB. > Jun 28 10:18:30 jessie-rtai-i386 kernel: [ 3133.466685] RTAI[math]: unloaded. > Jun 28 10:18:30 jessie-rtai-i386 kernel: [ 3133.480200] ALIEN entry: > Jun 28 10:18:30 jessie-rtai-i386 kernel: [ 3133.480661] entry.name=-1698244121 > Jun 28 10:18:30 jessie-rtai-i386 kernel: [ 3133.481374] entry.adr=f86d6000 > Jun 28 10:18:30 jessie-rtai-i386 kernel: [ 3133.481945] entry.tsk= (null) > Jun 28 10:18:30 jessie-rtai-i386 kernel: [ 3133.482512] entry.type=2097152 > Jun 28 10:18:30 jessie-rtai-i386 kernel: [ 3133.483073] entry.count=1 > Jun 28 10:18:30 jessie-rtai-i386 kernel: [ 3133.483581] entry.alink=176 > Jun 28 10:18:30 jessie-rtai-i386 kernel: [ 3133.484733] entry.nlink=0 > Jun 28 10:18:30 jessie-rtai-i386 kernel: [ 3133.505282] RTAI[malloc]: unloaded. > Jun 28 10:18:31 jessie-rtai-i386 kernel: [ 3133.604147] RTAI[sched]: unloaded (forced hard/soft/hard transitions: traps 0, syscalls 0). > Jun 28 10:18:31 jessie-rtai-i386 kernel: [ 3133.607569] I-pipe: head domain RTAI unregistered. > Jun 28 10:18:31 jessie-rtai-i386 kernel: [ 3133.609699] RTAI[hal]: unmounted. This led me to look closer at the hashed registry code, and it looks to me like there's a bug there (though probably not the bug causing the lockups i'm seeing): 1. Register an entry that hashes to slot 100. 2. Register another entry that also hashes to slot 100. The insert code will notice the collision and instead use the next free slot, let's say 100. 3. Remove the entry from step 1. 4. Now try to look up the entry from step 2. It will hash to slot 100, but 100 is empty, so the lookup fails. The normal way to handle hash collisions is to put a linked list in the bucket, and add all colliding entries to that list. This way there's never any question where to find an entry. I'll keep looking for the cause of my lockups... -- Sebastian Kuzminsky _______________________________________________ Rtai mailing list [email protected] https://mail.rtai.org/cgi-bin/mailman/listinfo/rtai