-
Notifications
You must be signed in to change notification settings - Fork 11
Expand file tree
/
Copy pathslow_console_cause_hardlockup
More file actions
275 lines (240 loc) · 11.9 KB
/
slow_console_cause_hardlockup
File metadata and controls
275 lines (240 loc) · 11.9 KB
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
1,Watchdog detected hard LOCKUP on cpu 16:
[ 557.369547] Kernel panic - not syncing: Hard LOCKUP
[ 557.369548] CPU: 16 PID: 11511 Comm: kubelet Tainted: G W OE ------------ T 3.10.0-514.26.2.el7.x86_64 #1
[ 557.369548] Hardware name: ZTE EC600G3/XH20G2, BIOS UBF03.11.67_SVN65859 12/29/2016
[ 557.369549] ffffffff818daafa 0000000061eaf60c ffff88407d485b18 ffffffff816873ff
[ 557.369550] ffff88407d485b98 ffffffff816807ea 0000000b00000010 ffff88407d485ba8
[ 557.369551] ffff88407d485b48 0000000061eaf60c ffff88407d485b88 ffffffff818da800
[ 557.369551] Call Trace:
[ 557.369552] <NMI> [<ffffffff816873ff>] dump_stack+0x19/0x1b
[ 557.369555] [<ffffffff816807ea>] panic+0xe3/0x1f2
[ 557.369558] [<ffffffff81085abf>] nmi_panic+0x3f/0x40
[ 557.369559] [<ffffffff8112f999>] watchdog_overflow_callback+0xf9/0x100
[ 557.369560] [<ffffffff81174e4e>] __perf_event_overflow+0x8e/0x1f0
[ 557.369562] [<ffffffff81175a94>] perf_event_overflow+0x14/0x20
[ 557.369563] [<ffffffff81009d88>] intel_pmu_handle_irq+0x1f8/0x4e0
[ 557.369564] [<ffffffff8131ab2c>] ? ioremap_page_range+0x27c/0x3e0
[ 557.369565] [<ffffffff811bf774>] ? vunmap_page_range+0x1c4/0x310
[ 557.369566] [<ffffffff811bf8d1>] ? unmap_kernel_range_noflush+0x11/0x20
[ 557.369567] [<ffffffff813ca434>] ? ghes_copy_tofrom_phys+0x124/0x210
[ 557.369568] [<ffffffff813ca5c0>] ? ghes_read_estatus+0xa0/0x190
[ 557.369569] [<ffffffff8168f02b>] perf_event_nmi_handler+0x2b/0x50
[ 557.369571] [<ffffffff81690477>] nmi_handle.isra.0+0x87/0x160
[ 557.369572] [<ffffffff8130f380>] ? cfqg_print_leaf_weight_device+0x40/0x40
[ 557.369573] [<ffffffff81690723>] do_nmi+0x1d3/0x410
[ 557.369574] [<ffffffff8130f380>] ? cfqg_print_leaf_weight_device+0x40/0x40
[ 557.369575] [<ffffffff8168f893>] end_repeat_nmi+0x1e/0x2e
[ 557.369576] [<ffffffff8130f380>] ? cfqg_print_leaf_weight_device+0x40/0x40
[ 557.369577] [<ffffffff8168ee6a>] ? _raw_spin_lock_irq+0x3a/0x60
[ 557.369577] [<ffffffff8168ee6a>] ? _raw_spin_lock_irq+0x3a/0x60
[ 557.369579] [<ffffffff8168ee6a>] ? _raw_spin_lock_irq+0x3a/0x60
[ 557.369580] <<EOE>> [<ffffffff81309336>] blkcg_print_blkgs+0x76/0xf0 ----》 wait for blkg->q->queue_lock
[ 557.369581] [<ffffffff8130f236>] cfqg_print_rwstat_recursive+0x36/0x40
[ 557.369583] [<ffffffff81109393>] cgroup_seqfile_show+0x73/0x80
[ 557.369584] [<ffffffff81222b57>] ? seq_buf_alloc+0x17/0x40
[ 557.369585] [<ffffffff8122305a>] seq_read+0x10a/0x3b0
[ 557.369586] [<ffffffff811fe9be>] vfs_read+0x9e/0x170
[ 557.369587] [<ffffffff811ff58f>] SyS_read+0x7f/0xe0
[ 557.369588] [<ffffffff81697ac9>] system_call_fastpath+0x16/0x1b
source code:
void blkcg_print_blkgs(struct seq_file *sf, struct blkcg *blkcg,
u64 (*prfill)(struct seq_file *,
struct blkg_policy_data *, int),
const struct blkcg_policy *pol, int data,
bool show_total)
{
struct blkcg_gq *blkg;
u64 total = 0;
rcu_read_lock();
hlist_for_each_entry_rcu(blkg, &blkcg->blkg_list, blkcg_node) {
spin_lock_irq(blkg->q->queue_lock);
......
}
2, Another process, "kworker/u113:1" acquired q->queue_lock and wait for console_write to finish:
PID: 319 TASK: ffff881ffb09edd0 CPU: 7 COMMAND: "kworker/u113:1"
#0 [ffff881fffbc5e48] crash_nmi_callback at ffffffff8104d342
#1 [ffff881fffbc5e58] nmi_handle at ffffffff81690477
#2 [ffff881fffbc5eb0] do_nmi at ffffffff81690683
#3 [ffff881fffbc5ef0] end_repeat_nmi at ffffffff8168f893
[exception RIP: delay_tsc+68]
RIP: ffffffff81326724 RSP: ffff881ffb0b7540 RFLAGS: 00000046
RAX: 0000000000000007 RBX: ffffffff81f89080 RCX: 0066a7d6eb5cfc9d
RDX: 0066a7d6eb5d0629 RSI: 0000000000000007 RDI: 0000000000000a23
RBP: ffff881ffb0b7540 R8: 0000000000000000 R9: 00000000ffffffff
R10: 00000000000003ff R11: 0000000000000001 R12: 00000000000026f3
R13: 0000000000000020 R14: ffffffff81d3c0fb R15: 000000000000003b
ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0018
--- <NMI exception stack> ---
#4 [ffff881ffb0b7540] delay_tsc at ffffffff81326724
#5 [ffff881ffb0b7548] __const_udelay at ffffffff81326678
#6 [ffff881ffb0b7558] wait_for_xmitr at ffffffff814056e0
#7 [ffff881ffb0b7580] serial8250_console_putchar at ffffffff814058ac
#8 [ffff881ffb0b75a0] uart_console_write at ffffffff8140035a
#9 [ffff881ffb0b75d0] serial8250_console_write at ffffffff814057fe
#10 [ffff881ffb0b7618] call_console_drivers.constprop.17 at ffffffff81087011
#11 [ffff881ffb0b7640] console_unlock at ffffffff810889e9
#12 [ffff881ffb0b7680] vprintk_emit at ffffffff81088df4
#13 [ffff881ffb0b76f0] dev_vprintk_emit at ffffffff81428e72
#14 [ffff881ffb0b77a8] dev_printk_emit at ffffffff81428eee
#15 [ffff881ffb0b7808] __dev_printk at ffffffff8142937e
#16 [ffff881ffb0b7818] dev_printk at ffffffff8142942d
#17 [ffff881ffb0b7888] sdev_prefix_printk at ffffffff81463771
#18 [ffff881ffb0b7918] scsi_prep_state_check at ffffffff814598e4
#19 [ffff881ffb0b7928] scsi_prep_fn at ffffffff8145992d
#20 [ffff881ffb0b7960] blk_peek_request at ffffffff812f0826
#21 [ffff881ffb0b7988] scsi_request_fn at ffffffff8145b588
#22 [ffff881ffb0b79f0] __blk_run_queue at ffffffff812ebd63
#23 [ffff881ffb0b7a08] blk_queue_bio at ffffffff812f1013 -----》acquired q->queue_lock and wait for console_write to finish
#24 [ffff881ffb0b7a50] generic_make_request at ffffffff812ef209
#25 [ffff881ffb0b7a98] submit_bio at ffffffff812ef351
#26 [ffff881ffb0b7af0] xfs_submit_ioend_bio at ffffffffa0146a63 [xfs]
#27 [ffff881ffb0b7b00] xfs_submit_ioend at ffffffffa0146b31 [xfs]
#28 [ffff881ffb0b7b40] xfs_vm_writepages at ffffffffa0146e18 [xfs]
#29 [ffff881ffb0b7bb8] do_writepages at ffffffff8118da6e
#30 [ffff881ffb0b7bc8] __writeback_single_inode at ffffffff812293a0
#31 [ffff881ffb0b7c08] writeback_sb_inodes at ffffffff8122a08e
#32 [ffff881ffb0b7cb0] __writeback_inodes_wb at ffffffff8122a2ef
#33 [ffff881ffb0b7cf8] wb_writeback at ffffffff8122ab33
#34 [ffff881ffb0b7d70] bdi_writeback_workfn at ffffffff8122cb2b
#35 [ffff881ffb0b7e20] process_one_work at ffffffff810a851b
#36 [ffff881ffb0b7e68] worker_thread at ffffffff810a9356
#37 [ffff881ffb0b7ec8] kthread at ffffffff810b0b6f
#38 [ffff881ffb0b7f50] ret_from_fork at ffffffff81697a18
source code:
void blk_queue_bio(struct request_queue *q, struct bio *bio)
{
...
} else {
spin_lock_irq(q->queue_lock);
add_acct_request(q, req, where);
__blk_run_queue(q);
out_unlock:
spin_unlock_irq(q->queue_lock);
}
}
void console_unlock(void)
{
static char text[LOG_LINE_MAX + PREFIX_MAX];
...
call_console_drivers(level, text, len);
...
}
3,We also analysis this vmcore
crash> p hardlockup_panic
hardlockup_panic = $2 = 1
and found static char text[LOG_LINE_MAX + PREFIX_MAX]:
crash> rd 0xffffffff81d3c0c0 100
ffffffff81d3c0c0: 322e36343520205b 73205d3538313031 [ 546.210185] s
ffffffff81d3c0d0: 3a303a313a302064 63656a6572203a30 d 0:1:0:0: rejec
ffffffff81d3c0e0: 4f2f4920676e6974 6c66666f206f7420 ting I/O to offl
ffffffff81d3c0f0: 6976656420656e69 5345525f440a6563 ine device.D_RES
ffffffff81d3c100: 6576697264205445 52443d6574796272 ET driverbyte=DR
ffffffff81d3c110: 0a4b4f5f52455649 286e6f0a4b0a0a65 IVER_OK.e..K.on(
ffffffff81d3c120: 30302e30302e3431 6564690a2930302e 14.00.00.00).ide
ffffffff81d3c130: 656d75636f642064 206e6f697461746e d documentation
ffffffff81d3c140: 696d696c20726f66 2e736e6f69746174 for limitations.
ffffffff81d3c150: 4c54554e472b200a 2b204c43412b2053 . +GNUTLS +ACL +
ffffffff81d3c160: 20345a4c2d205a58 504d4f434345532d XZ -LZ4 -SECCOMP
ffffffff81d3c170: 2044494b4c422b20 4c495455464c452b +BLKID +ELFUTIL
ffffffff81d3c180: 20444f4d4b2b2053 6e650a294e44492b S +KMOD +IDN).en
ffffffff81d3c190: 2d4654552e53555f 0000000000000a38 _US.UTF-8.......
ffffffff81d3c1a0: 0000000000000000 0000000000000000 ................
ffffffff81d3c1b0: 0000000000000000 0000000000000000 ................
ffffffff81d3c1c0: 0000000000000000 0000000000000000 ................
ffffffff81d3c1d0: 0000000000000000 0000000000000000 ................
So, the "kworker/u113:1"‘s wait time after acquired q->queue_lock is:
557 - 546 = 11
cause Hard LOCKUP.
crash> p hardlockup_panic
hardlockup_panic = $2 = 1
crash> p log_buf
log_buf = $10 = 0xffffffff81d3cd9c <__log_buf> ""
crash> p log_buf_len
log_buf_len = $8 = 1048576
crash> p * (struct console*) console_drivers
$21 = {
name = "tty\000\000\000\000\000\000\000\000\000\000\000\000",
write = 0xffffffff813f89a0 <vt_console_print>,
read = 0x0,
device = 0xffffffff813f71a0 <vt_console_device>,
unblank = 0xffffffff813fa110 <unblank_screen>,
setup = 0x0,
early_setup = 0x0,
flags = 7,
index = 0,
cflag = 0,
data = 0x0,
next = 0xffffffff81a84200 <serial8250_console>
}
crash> p * (struct console*) 0xffffffff81a84200
$22 = {
name = "ttyS\000\000\000\000\000\000\000\000\000\000\000",
write = 0xffffffff81405750 <serial8250_console_write>,
read = 0x0,
device = 0xffffffff814049e0 <uart_console_device>,
unblank = 0x0,
setup = 0xffffffff81b57d27 <serial8250_console_setup>,
early_setup = 0xffffffff814056a0 <serial8250_console_early_setup>,
flags = 21,
index = 0,
cflag = 0,
data = 0xffffffff81a84380 <serial8250_reg>,
next = 0x0
}
console_unlock 函数中，一块static的内存保存了待输出的日志信息：
void console_unlock(void)
{
static char text[LOG_LINE_MAX + PREFIX_MAX];
static u64 seen_seq;
unsigned long flags;
bool wake_klogd = false;
bool retry;
unsigned cnt;
...
}
反汇编 console_unlock 函数，寻找引用text 的地方：
crash> dis -l console_unlock
...
/usr/src/debug/kernel-3.10.0-514.26.2.el7/linux-3.10.0-514.26.2.el7.x86_64/kernel/printk.c: 1473
0xffffffff8108891c <console_unlock+924>: mov $0x400,%eax
0xffffffff81088921 <console_unlock+929>: jmpq 0xffffffff8108883b <console_unlock+699>
0xffffffff81088926 <console_unlock+934>: mov $0xffffffff81d3c0c0,%rsi
0xffffffff8108892d <console_unlock+941>: callq 0xffffffff81086600 <print_time>
0xffffffff81088932 <console_unlock+946>: mov %rax,%r12
源码：
static size_t cont_print_text(char *text, size_t size)
{
size_t textlen = 0;
size_t len;
if (cont.cons == 0 && (console_prev & LOG_NEWLINE)) {
textlen += print_time(cont.ts_nsec, text);
size -= textlen;
}
发现0xffffffff81d3c0c0 就是static内存，读取它的内容：
crash> rd 0xffffffff81d3c0c0 100
ffffffff81d3c0c0: 322e36343520205b 73205d3538313031 [ 546.210185] s
ffffffff81d3c0d0: 3a303a313a302064 63656a6572203a30 d 0:1:0:0: rejec
ffffffff81d3c0e0: 4f2f4920676e6974 6c66666f206f7420 ting I/O to offl
ffffffff81d3c0f0: 6976656420656e69 5345525f440a6563 ine device.D_RES
ffffffff81d3c100: 6576697264205445 52443d6574796272 ET driverbyte=DR
ffffffff81d3c110: 0a4b4f5f52455649 286e6f0a4b0a0a65 IVER_OK.e..K.on(
ffffffff81d3c120: 30302e30302e3431 6564690a2930302e 14.00.00.00).ide
ffffffff81d3c130: 656d75636f642064 206e6f697461746e d documentation
ffffffff81d3c140: 696d696c20726f66 2e736e6f69746174 for limitations.
ffffffff81d3c150: 4c54554e472b200a 2b204c43412b2053 . +GNUTLS +ACL +
ffffffff81d3c160: 20345a4c2d205a58 504d4f434345532d XZ -LZ4 -SECCOMP
ffffffff81d3c170: 2044494b4c422b20 4c495455464c452b +BLKID +ELFUTIL
ffffffff81d3c180: 20444f4d4b2b2053 6e650a294e44492b S +KMOD +IDN).en
ffffffff81d3c190: 2d4654552e53555f 0000000000000a38 _US.UTF-8.......
ffffffff81d3c1a0: 0000000000000000 0000000000000000 ................
ffffffff81d3c1b0: 0000000000000000 0000000000000000 ................
ffffffff81d3c1c0: 0000000000000000 0000000000000000 ................
ffffffff81d3c1d0: 0000000000000000 0000000000000000 ................
So, the "kworker/u113:1"‘s waiting time after acquired q->queue_lock is:
557 - 546 = 11
上述临时日志持续时间：557 - 546 = 11, 刚好超过hard_lockup 的门限值(int __read_mostly watchdog_thresh = 10;)。
这个补丁应该可以修复它：
https://lkml.org/lkml/2016/4/22/487
但是这个补丁一年多了也没有进入主线内核。
也同时向开源社区提交bug：
https://bugzilla.kernel.org/show_bug.cgi?id=199003