Re: rtmutex assert failure (was [Patch] restore the RCU callback...)

Robert Crocombe
2006-08-29T04:05:29Z

On 8/28/06, hui Bill Huey <billh@gnuppy.monkey.org> wrote:

> I was unclear in explain that __put_task_struct() should never
> appear with free_task() in a stack trace as you can clearly see
> from the implementation. All it's suppose to do is wake a thread,
> so "how?" you're getting those things simultaneously in the stack
> trace is completely baffling to me. Could you double check to see
> if it's booting the right kernel ? maybe make sure that's calling
> that version of the function with printks or something ?

So I built another kernel with the most recent "t6" patches from
scratch and stuck in a directory 2.6.17-rt8-mrproper.

[rcrocomb@spanky ~]$ cd kernel/
[rcrocomb@spanky kernel]$ rm -Rf test_2.6.17-rt8/
[rcrocomb@spanky kernel]$ tar xf source/linux-2.6.16.tar
[rcrocomb@spanky kernel]$ mv linux-2.6.16/ 2.6.17-rt8-mrproper
[rcrocomb@spanky kernel]$ cd 2.6.17-rt8-mrproper/
[rcrocomb@spanky 2.6.17-rt8-mrproper]$ patch -s -p1 < ../patches/patch-2.6.17
[rcrocomb@spanky 2.6.17-rt8-mrproper]$ patch -s -p1 <
../patches/patch-2.6.17-rt8
[rcrocomb@spanky 2.6.17-rt8-mrproper]$ patch -s -p0 < ../patches/t6.diff
[rcrocomb@spanky 2.6.17-rt8-mrproper]$ uname -r
2.6.17-rt8_UP_00
[rcrocomb@spanky 2.6.17-rt8-mrproper]$ zcat /proc/config.gz > ./.config
[rcrocomb@spanky 2.6.17-rt8-mrproper]$ make oldconfig

I added some printk()s:

[rcrocomb@spanky 2.6.17-rt8-mrproper]$ diff -u
~/kernel/2.6.17-rt8-t6/kernel/fork.c kernel/fork.c
--- /home/rcrocomb/kernel/2.6.17-rt8-t6/kernel/fork.c 2006-08-25
13:32:43.000000000 -0700
+++ kernel/fork.c 2006-08-28 19:52:22.000000000 -0700
@@ -1753,12 +1753,16 @@
{
struct list_head *head;

+ printk(KERN_DEBUG "+");
+
head = &get_cpu_var(delayed_put_task_struct_list);
list_add_tail(&task->delayed_drop, head);

_wake_cpu_desched_task();

put_cpu_var(delayed_put_task_struct_list);
+
+ printk(KERN_DEBUG "-\n");
}
#endif

but these make the machine sad:

+<3>BUG: sleeping function called from invalid context modprobe(2927)
at kernel/rtmutex.c:777
in_atomic():1 [00000001], irqs_disabled():0

Call Trace:
<ffffffff80304596>{vgacon_cursor+470}
<ffffffff8020b2c6>{__might_sleep+271}
<ffffffff8025f276>{rt_lock+155}
<ffffffff80337cb6>{serial8250_console_write+86}
<ffffffff803310e1>{vt_console_print+550}
<ffffffff80279c24>{__call_console_drivers+75}
<ffffffff80279c9b>{_call_console_drivers+102}
<ffffffff80215e11>{release_console_sem+372}
<ffffffff8027a212>{vprintk+671}
<ffffffff802629c9>{__switch_to+42}
<ffffffff8028f2ff>{debug_rt_mutex_lock+186}
<ffffffff8027a2cd>{printk+103}
<ffffffff80244d0b>{try_to_wake_up+358}
<ffffffff802629c9>{__switch_to+42}
<ffffffff80245886>{__put_task_struct+26}
<ffffffff8025d556>{thread_return+144}
<ffffffff80278939>{rt_mutex_setprio+206}
<ffffffff8025d662>{preempt_schedule+80}
<ffffffff8028d9af>{rt_mutex_adjust_prio+80}
<ffffffff8025ec99>{rt_lock_slowunlock+181}
<ffffffff8025f1d9>{__lock_text_start+9}
<ffffffff8025f4c5>{rt_write_unlock+9}
<ffffffff802149df>{do_exit+2100}
<ffffffff8028f452>{debug_rt_mutex_unlock+293}
<ffffffff80246f79>{cpu_idle+0}
<ffffffff8024a87a>{sys_exit_group+18}
<ffffffff8025964e>{system_call+126}
---------------------------
| preempt count: 00000001 ]
| 1-level deep critical section nesting:
----------------------------------------
.. [<ffffffff8025d003>] .... __schedule+0xb3/0x576
.....[<ffffffff8025d662>] .. ( <= preempt_schedule+0x50/0x81)
-

