]>
Commit | Line | Data |
---|---|---|
d4cb193b GKH |
1 | From 504d58745c9ca28d33572e2d8a9990b43e06075d Mon Sep 17 00:00:00 2001 |
2 | From: Jan Kara <jack@suse.cz> | |
3 | Date: Fri, 1 Aug 2014 12:20:02 +0200 | |
4 | Subject: timer: Fix lock inversion between hrtimer_bases.lock and scheduler locks | |
5 | ||
6 | From: Jan Kara <jack@suse.cz> | |
7 | ||
8 | commit 504d58745c9ca28d33572e2d8a9990b43e06075d upstream. | |
9 | ||
10 | clockevents_increase_min_delta() calls printk() from under | |
11 | hrtimer_bases.lock. That causes lock inversion on scheduler locks because | |
12 | printk() can call into the scheduler. Lockdep puts it as: | |
13 | ||
14 | ====================================================== | |
15 | [ INFO: possible circular locking dependency detected ] | |
16 | 3.15.0-rc8-06195-g939f04b #2 Not tainted | |
17 | ------------------------------------------------------- | |
18 | trinity-main/74 is trying to acquire lock: | |
19 | (&port_lock_key){-.....}, at: [<811c60be>] serial8250_console_write+0x8c/0x10c | |
20 | ||
21 | but task is already holding lock: | |
22 | (hrtimer_bases.lock){-.-...}, at: [<8103caeb>] hrtimer_try_to_cancel+0x13/0x66 | |
23 | ||
24 | which lock already depends on the new lock. | |
25 | ||
26 | the existing dependency chain (in reverse order) is: | |
27 | ||
28 | -> #5 (hrtimer_bases.lock){-.-...}: | |
29 | [<8104a942>] lock_acquire+0x92/0x101 | |
30 | [<8142f11d>] _raw_spin_lock_irqsave+0x2e/0x3e | |
31 | [<8103c918>] __hrtimer_start_range_ns+0x1c/0x197 | |
32 | [<8107ec20>] perf_swevent_start_hrtimer.part.41+0x7a/0x85 | |
33 | [<81080792>] task_clock_event_start+0x3a/0x3f | |
34 | [<810807a4>] task_clock_event_add+0xd/0x14 | |
35 | [<8108259a>] event_sched_in+0xb6/0x17a | |
36 | [<810826a2>] group_sched_in+0x44/0x122 | |
37 | [<81082885>] ctx_sched_in.isra.67+0x105/0x11f | |
38 | [<810828e6>] perf_event_sched_in.isra.70+0x47/0x4b | |
39 | [<81082bf6>] __perf_install_in_context+0x8b/0xa3 | |
40 | [<8107eb8e>] remote_function+0x12/0x2a | |
41 | [<8105f5af>] smp_call_function_single+0x2d/0x53 | |
42 | [<8107e17d>] task_function_call+0x30/0x36 | |
43 | [<8107fb82>] perf_install_in_context+0x87/0xbb | |
44 | [<810852c9>] SYSC_perf_event_open+0x5c6/0x701 | |
45 | [<810856f9>] SyS_perf_event_open+0x17/0x19 | |
46 | [<8142f8ee>] syscall_call+0x7/0xb | |
47 | ||
48 | -> #4 (&ctx->lock){......}: | |
49 | [<8104a942>] lock_acquire+0x92/0x101 | |
50 | [<8142f04c>] _raw_spin_lock+0x21/0x30 | |
51 | [<81081df3>] __perf_event_task_sched_out+0x1dc/0x34f | |
52 | [<8142cacc>] __schedule+0x4c6/0x4cb | |
53 | [<8142cae0>] schedule+0xf/0x11 | |
54 | [<8142f9a6>] work_resched+0x5/0x30 | |
55 | ||
56 | -> #3 (&rq->lock){-.-.-.}: | |
57 | [<8104a942>] lock_acquire+0x92/0x101 | |
58 | [<8142f04c>] _raw_spin_lock+0x21/0x30 | |
59 | [<81040873>] __task_rq_lock+0x33/0x3a | |
60 | [<8104184c>] wake_up_new_task+0x25/0xc2 | |
61 | [<8102474b>] do_fork+0x15c/0x2a0 | |
62 | [<810248a9>] kernel_thread+0x1a/0x1f | |
63 | [<814232a2>] rest_init+0x1a/0x10e | |
64 | [<817af949>] start_kernel+0x303/0x308 | |
65 | [<817af2ab>] i386_start_kernel+0x79/0x7d | |
66 | ||
67 | -> #2 (&p->pi_lock){-.-...}: | |
68 | [<8104a942>] lock_acquire+0x92/0x101 | |
69 | [<8142f11d>] _raw_spin_lock_irqsave+0x2e/0x3e | |
70 | [<810413dd>] try_to_wake_up+0x1d/0xd6 | |
71 | [<810414cd>] default_wake_function+0xb/0xd | |
72 | [<810461f3>] __wake_up_common+0x39/0x59 | |
73 | [<81046346>] __wake_up+0x29/0x3b | |
74 | [<811b8733>] tty_wakeup+0x49/0x51 | |
75 | [<811c3568>] uart_write_wakeup+0x17/0x19 | |
76 | [<811c5dc1>] serial8250_tx_chars+0xbc/0xfb | |
77 | [<811c5f28>] serial8250_handle_irq+0x54/0x6a | |
78 | [<811c5f57>] serial8250_default_handle_irq+0x19/0x1c | |
79 | [<811c56d8>] serial8250_interrupt+0x38/0x9e | |
80 | [<810510e7>] handle_irq_event_percpu+0x5f/0x1e2 | |
81 | [<81051296>] handle_irq_event+0x2c/0x43 | |
82 | [<81052cee>] handle_level_irq+0x57/0x80 | |
83 | [<81002a72>] handle_irq+0x46/0x5c | |
84 | [<810027df>] do_IRQ+0x32/0x89 | |
85 | [<8143036e>] common_interrupt+0x2e/0x33 | |
86 | [<8142f23c>] _raw_spin_unlock_irqrestore+0x3f/0x49 | |
87 | [<811c25a4>] uart_start+0x2d/0x32 | |
88 | [<811c2c04>] uart_write+0xc7/0xd6 | |
89 | [<811bc6f6>] n_tty_write+0xb8/0x35e | |
90 | [<811b9beb>] tty_write+0x163/0x1e4 | |
91 | [<811b9cd9>] redirected_tty_write+0x6d/0x75 | |
92 | [<810b6ed6>] vfs_write+0x75/0xb0 | |
93 | [<810b7265>] SyS_write+0x44/0x77 | |
94 | [<8142f8ee>] syscall_call+0x7/0xb | |
95 | ||
96 | -> #1 (&tty->write_wait){-.....}: | |
97 | [<8104a942>] lock_acquire+0x92/0x101 | |
98 | [<8142f11d>] _raw_spin_lock_irqsave+0x2e/0x3e | |
99 | [<81046332>] __wake_up+0x15/0x3b | |
100 | [<811b8733>] tty_wakeup+0x49/0x51 | |
101 | [<811c3568>] uart_write_wakeup+0x17/0x19 | |
102 | [<811c5dc1>] serial8250_tx_chars+0xbc/0xfb | |
103 | [<811c5f28>] serial8250_handle_irq+0x54/0x6a | |
104 | [<811c5f57>] serial8250_default_handle_irq+0x19/0x1c | |
105 | [<811c56d8>] serial8250_interrupt+0x38/0x9e | |
106 | [<810510e7>] handle_irq_event_percpu+0x5f/0x1e2 | |
107 | [<81051296>] handle_irq_event+0x2c/0x43 | |
108 | [<81052cee>] handle_level_irq+0x57/0x80 | |
109 | [<81002a72>] handle_irq+0x46/0x5c | |
110 | [<810027df>] do_IRQ+0x32/0x89 | |
111 | [<8143036e>] common_interrupt+0x2e/0x33 | |
112 | [<8142f23c>] _raw_spin_unlock_irqrestore+0x3f/0x49 | |
113 | [<811c25a4>] uart_start+0x2d/0x32 | |
114 | [<811c2c04>] uart_write+0xc7/0xd6 | |
115 | [<811bc6f6>] n_tty_write+0xb8/0x35e | |
116 | [<811b9beb>] tty_write+0x163/0x1e4 | |
117 | [<811b9cd9>] redirected_tty_write+0x6d/0x75 | |
118 | [<810b6ed6>] vfs_write+0x75/0xb0 | |
119 | [<810b7265>] SyS_write+0x44/0x77 | |
120 | [<8142f8ee>] syscall_call+0x7/0xb | |
121 | ||
122 | -> #0 (&port_lock_key){-.....}: | |
123 | [<8104a62d>] __lock_acquire+0x9ea/0xc6d | |
124 | [<8104a942>] lock_acquire+0x92/0x101 | |
125 | [<8142f11d>] _raw_spin_lock_irqsave+0x2e/0x3e | |
126 | [<811c60be>] serial8250_console_write+0x8c/0x10c | |
127 | [<8104e402>] call_console_drivers.constprop.31+0x87/0x118 | |
128 | [<8104f5d5>] console_unlock+0x1d7/0x398 | |
129 | [<8104fb70>] vprintk_emit+0x3da/0x3e4 | |
130 | [<81425f76>] printk+0x17/0x19 | |
131 | [<8105bfa0>] clockevents_program_min_delta+0x104/0x116 | |
132 | [<8105c548>] clockevents_program_event+0xe7/0xf3 | |
133 | [<8105cc1c>] tick_program_event+0x1e/0x23 | |
134 | [<8103c43c>] hrtimer_force_reprogram+0x88/0x8f | |
135 | [<8103c49e>] __remove_hrtimer+0x5b/0x79 | |
136 | [<8103cb21>] hrtimer_try_to_cancel+0x49/0x66 | |
137 | [<8103cb4b>] hrtimer_cancel+0xd/0x18 | |
138 | [<8107f102>] perf_swevent_cancel_hrtimer.part.60+0x2b/0x30 | |
139 | [<81080705>] task_clock_event_stop+0x20/0x64 | |
140 | [<81080756>] task_clock_event_del+0xd/0xf | |
141 | [<81081350>] event_sched_out+0xab/0x11e | |
142 | [<810813e0>] group_sched_out+0x1d/0x66 | |
143 | [<81081682>] ctx_sched_out+0xaf/0xbf | |
144 | [<81081e04>] __perf_event_task_sched_out+0x1ed/0x34f | |
145 | [<8142cacc>] __schedule+0x4c6/0x4cb | |
146 | [<8142cae0>] schedule+0xf/0x11 | |
147 | [<8142f9a6>] work_resched+0x5/0x30 | |
148 | ||
149 | other info that might help us debug this: | |
150 | ||
151 | Chain exists of: | |
152 | &port_lock_key --> &ctx->lock --> hrtimer_bases.lock | |
153 | ||
154 | Possible unsafe locking scenario: | |
155 | ||
156 | CPU0 CPU1 | |
157 | ---- ---- | |
158 | lock(hrtimer_bases.lock); | |
159 | lock(&ctx->lock); | |
160 | lock(hrtimer_bases.lock); | |
161 | lock(&port_lock_key); | |
162 | ||
163 | *** DEADLOCK *** | |
164 | ||
165 | 4 locks held by trinity-main/74: | |
166 | #0: (&rq->lock){-.-.-.}, at: [<8142c6f3>] __schedule+0xed/0x4cb | |
167 | #1: (&ctx->lock){......}, at: [<81081df3>] __perf_event_task_sched_out+0x1dc/0x34f | |
168 | #2: (hrtimer_bases.lock){-.-...}, at: [<8103caeb>] hrtimer_try_to_cancel+0x13/0x66 | |
169 | #3: (console_lock){+.+...}, at: [<8104fb5d>] vprintk_emit+0x3c7/0x3e4 | |
170 | ||
171 | stack backtrace: | |
172 | CPU: 0 PID: 74 Comm: trinity-main Not tainted 3.15.0-rc8-06195-g939f04b #2 | |
173 | 00000000 81c3a310 8b995c14 81426f69 8b995c44 81425a99 8161f671 8161f570 | |
174 | 8161f538 8161f559 8161f538 8b995c78 8b142bb0 00000004 8b142fdc 8b142bb0 | |
175 | 8b995ca8 8104a62d 8b142fac 000016f2 81c3a310 00000001 00000001 00000003 | |
176 | Call Trace: | |
177 | [<81426f69>] dump_stack+0x16/0x18 | |
178 | [<81425a99>] print_circular_bug+0x18f/0x19c | |
179 | [<8104a62d>] __lock_acquire+0x9ea/0xc6d | |
180 | [<8104a942>] lock_acquire+0x92/0x101 | |
181 | [<811c60be>] ? serial8250_console_write+0x8c/0x10c | |
182 | [<811c6032>] ? wait_for_xmitr+0x76/0x76 | |
183 | [<8142f11d>] _raw_spin_lock_irqsave+0x2e/0x3e | |
184 | [<811c60be>] ? serial8250_console_write+0x8c/0x10c | |
185 | [<811c60be>] serial8250_console_write+0x8c/0x10c | |
186 | [<8104af87>] ? lock_release+0x191/0x223 | |
187 | [<811c6032>] ? wait_for_xmitr+0x76/0x76 | |
188 | [<8104e402>] call_console_drivers.constprop.31+0x87/0x118 | |
189 | [<8104f5d5>] console_unlock+0x1d7/0x398 | |
190 | [<8104fb70>] vprintk_emit+0x3da/0x3e4 | |
191 | [<81425f76>] printk+0x17/0x19 | |
192 | [<8105bfa0>] clockevents_program_min_delta+0x104/0x116 | |
193 | [<8105cc1c>] tick_program_event+0x1e/0x23 | |
194 | [<8103c43c>] hrtimer_force_reprogram+0x88/0x8f | |
195 | [<8103c49e>] __remove_hrtimer+0x5b/0x79 | |
196 | [<8103cb21>] hrtimer_try_to_cancel+0x49/0x66 | |
197 | [<8103cb4b>] hrtimer_cancel+0xd/0x18 | |
198 | [<8107f102>] perf_swevent_cancel_hrtimer.part.60+0x2b/0x30 | |
199 | [<81080705>] task_clock_event_stop+0x20/0x64 | |
200 | [<81080756>] task_clock_event_del+0xd/0xf | |
201 | [<81081350>] event_sched_out+0xab/0x11e | |
202 | [<810813e0>] group_sched_out+0x1d/0x66 | |
203 | [<81081682>] ctx_sched_out+0xaf/0xbf | |
204 | [<81081e04>] __perf_event_task_sched_out+0x1ed/0x34f | |
205 | [<8104416d>] ? __dequeue_entity+0x23/0x27 | |
206 | [<81044505>] ? pick_next_task_fair+0xb1/0x120 | |
207 | [<8142cacc>] __schedule+0x4c6/0x4cb | |
208 | [<81047574>] ? trace_hardirqs_off_caller+0xd7/0x108 | |
209 | [<810475b0>] ? trace_hardirqs_off+0xb/0xd | |
210 | [<81056346>] ? rcu_irq_exit+0x64/0x77 | |
211 | ||
212 | Fix the problem by using printk_deferred() which does not call into the | |
213 | scheduler. | |
214 | ||
215 | Reported-by: Fengguang Wu <fengguang.wu@intel.com> | |
216 | Signed-off-by: Jan Kara <jack@suse.cz> | |
217 | Signed-off-by: Thomas Gleixner <tglx@linutronix.de> | |
218 | Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org> | |
219 | ||
220 | --- | |
221 | kernel/time/clockevents.c | 10 ++++++---- | |
222 | 1 file changed, 6 insertions(+), 4 deletions(-) | |
223 | ||
224 | --- a/kernel/time/clockevents.c | |
225 | +++ b/kernel/time/clockevents.c | |
226 | @@ -146,7 +146,8 @@ static int clockevents_increase_min_delt | |
227 | { | |
228 | /* Nothing to do if we already reached the limit */ | |
229 | if (dev->min_delta_ns >= MIN_DELTA_LIMIT) { | |
230 | - printk(KERN_WARNING "CE: Reprogramming failure. Giving up\n"); | |
231 | + printk_deferred(KERN_WARNING | |
232 | + "CE: Reprogramming failure. Giving up\n"); | |
233 | dev->next_event.tv64 = KTIME_MAX; | |
234 | return -ETIME; | |
235 | } | |
236 | @@ -159,9 +160,10 @@ static int clockevents_increase_min_delt | |
237 | if (dev->min_delta_ns > MIN_DELTA_LIMIT) | |
238 | dev->min_delta_ns = MIN_DELTA_LIMIT; | |
239 | ||
240 | - printk(KERN_WARNING "CE: %s increased min_delta_ns to %llu nsec\n", | |
241 | - dev->name ? dev->name : "?", | |
242 | - (unsigned long long) dev->min_delta_ns); | |
243 | + printk_deferred(KERN_WARNING | |
244 | + "CE: %s increased min_delta_ns to %llu nsec\n", | |
245 | + dev->name ? dev->name : "?", | |
246 | + (unsigned long long) dev->min_delta_ns); | |
247 | return 0; | |
248 | } | |
249 |