Re: [patch] Real-Time Preemption, -RT-2.6.13-rc4-V0.7.52-01

Steven Rostedt
2005-08-02T19:45:53Z

On Tue, 2005-08-02 at 12:19 +0200, Ingo Molnar wrote:
> * Steven Rostedt <rostedt@goodmis.org> wrote:
>
> > In my custom kernel, I have a wchan field of the task that records
> > where the task calls something that might schedule. This way I can see
> > where things locked up if I don't have a back trace of the task. This
> > field is always zero when it switches to usermode. Something like
> > this can also be used to check how long the process is in kernel mode.
> > If a task is in the kernel for more than 10 seconds without sleeping,
> > that would definitely be a good indication of something wrong. I
> > probably could write something to check for this if people are
> > interested. I wont waste my time if nobody would want it.
>
> this would be a pretty useful extension of the softlockup checker!

Here it is (Finally). I just had to be patient with the kjournal
lockup. I had to wait some time before the lockup occurred, but when it
did, I got my message out:
--------------------------------------------
BUG: possible soft lockup detected on CPU#0! 1314840-1313839(1314839)
curr=kjournald:734 count=11
[<c010410f>] dump_stack+0x1f/0x30 (20)
[<c01441e0>] softlockup_tick+0x170/0x1a0 (44)
[<c0125d32>] update_process_times+0x62/0x140 (28)
[<c010861d>] timer_interrupt+0x4d/0x100 (20)
[<c014450f>] handle_IRQ_event+0x6f/0x120 (48)
[<c014469c>] __do_IRQ+0xdc/0x1a0 (48)
[<c0105abe>] do_IRQ+0x4e/0x90 (28)
[<c0103b67>] common_interrupt+0x1f/0x24 (112)
[<c01edc36>] journal_commit_transaction+0x1206/0x1430 (112)
[<c01f06d0>] kjournald+0xd0/0x1e0 (84)
[<c01011ed>] kernel_thread_helper+0x5/0x18 (825638940)
---------------------------
| preempt count: 20010003 ]
| 3-level deep critical section nesting:
----------------------------------------
.. [<c013d49a>] .... add_preempt_count+0x1a/0x20
.....[<c01085ec>] .. ( <= timer_interrupt+0x1c/0x100)
.. [<c013d49a>] .... add_preempt_count+0x1a/0x20
.....[<c014418d>] .. ( <= softlockup_tick+0x11d/0x1a0)
.. [<c013d49a>] .... add_preempt_count+0x1a/0x20
.....[<c013e727>] .. ( <= print_traces+0x17/0x50)

------------------------------
| showing all locks held by: | (kjournald/734 [c13e20b0, 69]):
------------------------------
-----------------------------------------------

This does NOT detect lockups in user space. If a RT user program gets
stuck in an infinite loop, it's their problem. This only detects lockups
in the kernel. I also don't determine a difference if a kernel is stuck
as a RT task or not, as long as it tries to sleep once in a while this
message wont appear. I'm not aware of any kernel thread that spins in
the kernel, so I don't think this will be a problem. (I forgot about
swapper and it was showing up, hence the check for current->pid :-).

Note this currently only works with i386. If other archs want this, they
need to modify the thread_info to include the softlockup_count, and then
upon returning to user space it needs to be reset. Then the
ARCH_HAS_SOFTLOCK_DETECT needs to be defined. This counter will be reset
at every time the kernel enters users space, so this includes the timer
interrupt.

-- Steve

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>

Index: linux_realtime_ernie/kernel/sched.c
===================================================================
--- linux_realtime_ernie/kernel/sched.c (revision 266)
+++ linux_realtime_ernie/kernel/sched.c (working copy)
@@ -3367,6 +3367,8 @@
send_sig(SIGUSR2, current, 1);
}
do {
+ if (current->state & ~TASK_RUNNING_MUTEX)
+ touch_light_softlockup_watchdog();
__schedule();
} while (unlikely(test_thread_flag(TIF_NEED_RESCHED) || test_thread_flag(TIF_NEED_RESCHED_DELAYED)));
raw_local_irq_enable(); // TODO: do sti; ret
Index: linux_realtime_ernie/kernel/softlockup.c
===================================================================
--- linux_realtime_ernie/kernel/softlockup.c (revision 269)
+++ linux_realtime_ernie/kernel/softlockup.c (working copy)
@@ -3,6 +3,10 @@
*
* started by Ingo Molnar, (C) 2005, Red Hat
*
+ * Steven Rostedt, Kihon Technologies Inc.
+ * Added light softlockup detection off of what Daniel Walker of
+ * MontaVista started.
+ *
* this code detects soft lockups: incidents in where on a CPU
* the kernel does not reschedule for 10 seconds or more.
*/
@@ -20,9 +24,7 @@
static DEFINE_PER_CPU(unsigned long, timeout) = INITIAL_JIFFIES;
static DEFINE_PER_CPU(unsigned long, timestamp) = INITIAL_JIFFIES;
static DEFINE_PER_CPU(unsigned long, print_timestamp) = INITIAL_JIFFIES;
-static DEFINE_PER_CPU(struct task_struct *, prev_task);
static DEFINE_PER_CPU(struct task_struct *, watchdog_task);
-static DEFINE_PER_CPU(unsigned long, task_counter);

