Re: [PATCH] softlockup: fix problem with long kernel pauses from kgdb

[Yong Zhang]

On Tue, Aug 4, 2009 at 10:16 PM, Ingo Molnar <mingo@xxxxxxx> wrote:
>
> * Jason Wessel <jason.wessel@xxxxxxxxxxxxx> wrote:
>
>> Peter Zijlstra wrote:
>> > On Mon, 2009-07-27 at 15:03 -0500, Jason Wessel wrote:
>> >> The fix is to simply invoke sched_clock_tick() to update "cpu sched
>> >> clock" on exit from kgdb_handle_exception.
>> >
>> > Is that a regular IRQ context, or is that NMI context?
>> >
>> >> Signed-off-by: Dongdong Deng <Dongdong.Deng@xxxxxxxxxxxxx>
>> >> Signed-off-by: Jason Wessel <jason.wessel@xxxxxxxxxxxxx>
>> >> Cc: Ingo Molnar <mingo@xxxxxxx>
>> >> Cc: peterz@xxxxxxxxxxxxx
>> >> ---
>> >> Âkernel/softlockup.c | Â Â3 +++
>> >> Â1 file changed, 3 insertions(+)
>> >>
>> >> --- a/kernel/softlockup.c
>> >> +++ b/kernel/softlockup.c
>> >> @@ -118,6 +118,9 @@ void softlockup_tick(void)
>> >> Â Â Â Â }
>> >>
>> >> Â Â Â Â if (touch_timestamp == 0) {
>> >> + Â Â Â Â Â Â Â /* If the time stamp was touched externally make sure the
>> >> + Â Â Â Â Â Â Â Â* scheduler tick is up to date as well */
>> >> + Â Â Â Â Â Â Â sched_clock_tick();
>> >> Â Â Â Â Â Â Â Â __touch_softlockup_watchdog();
>> >> Â Â Â Â Â Â Â Â return;
>> >> Â Â Â Â }
>> >>
>> >
>> > Aside from the funny comment style (please fix) the fix does look
>> > sensible.
>>
>> It turns out that further testing of this patch shows a regression in
>> the ability to detect certain lockups. ÂIt is a direct result of the
>> way the scheduling code makes use of the touch_softlockup_watchdog().
>> With the above proposed patch the tick was getting updated after a
>> resume, but was also getting updated with the run_timers(), and if
>> that happened before the softlockup tick, no softlockup would get
>> reported (note that I was using some test code to induce softlockups).
>>
>> The patch below is a bit more invasive but solves the problem by
>> allowing kgdb to request that the sched cpu clock is updated only when
>> returning from a state where we know we need to force the update.
>>
>> Would this change be an acceptable solution to allow kgdb to
>> peacefully exist with the softlockup code?
>>
>> Thanks,
>> Jason.
>>
>>
>> -----
>> From: Jason Wessel <jason.wessel@xxxxxxxxxxxxx>
>> Subject: [PATCH] softlockup: add sched_clock_tick() to avoid kernel warning on kgdb resume
>>
>> When CONFIG_HAVE_UNSTABLE_SCHED_CLOCK is set sched_clock() gets the
>> time from hardware, such as from TSC. ÂIn this configuration kgdb will
>> report a softlock warning messages on resuming or detaching from a
>> debug session.
>>
>> Sequence of events in the problem case:
>>
>> 1) "cpu sched clock" and "hardware time" are at 100 sec prior
>> Â Âto a call to kgdb_handle_exception()
>>
>> 2) Debugger waits in kgdb_handle_exception() for 80 sec and on exit
>> Â Âthe following is called ... Âtouch_softlockup_watchdog() -->
>> Â Â__raw_get_cpu_var(touch_timestamp) = 0;
>>
>> 3) "cpu sched clock" = 100s (it was not updated, because the interrupt
>> Â Âwas disabled in kgdb) but the "hardware time" = 180 sec
>>
>> 4) The first timer interrupt after resuming from kgdb_handle_exception
>> Â Âupdates the watchdog from the "cpu sched clock"
>>
>> update_process_times() { ... Ârun_local_timers() --> softlockup_tick()
>> --> check (touch_timestamp == 0) (it is "YES" here, we have set
>> "touch_timestamp = 0" at kgdb) --> __touch_softlockup_watchdog()
>> ***(A)--> reset "touch_timestamp" to "get_timestamp()" (Here, the
>> "touch_timestamp" will still be set to 100s.) Â...
>>
>> Â Â scheduler_tick() ***(B)--> sched_clock_tick() (update "cpu sched
>> Â Â clock" to "hardware time" = 180s) ... Â}
>>
>> 5) The Second timer interrupt handler appears to have a large jump and
>> Â Âtrips the softlockup warning.
>>
>> update_process_times() { ... Ârun_local_timers() --> softlockup_tick()
>> --> "cpu sched clock" - "touch_timestamp" = 180s-100s > 60s --> printk
>> "soft lockup error messages" ... Â}
>>
>> note: ***(A) reset "touch_timestamp" to "get_timestamp(this_cpu)"
>>
>> Why "touch_timestamp" is 100 sec, instead of 180 sec?
>>
>> With the CONFIG_HAVE_UNSTABLE_SCHED_CLOCK" set the call trace of
>> get_timestamp() is:
>>
>> get_timestamp(this_cpu) -->cpu_clock(this_cpu)
>> -->sched_clock_cpu(this_cpu) -->__update_sched_clock(sched_clock_data,
>> now)
>>
>> The __update_sched_clock() function uses the GTOD tick value to create
>> a window to normalize the "now" values. ÂSo if "now" values is too big
>> for sched_clock_data, it will be ignored.
>>
>> The fix is to invoke sched_clock_tick() to update "cpu sched clock" in
>> order to recover from this state. ÂThis is done by introducing the
>> function touch_softlockup_watchdog_sync(), which allows kgdb to
>> request that the sched clock is updated when the watchdog thread runs
>> the first time after a resume from kgdb.
>>
>> Signed-off-by: Jason Wessel <jason.wessel@xxxxxxxxxxxxx>
>> Signed-off-by: Dongdong Deng <Dongdong.Deng@xxxxxxxxxxxxx>
>> Cc: Ingo Molnar <mingo@xxxxxxx>
>> Cc: peterz@xxxxxxxxxxxxx
>>
>> ---
>> Âinclude/linux/sched.h | Â Â4 ++++
>> Âkernel/kgdb.c     |  Â6 +++---
>> Âkernel/softlockup.c  |  16 ++++++++++++++++
>> Â3 files changed, 23 insertions(+), 3 deletions(-)
>>
>> --- a/kernel/softlockup.c
>> +++ b/kernel/softlockup.c
>> @@ -79,6 +79,14 @@ void touch_softlockup_watchdog(void)
>> Â}
>> ÂEXPORT_SYMBOL(touch_softlockup_watchdog);
>>
>> +static int softlock_touch_sync[NR_CPUS];
>> +
>> +void touch_softlockup_watchdog_sync(void)
>> +{
>> + Â Â softlock_touch_sync[raw_smp_processor_id()] = 1;
>> + Â Â __raw_get_cpu_var(touch_timestamp) = 0;
>> +}
>> +
>> Âvoid touch_all_softlockup_watchdogs(void)
>> Â{
>> Â Â Â int cpu;
>> @@ -118,6 +126,14 @@ void softlockup_tick(void)
>> Â Â Â }
>>
>> Â Â Â if (touch_timestamp == 0) {
>> + Â Â Â Â Â Â if (unlikely(softlock_touch_sync[this_cpu])) {
>> + Â Â Â Â Â Â Â Â Â Â /*
>> + Â Â Â Â Â Â Â Â Â Â Â* If the time stamp was touched atomically
>> + Â Â Â Â Â Â Â Â Â Â Â* make sure the scheduler tick is up to date.
>> + Â Â Â Â Â Â Â Â Â Â Â*/
>> + Â Â Â Â Â Â Â Â Â Â softlock_touch_sync[this_cpu] = 0;
>> + Â Â Â Â Â Â Â Â Â Â sched_clock_tick();
>> + Â Â Â Â Â Â }
>
> Hm, this looks quite ugly. Peter, Thomas, can you think of a cleaner
> solution?
>

We need not to sync up sched_clock in softlockup_tick, it can just return
and sync up the timestamp in the next tick. This will not touch what should
be done by dynticks, scheduler time and so on and keep softlockup_tick
clean.

I have rewrote the patch based on above, please check the attachment.

Thanks,
Yong

> Â Â Â ÂIngo
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@xxxxxxxxxxxxxxx
> More majordomo info at Âhttp://vger.kernel.org/majordomo-info.html
> Please read the FAQ at Âhttp://www.tux.org/lkml/
>
From 1821356596bdd28dfc69f708a6929394da351001 Mon Sep 17 00:00:00 2001
From: Yong Zhang <yong.zhang0@xxxxxxxxx>
Date: Sat, 26 Sep 2009 10:37:14 +0800
Subject: [PATCH] softlockup: introduce touch_softlockup_watchdog_sync()

In case of system halted for a long time, system will
do time sync up in the first incoming tick. But if we
also touch softlockup_tick timestamp at the same time,
softlockup_tick could keep a old timestamp and
this will lead annoying softlockup warning.
So move softlockup syncing it's timestamp to the next
tick.

Signed-off-by: Jason Wessel <jason.wessel@xxxxxxxxxxxxx>
Signed-off-by: Dongdong Deng <Dongdong.Deng@xxxxxxxxxxxxx>
Cc: Ingo Molnar <mingo@xxxxxxx>
Cc: Peter Zijlstra <peterz@xxxxxxxxxxxxx>
LKML-Reference: <http://lkml.org/lkml/2009/7/27/317>
Signed-off-by: Yong Zhang <yong.zhang0@xxxxxxxxx>
---
 include/linux/sched.h |    4 ++++
 kernel/softlockup.c   |   18 ++++++++++++++++++
 2 files changed, 22 insertions(+), 0 deletions(-)

diff --git a/include/linux/sched.h b/include/linux/sched.h
index 75e6e60..1aa4574 100644
--- a/include/linux/sched.h
+++ b/include/linux/sched.h
@@ -307,6 +307,7 @@ extern void sched_show_task(struct task_struct *p);
 #ifdef CONFIG_DETECT_SOFTLOCKUP
 extern void softlockup_tick(void);
 extern void touch_softlockup_watchdog(void);
+extern void touch_softlockup_watchdog_sync(void);
 extern void touch_all_softlockup_watchdogs(void);
 extern int proc_dosoftlockup_thresh(struct ctl_table *table, int write,
 				    void __user *buffer,
@@ -320,6 +321,9 @@ static inline void softlockup_tick(void)
 static inline void touch_softlockup_watchdog(void)
 {
 }
+static inline void touch_softlockup_watchdog_sync(void)
+{
+}
 static inline void touch_all_softlockup_watchdogs(void)
 {
 }
diff --git a/kernel/softlockup.c b/kernel/softlockup.c
index 81324d1..628d531 100644
--- a/kernel/softlockup.c
+++ b/kernel/softlockup.c
@@ -25,6 +25,7 @@ static DEFINE_SPINLOCK(print_lock);
 static DEFINE_PER_CPU(unsigned long, touch_timestamp);
 static DEFINE_PER_CPU(unsigned long, print_timestamp);
 static DEFINE_PER_CPU(struct task_struct *, watchdog_task);
+static DEFINE_PER_CPU(bool, softlock_touch_sync);
 
 static int __read_mostly did_panic;
 int __read_mostly softlockup_thresh = 60;
@@ -79,6 +80,13 @@ void touch_softlockup_watchdog(void)
 }
 EXPORT_SYMBOL(touch_softlockup_watchdog);
 
+void touch_softlockup_watchdog_sync(void)
+{
+	__raw_get_cpu_var(touch_timestamp) = 0;
+	__raw_get_cpu_var(softlock_touch_sync) = true;
+}
+EXPORT_SYMBOL(touch_softlockup_watchdog_sync);
+
 void touch_all_softlockup_watchdogs(void)
 {
 	int cpu;
@@ -117,6 +125,15 @@ void softlockup_tick(void)
 		return;
 	}
 
+	/*
+	 * If the scheduler tick is not up to date. Skip this check
+	 * and wait for the timestamp to to synced in the next tick
+	 */
+	if (unlikely(per_cpu(softlock_touch_sync, this_cpu))) {
+		per_cpu(softlock_touch_sync, this_cpu) = false;
+		return;
+	}
+
 	if (touch_timestamp == 0) {
 		__touch_softlockup_watchdog();
 		return;
@@ -216,6 +233,7 @@ cpu_callback(struct notifier_block *nfb, unsigned long action, void *hcpu)
 			return NOTIFY_BAD;
 		}
 		per_cpu(touch_timestamp, hotcpu) = 0;
+		per_cpu(softlock_touch_sync, hotcpu) = false;
 		per_cpu(watchdog_task, hotcpu) = p;
 		kthread_bind(p, hotcpu);
 		break;
-- 
1.6.0.4