Re: kernel deadlock

From: Gerlando Falauto
Date: Tue Sep 03 2013 - 10:58:02 EST

Hi,

I tried again from scratch, so let me recap the whole situation, so we can all view it from the same standpoint. This should make the problem easier to see and reproduce.

I can confirm that running a stock 3.10 kernel with HRTICK enabled:

diff --git a/kernel/sched/features.h b/kernel/sched/features.h
index 99399f8..294e3ca 100644
--- a/kernel/sched/features.h
+++ b/kernel/sched/features.h
@@ -41,7 +41,7 @@ SCHED_FEAT(WAKEUP_PREEMPTION, true)
*/
SCHED_FEAT(ARCH_POWER, true)

-SCHED_FEAT(HRTICK, false)
+SCHED_FEAT(HRTICK, true)
SCHED_FEAT(DOUBLE_TICK, false)
SCHED_FEAT(LB_BIAS, true)

makes the following program (and the whole board, as a matter of fact) hang with no further notice:

#include <stdio.h>
#include <sys/timex.h>

int main(void)
{
int i;

for (i = 0 ; ; i++) {
struct timex adj = {};
printf("%d\r", i);
fflush(stdout);
adjtimex(&adj);
}
return 0;
}

If I then revert everything up to (and including) the offending commit
(mind the '~'):

$ git log --oneline ...06c017f~ -- kernel/time/timekeeping.c kernel/time/ntp.c | cut -f1 -d' ' | xargs git revert

The problem disappears.

If I then cherry-pick again the offending commit:

$ git cherry-pick 06c017f; git log -1

commit 06c017fdd4dc48451a29ac37fc1db4a3f86b7f40
Author: John Stultz <john.stultz@xxxxxxxxxx>
Date: Fri Mar 22 11:37:28 2013 -0700

timekeeping: Hold timekeepering locks in do_adjtimex and hardpps

In moving the NTP state to be protected by the timekeeping locks,
be sure to acquire the timekeeping locks prior to calling
ntp functions.

Cc: Thomas Gleixner <tglx@xxxxxxxxxxxxx>
Cc: Richard Cochran <richardcochran@xxxxxxxxx>
Cc: Prarit Bhargava <prarit@xxxxxxxxxx>
Signed-off-by: John Stultz <john.stultz@xxxxxxxxxx>

I get the following deadlock report:

================================ cut ===============================

=================================
[ INFO: inconsistent lock state ]
3.10.0-00018-gd915798 #3 Not tainted
---------------------------------
inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
a.out/574 [HC0[0]:SC0[0]:HE1:SE1] takes:
(timekeeper_lock){?.-...}, at: [<c0049d00>] do_adjtimex+0x94/0xf4
{IN-HARDIRQ-W} state was registered at:
[<c00548fc>] __lock_acquire+0xabc/0x1bb8
[<c0055ffc>] lock_acquire+0xa8/0x15c
[<c0432c1c>] _raw_spin_lock_irqsave+0x50/0x64
[<c0049090>] do_timer+0x2c/0xa54
[<c004dfa8>] tick_periodic+0x74/0x9c
[<c004dfe8>] tick_handle_periodic+0x18/0x7c
[<c0012da8>] orion_timer_interrupt+0x24/0x34
[<c00693b8>] handle_irq_event_percpu+0x5c/0x300
[<c0069698>] handle_irq_event+0x3c/0x5c
[<c006b920>] handle_level_irq+0x8c/0xe8
[<c0068d30>] generic_handle_irq+0x28/0x44
[<c000951c>] handle_IRQ+0x30/0x84
[<c04338b8>] __irq_svc+0x38/0xa0
[<c0617824>] calibrate_delay+0x350/0x4e4
[<c05e26e0>] start_kernel+0x23c/0x2c4
[<0000803c>] 0x803c
irq event stamp: 2840
hardirqs last enabled at (2839): [<c0008ccc>] no_work_pending+0x8/0x28
hardirqs last disabled at (2840): [<c0432bec>] _raw_spin_lock_irqsave+0x20/0x64
softirqs last enabled at (2098): [<c039e908>] rpc_wake_up_first+0x6c/0x15c
softirqs last disabled at (2096): [<c0432e58>] _raw_spin_lock_bh+0x14/0x54