static int did_panic = 0;
static int softlock_panic(struct notifier_block *this, unsigned long event,
@@ -59,25 +61,25 @@
if (!per_cpu(watchdog_task, this_cpu))
return;

- if (per_cpu(prev_task, this_cpu) != current ||
- !rt_task(current)) {
- per_cpu(prev_task, this_cpu) = current;
- per_cpu(task_counter, this_cpu) = 0;
- }
- else if ((++per_cpu(task_counter, this_cpu) > 10) && printk_ratelimit()) {
-
- spin_lock(&print_lock);
- printk(KERN_ERR "BUG: possible soft lockup detected on CPU#%u! %lu-%lu(%lu)\n",
- this_cpu, jiffies, timestamp, timeout);
- printk("curr=%s:%d\n",current->comm,current->pid);
-
- dump_stack();
+#ifdef ARCH_HAS_SOFTLOCKUP_DETECT
+ if (current->pid) {
+ unsigned long count;
+ count = task_softlockup_count(current);
+ if (++count > 10) {
+ spin_lock(&print_lock);
+ printk(KERN_ERR "BUG: possible soft lockup detected on CPU#%u! %lu-%lu(%lu)\n",
+ this_cpu, jiffies, timestamp, timeout);
+ printk("curr=%s:%d count=%ld\n",current->comm,current->pid,count);
+ dump_stack();
#if defined(__i386__) && defined(CONFIG_SMP)
- nmi_show_all_regs();
+ nmi_show_all_regs();
#endif
- spin_unlock(&print_lock);
- per_cpu(task_counter, this_cpu) = 0;
+ spin_unlock(&print_lock);
+ count = 0;
+ }
+ set_task_softlockup_count(current,count);
}
+#endif /* ARCH_HAS_SOFTLOCKUP_DETECT */

wake_up_process(per_cpu(watchdog_task, this_cpu));
per_cpu(timeout, this_cpu) = jiffies + msecs_to_jiffies(1000);
@@ -101,7 +103,6 @@
nmi_show_all_regs();
#endif
spin_unlock(&print_lock);
- per_cpu(task_counter, this_cpu) = 0;
}
}

Index: linux_realtime_ernie/include/asm-i386/thread_info.h
===================================================================
--- linux_realtime_ernie/include/asm-i386/thread_info.h (revision 266)
+++ linux_realtime_ernie/include/asm-i386/thread_info.h (working copy)
@@ -43,6 +43,13 @@
unsigned long previous_esp; /* ESP of the previous stack in case
of nested (IRQ) stacks
*/
+#ifdef CONFIG_DETECT_SOFTLOCKUP
+#define ARCH_HAS_SOFTLOCKUP_DETECT
+ unsigned long softlockup_count; /* Count to keep track how long the
+ thread is in the kernel without
+ sleeping.
+ */
+#endif
__u8 supervisor_stack[0];
};

Index: linux_realtime_ernie/include/linux/sched.h
===================================================================
--- linux_realtime_ernie/include/linux/sched.h (revision 266)
+++ linux_realtime_ernie/include/linux/sched.h (working copy)
@@ -1497,6 +1497,26 @@

#endif /* CONFIG_SMP */

+#ifdef ARCH_HAS_SOFTLOCKUP_DETECT
+static inline unsigned long task_softlockup_count(const struct task_struct *p)
+{
+ return p->thread_info->softlockup_count;
+}
+static inline void set_task_softlockup_count(const struct task_struct *p,
+ unsigned long count)
+{
+ p->thread_info->softlockup_count = count;
+}
+static inline void touch_light_softlockup_watchdog(void)
+{
+ set_task_softlockup_count(current, 0);
+}
+#else
+static inline void touch_light_softlockup_watchdog(void)
+{
+}
+#endif
+
#ifdef HAVE_ARCH_PICK_MMAP_LAYOUT
extern void arch_pick_mmap_layout(struct mm_struct *mm);
#else
Index: linux_realtime_ernie/arch/i386/kernel/asm-offsets.c
===================================================================
--- linux_realtime_ernie/arch/i386/kernel/asm-offsets.c (revision 266)
+++ linux_realtime_ernie/arch/i386/kernel/asm-offsets.c (working copy)
@@ -53,6 +53,9 @@
OFFSET(TI_preempt_count, thread_info, preempt_count);
OFFSET(TI_addr_limit, thread_info, addr_limit);
OFFSET(TI_restart_block, thread_info, restart_block);
+#ifdef CONFIG_DETECT_SOFTLOCKUP
+ OFFSET(TI_softlockup_count, thread_info, softlockup_count);
+#endif
BLANK();

OFFSET(EXEC_DOMAIN_handler, exec_domain, handler);
Index: linux_realtime_ernie/arch/i386/kernel/entry.S
===================================================================
--- linux_realtime_ernie/arch/i386/kernel/entry.S (revision 266)
+++ linux_realtime_ernie/arch/i386/kernel/entry.S (working copy)
@@ -155,6 +155,10 @@
andl $_TIF_WORK_MASK, %ecx # is there any work to be done on
# int/exception return?
jne work_pending
+#ifdef CONFIG_DETECT_SOFTLOCKUP
+ movl $0, TI_softlockup_count(%ebp) # Zero out the count when going
+ # back to userland
+#endif
jmp restore_all

#ifdef CONFIG_PREEMPT