I originally was using KERN_ERR, but the machine wouldn't finish
booting, so I thought that by using KERN_DEBUG, I could boot it and
then switch loglevels with Sysrq. So I think it's relatively assured
that it is indeed going into this version of __put_task_struct(). If
it's at all valuable, the last character printing before lockup was
always the "+" character, but this last char is only on the video
console and not the serial.

Err, I hope this is what you meant. I have unlimited bits, and can
sprinkle them whereever you'd like.

Also, I switched up configs a bit (disabling a few debugging options)
because I was curious as to what gcc -E would show when processing
fork.c, and it appeared that lots of code could be snipped by doing
this. I kinda hoped there was some cool GNU utility to generate a
static call graph or similar (I was trying to find how free_task()
could come after __put_task_struct() as you mentioned). I've appended
a diff of the config from the original UP kernel and 'mrproper''.
Note that UP is vanilla 2.6.17-rt8 while mrproper includes your t6
patches (but its CONFIG_LOCALVERSION is UP_01 vs UP_00: consistency is
not my strong suit).

After the config diff is the result of the command:

gcc -D__KERNEL__ -I../include -E fork.c

(which I hope is reasonable) while in the kernel directory. I hoped
that a free_task() would magically appear, but was disappointed, and
tracing down and expanding all the various functions made me dizzy.
Someone needs to hook 'sparse' and graphviz together >:<.

--
Robert Crocombe
rcrocomb@gmail.com

[rcrocomb@spanky 2.6.17-rt8-mrproper]$ diff -u
~/kernel/2.6.17-rt8-UP/.config ./.config
--- /home/rcrocomb/kernel/2.6.17-rt8-UP/.config 2006-08-25
17:14:28.000000000 -0700
+++ ./.config 2006-08-28 19:57:33.000000000 -0700
@@ -1,7 +1,7 @@
#
# Automatically generated make config: don't edit
# Linux kernel version: 2.6.17-rt8
-# Fri Aug 25 17:14:28 2006
+# Mon Aug 28 19:57:33 2006
#
CONFIG_X86_64=y
CONFIG_64BIT=y
@@ -30,7 +30,7 @@
#
# General setup
#
-CONFIG_LOCALVERSION="_UP_00"
+CONFIG_LOCALVERSION="_UP_01"
CONFIG_LOCALVERSION_AUTO=y
CONFIG_SWAP=y
CONFIG_SYSVIPC=y
@@ -1026,19 +1026,10 @@
CONFIG_DEBUG_RT_MUTEXES=y
CONFIG_DEBUG_PI_LIST=y
# CONFIG_RT_MUTEX_TESTER is not set
-CONFIG_WAKEUP_TIMING=y
-CONFIG_WAKEUP_LATENCY_HIST=y
+# CONFIG_WAKEUP_TIMING is not set
CONFIG_PREEMPT_TRACE=y
-CONFIG_CRITICAL_PREEMPT_TIMING=y
-CONFIG_PREEMPT_OFF_HIST=y
-CONFIG_CRITICAL_IRQSOFF_TIMING=y
-CONFIG_INTERRUPT_OFF_HIST=y
-CONFIG_CRITICAL_TIMING=y
-CONFIG_DEBUG_TRACE_IRQFLAGS=y
-CONFIG_LATENCY_TIMING=y
-CONFIG_CRITICAL_LATENCY_HIST=y
-CONFIG_LATENCY_HIST=y
-# CONFIG_LATENCY_TRACE is not set
+# CONFIG_CRITICAL_PREEMPT_TIMING is not set
+# CONFIG_CRITICAL_IRQSOFF_TIMING is not set
# CONFIG_DEBUG_KOBJECT is not set
CONFIG_DEBUG_INFO=y
# CONFIG_DEBUG_FS is not set

All the formatting is mine own, and I stripped some do-while (0)s.

void __put_task_struct(struct task_struct *task)
{
struct list_head *head;

head = &(*(
{

add_preempt_count(1);
__asm__ __volatile__("": : :"memory");

&(*(
{
unsigned long __ptr;
__asm__ ("" : "=r"(__ptr) :
"0"(&per_cpu__delayed_put_task_struct_list));
(typeof(&per_cpu__delayed_put_task_struct_list)) (__ptr + ((
{
typeof(((struct x8664_pda *)0)->data_offset) ret__;

switch ((sizeof(((struct x8664_pda *)0)->data_offset)))
{
case 2: asm volatile(BLORP_A); break; // it's all asm.
I have it, if you care
case 4: asm volatile(BLORP_B); break;
case 8: asm volatile(BLORP_C); break;
default: __bad_pda_field();
}

ret__;
}
)));
}));

}));

list_add_tail(&task->delayed_drop, head);

_wake_cpu_desched_task();

__asm__ __volatile__("": : :"memory");
sub_preempt_count(1);
__asm__ __volatile__("": : :"memory");

if (__builtin_expect(!!(test_ti_thread_flag(current_thread_info(), 3)), 0))
preempt_schedule();
}