other info that might help us debug this:
Possible unsafe locking scenario:

CPU0
----
lock(timekeeper_lock);
<Interrupt>
lock(timekeeper_lock);

*** DEADLOCK ***

1 lock held by a.out/574:
#0: (timekeeper_lock){?.-...}, at: [<c0049d00>] do_adjtimex+0x94/0xf4

stack backtrace:
CPU: 0 PID: 574 Comm: a.out Not tainted 3.10.0-00018-gd915798 #3
[<c000d67c>] (unwind_backtrace+0x0/0xf0) from [<c000b530>] (show_stack+0x10/0x14)
[<c000b530>] (show_stack+0x10/0x14) from [<c042c274>] (print_usage_bug.part.27+0x218/0x280)
[<c042c274>] (print_usage_bug.part.27+0x218/0x280) from [<c005281c>] (mark_lock+0x538/0x6bc)
[<c005281c>] (mark_lock+0x538/0x6bc) from [<c0052a30>] (mark_held_locks+0x90/0x124)
[<c0052a30>] (mark_held_locks+0x90/0x124) from [<c0052b6c>] (trace_hardirqs_on_caller+0xa8/0x23c)
[<c0052b6c>] (trace_hardirqs_on_caller+0xa8/0x23c) from [<c0433390>] (_raw_spin_unlock_irq+0x24/0x5c)
[<c0433390>] (_raw_spin_unlock_irq+0x24/0x5c) from [<c004a490>] (__do_adjtimex+0xf0/0x580)
[<c004a490>] (__do_adjtimex+0xf0/0x580) from [<c0049d20>] (do_adjtimex+0xb4/0xf4)
[<c0049d20>] (do_adjtimex+0xb4/0xf4) from [<c001cf38>] (SyS_adjtimex+0x50/0xa8)
[<c001cf38>] (SyS_adjtimex+0x50/0xa8) from [<c0008c40>] (ret_fast_syscall+0x0/0x44)

================================ cut ===============================

And as soon as I also cherry-pick (notice there is another commit in between, which seems not to be relevant on this matter):

$ git cherry-pick a076b2146fabb0894cae5e0189a8ba3f1502d737; git show

commit a076b2146fabb0894cae5e0189a8ba3f1502d737
Author: John Stultz <john.stultz@xxxxxxxxxx>
Date: Fri Mar 22 11:52:03 2013 -0700

ntp: Remove ntp_lock, using the timekeeping locks to protect ntp state

In order to properly handle the NTP state in future changes to the
timekeeping lock management, this patch moves the management of
all of the ntp state under the timekeeping locks.

This allows us to remove the ntp_lock.

Cc: Thomas Gleixner <tglx@xxxxxxxxxxxxx>
Cc: Richard Cochran <richardcochran@xxxxxxxxx>
Cc: Prarit Bhargava <prarit@xxxxxxxxxx>
Signed-off-by: John Stultz <john.stultz@xxxxxxxxxx>


I end up in the situation where the system hangs completely and NO deadlock report whatsoever is output.

So it looks like 06c017fdd4dc48451a29ac37fc1db4a3f86b7f40 introduces the deadlock, while a076b2146fabb0894cae5e0189a8ba3f1502d737 cares to hide the report.

Notice how I tested the above on an ARM board; on PowerPC I get similar results, although I am not able to see the deadlock report under any circumstances (enabling CONFIG_PROVE_LOCKING, which is the flag that triggers the deadlock report, causes the kernel to hang at startup even on a vanilla 3.10 kernel).

John, could you please confirm whether you're at least able to reproduce it somehow?

Thank you,
Gerlando
--
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/