Chinaunix

标题: 空指针in handle_IRQ_event [打印本页]

作者: humjb_1983 时间: 2015-01-10 15:37
标题: 空指针in handle_IRQ_event
一、故障现象
内核panic，打印如下：
Unable to handle kernel NULL pointer dereference at 0000000000000039 RIP:
[<ffffffff80010b74>] handle_IRQ_event+0x44/0xa6
PGD 61df63067 PUD 61ea5a067 PMD 0
Oops: 0000 [1] SMP
last sysfs file: /devices/system/cpu/cpu0/cpufreq/scaling_max_freq
CPU 8
Modules linked in: ossmod(U) tipc(U) bsp_smbus_ctrl(U) bonding autofs4 hidp rfcomm l2cap bluetooth lockd sunrpc ipv6 xfrm_nalgo crypto_api cpufreq_ondemand acpi_cpufreq freq_table dm_mirror d
m_multipath scsi_dh video hwmon backlight sbs i2c_ec button battery asus_acpi acpi_memhotplug ac lp floppy esh(U) snd_hda_intel snd_seq_dummy snd_seq_oss snd_seq_midi_event snd_seq snd_seq_de
vice sg snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd_page_alloc snd_hwdep snd igb i2c_i801 i2c_core soundcore 8021q serio_raw parport_pc parport e1000(U) pcspkr dm_raid45 dm_message dm_reg
ion_hash dm_log dm_mod dm_mem_cache ata_piix libata shpchp mptsas mptscsih mptbase scsi_transport_sas sd_mod scsi_mod ext3 jbd uhci_hcd ohci_hcd ehci_hcd
Pid: 0, comm: swapper Tainted: G 2.6.18-164.el5 #1
RIP: 0010:[<ffffffff80010b74>] [<ffffffff80010b74>] handle_IRQ_event+0x44/0xa6
RSP: 0018:ffff81032fca7f28 EFLAGS: 00010202
RAX: 0000000000000001 RBX: 0000000000000000 RCX: 00000000000000b2
RDX: ffff810009028520 RSI: ffff81032fc98000 RDI: ffff81032b1c7180
RBP: 0000000000000001 R08: ffff81032fca0000 R09: ffffffff800967c5
R10: ffff81032fca7f30 R11: ffff81032fca1ee8 R12: 00000000000000b2
R13: 0000000000000001 R14: ffff81032fca1df8 R15: ffff81032fca1df8
FS: 0000000000000000(0000) GS:ffff81010b373b40(0000) knlGS:0000000000000000
CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b
CR2: 0000000000000039 CR3: 000000061f37c000 CR4: 00000000000006e0
Process swapper (pid: 0, threadinfo ffff81032fca0000, task ffff81033ab0f7e0)
Stack: ffffffff803e3580 000000000000b200 00000000000000b2 ffff81032acdee40
ffffffff803e35bc ffffffff800b9808 ffffffff8001235a 00000000000000b2
ffff81032fca1df8 00000000009c1418 ffff81062dc4d000 0000000000000800
Call Trace:
<IRQ> [<ffffffff800b9808>] __do_IRQ+0xa4/0x103
[<ffffffff8001235a>] __do_softirq+0x89/0x133
[<ffffffff8006c997>] do_IRQ+0xe7/0xf5
[<ffffffff8005d615>] ret_from_intr+0x0/0xa
<EOI> [<ffffffff8019768f>] acpi_processor_idle+0x274/0x463
[<ffffffff80197685>] acpi_processor_idle+0x26a/0x463
[<ffffffff8019741b>] acpi_processor_idle+0x0/0x463
[<ffffffff8019741b>] acpi_processor_idle+0x0/0x463
[<ffffffff8004939e>] cpu_idle+0x95/0xb8
[<ffffffff80076e23>] start_secondary+0x45a/0x469

从打印看，是在handle_IRQ_event函数中遇到了空指针

目前从我们的分析看，怀疑是硬件1bit跳变问题，但无法确认，请大家一起看看是否还有其它想法。

正好@Tinnal回来了，有空帮忙瞅瞅~，谢谢！

在blog中记录了一下分析过程(供参考)：
http://blog.chinaunix.net/uid-14528823-id-4751271.html

作者: smalloc 时间: 2015-01-10 15:49
intel的平板？内核怎么才2.6.18?

作者: Tinnal 时间: 2015-01-11 00:59
日记正在审核，

，看不了blog.

作者: Tinnal 时间: 2015-01-11 01:01
能把对应的源码、反汇编、还有你的分析过程，贴过来吗？

作者: humjb_1983 时间: 2015-01-12 08:24

smalloc 发表于 2015-01-10 15:49
intel的平板？内核怎么才2.6.18?

老版本的环境了~，服务器上没出问题的话，通常不升级版本~~

作者: humjb_1983 时间: 2015-01-12 08:27

Tinnal 发表于 2015-01-11 01:01
能把对应的源码、反汇编、还有你的分析过程，贴过来吗？

二、Vmcore分析
1、反汇编handle_IRQ_event，获取RIP所在的指令

点击(此处)折叠或打开
crash> dis -l handle_IRQ_event
/usr/src/debug/kernel-2.6.18/linux-2.6.18.x86_64/kernel/irq/handle.c: 134
0xffffffff80010b30 <handle_IRQ_event>: push %r14
include/trace/irq.h: 7
0xffffffff80010b32 <handle_IRQ_event+2>: cmpl $0x0,3859215(%rip) # 0xffffffff803bee48 <__tracepoint_irq_entry.10785+8>
/usr/src/debug/kernel-2.6.18/linux-2.6.18.x86_64/kernel/irq/handle.c: 134
0xffffffff80010b39 <handle_IRQ_event+9>: mov %rsi,%r14
0xffffffff80010b3c <handle_IRQ_event+12>: push %r13
0xffffffff80010b3e <handle_IRQ_event+14>: push %r12
0xffffffff80010b40 <handle_IRQ_event+16>: mov %edi,%r12d
0xffffffff80010b43 <handle_IRQ_event+19>: push %rbp
0xffffffff80010b44 <handle_IRQ_event+20>: mov %rdx,%rbp
0xffffffff80010b47 <handle_IRQ_event+23>: push %rbx
include/trace/irq.h: 7
0xffffffff80010b48 <handle_IRQ_event+24>: je 0xffffffff80010b68 <handle_IRQ_event+56>
0xffffffff80010b4a <handle_IRQ_event+26>: mov 3859199(%rip),%rbx # 0xffffffff803bee50 <__tracepoint_irq_entry.10785+16>
0xffffffff80010b51 <handle_IRQ_event+33>: test %rbx,%rbx
0xffffffff80010b54 <handle_IRQ_event+36>: je 0xffffffff80010b68 <handle_IRQ_event+56>
0xffffffff80010b56 <handle_IRQ_event+38>: mov %r14,%rsi
0xffffffff80010b59 <handle_IRQ_event+41>: mov %r12d,%edi
0xffffffff80010b5c <handle_IRQ_event+44>: callq *(%rbx)
0xffffffff80010b5e <handle_IRQ_event+46>: add $0x8,%rbx
0xffffffff80010b62 <handle_IRQ_event+50>: cmpq $0x0,(%rbx)
0xffffffff80010b66 <handle_IRQ_event+54>: jmp 0xffffffff80010b54 <handle_IRQ_event+36>
/usr/src/debug/kernel-2.6.18/linux-2.6.18.x86_64/kernel/irq/handle.c: 142
0xffffffff80010b68 <handle_IRQ_event+56>: testb $0x20,0x8(%rbp)
0xffffffff80010b6c <handle_IRQ_event+60>: jne 0xffffffff80010b6f <handle_IRQ_event+63>
include/asm/irqflags.h: 80
0xffffffff80010b6e <handle_IRQ_event+62>: sti
0xffffffff80010b6f <handle_IRQ_event+63>: xor %r13d,%r13d
0xffffffff80010b72 <handle_IRQ_event+66>: xor %ebx,%ebx
/usr/src/debug/kernel-2.6.18/linux-2.6.18.x86_64/kernel/irq/handle.c: 146
0xffffffff80010b74 <handle_IRQ_event+68>: mov 0x38(%rbp),%rsi
0xffffffff80010b78 <handle_IRQ_event+72>: mov %r14,%rdx

从之前的堆栈可以看出RIP为：handle_IRQ_event+0x44/0xa6
0x44折算成十进制为68，所以需要关注handle_IRQ_event+68行：
0xffffffff80010b74 <handle_IRQ_event+68>:    mov 0x38(%rbp),%rsi
从之前的汇编分析，rsi的值应该是上级函数传入，不太可能在其中出现空指针，问题应该出在0x38(%rbp)上，也就是rbp上。

2、结合handle_IRQ_event源代码分析
handle_IRQ_event代码如下：

点击(此处)折叠或打开
132 irqreturn_t handle_IRQ_event(unsigned int irq, struct pt_regs *regs,
133 struct irqaction *action)
134 {
135 irqreturn_t ret, retval = IRQ_NONE;
136 unsigned int status = 0;
137
138 trace_irq_entry(irq, regs);
139
140 handle_dynamic_tick(action);
141
142 if (!(action->flags & IRQF_DISABLED))
143 local_irq_enable_in_hardirq();
144
145 do {
146 ret = action->handler(irq, action->dev_id, regs);
147 if (ret == IRQ_HANDLED)
148 status |= action->flags;
149 retval |= ret;
150 action = action->next;
151 } while (action);
152
153 if (status & IRQF_SAMPLE_RANDOM)
154 add_interrupt_randomness(irq);
155 local_irq_disable();
156
157 trace_irq_exit(irq, retval);
158
159 return retval;
160 }

之前反汇编中有代码行提示：
/usr/src/debug/kernel-2.6.18/linux-2.6.18.x86_64/kernel/irq/handle.c: 146
可以看出问题出在146行：
146       ret = action->handler(irq, action->dev_id, regs);
可以看出0x38(%rbp)应该对应action->dev_id(因为通过偏移访问，结构体访问基本如此)，如此可见rbp中存放的即action变量的的值，
分析源代码，action是通过入参传入的，但是在146-151行的循环中，150行，对action重新赋值了。
150       action = action->next;
如此，可以推测action->next出问题了，也就是通过入参传入的action的next成员出问题了，of course，也可能是一开始的传入的如此就有问题了。
继续分析action入参的值。

3、入参(action)分析
action被放入了rbp寄存器，看如下汇编行：
0xffffffff80010b44 <handle_IRQ_event+20>:    mov %rdx,%rbp
可以看出，action入参是通过rdx寄存器传入的，并不是我们通常认为的通过堆栈。需要进一步分析上级行数中的rdx寄存器的值。

4、上级函数__do_IRQ分析

点击(此处)折叠或打开
crash> bt
PID: 0 TASK: ffff81033ab0f7e0 CPU: 8 COMMAND: "swapper"
#0 [ffff81032fca7c80] crash_kexec at ffffffff800ac5b9
#1 [ffff81032fca7d40] __die at ffffffff80065127
#2 [ffff81032fca7d80] do_page_fault at ffffffff80066da7
#3 [ffff81032fca7e70] error_exit at ffffffff8005dde9
[exception RIP: handle_IRQ_event+68]
RIP: ffffffff80010b74 RSP: ffff81032fca7f28 RFLAGS: 00010202
RAX: 0000000000000001 RBX: 0000000000000000 RCX: 00000000000000b2
RDX: ffff810009028520 RSI: ffff81032fc98000 RDI: ffff81032b1c7180
RBP: 0000000000000001 R8: ffff81032fca0000 R9: ffffffff800967c5
R10: ffff81032fca7f30 R11: ffff81032fca1ee8 R12: 00000000000000b2
R13: 0000000000000001 R14: ffff81032fca1df8 R15: ffff81032fca1df8
ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0018
#4 [ffff81032fca7f20] handle_IRQ_event at ffffffff80010b81
#5 [ffff81032fca7f50] __do_IRQ at ffffffff800b9808
#6 [ffff81032fca7f90] do_IRQ at ffffffff8006c997
--- <IRQ stack> ---
可见，上级函数为__do_IRQ。
对照__do_IRQ源代码，可以看出调用handle_IRQ_event的地方为240行，所以关注汇编中的相关行附件代码即可

点击(此处)折叠或打开
174 fastcall unsigned int __do_IRQ(unsigned int irq, struct pt_regs *regs)
175 {
176 struct irq_desc *desc = irq_desc + irq;
177 struct irqaction *action;
178 unsigned int status;
...
235 for (;

{
236 irqreturn_t action_ret;
237
238 spin_unlock(&desc->lock);
239
240 action_ret = handle_IRQ_event(irq, regs, action);
241 if (!noirqdebug)
242 note_interrupt(irq, desc, action_ret, regs);
243
244 spin_lock(&desc->lock);
245 if (likely(!(desc->status & IRQ_PENDING)))
246 break;
247 desc->status &= ~IRQ_PENDING;
248 }
...
260 }
继续反汇编__do_IRQ

点击(此处)折叠或打开
/usr/src/debug/kernel-2.6.18/linux-2.6.18.x86_64/kernel/irq/handle.c: 222
0xffffffff800b97f1 <__do_IRQ+141>: je 0xffffffff800b9845 <__do_IRQ+225>
include/asm/spinlock.h: 62
0xffffffff800b97f3 <__do_IRQ+143>: movl $0x1,0x3c(%rbx)
/usr/src/debug/kernel-2.6.18/linux-2.6.18.x86_64/kernel/irq/handle.c: 240
0xffffffff800b97fa <__do_IRQ+150>: mov %r13,%rdx
0xffffffff800b97fd <__do_IRQ+153>: mov %r15,%rsi
0xffffffff800b9800 <__do_IRQ+156>: mov %r12d,%edi
0xffffffff800b9803 <__do_IRQ+159>: callq 0xffffffff80010b30 <handle_IRQ_event>
/usr/src/debug/kernel-2.6.18/linux-2.6.18.x86_64/kernel/irq/handle.c: 241
0xffffffff800b9808 <__do_IRQ+164>: cmpl $0x0,3358161(%rip) # 0xffffffff803ed5e0 <noirqdebug>
0xffffffff800b980f <__do_IRQ+171>: jne 0xffffffff800b9821 <__do_IRQ+189>
/usr/src/debug/kernel-2.6.18/linux-2.6.18.x86_64/kernel/irq/handle.c: 242
0xffffffff800b9811 <__do_IRQ+173>: mov %r15,%rcx
0xffffffff800b9814 <__do_IRQ+176>: mov %eax,%edx
0xffffffff800b9816 <__do_IRQ+178>: mov %rbx,%rsi
0xffffffff800b9819 <__do_IRQ+181>: mov %r12d,%edi

可以看出edx的值来源于r13，再回看handle_IRQ_event函数的反汇编，在该函数的开始对r13寄存器进行了压栈

点击(此处)折叠或打开
0xffffffff80010b30 <handle_IRQ_event>: push %r14
include/trace/irq.h: 7
0xffffffff80010b32 <handle_IRQ_event+2>: cmpl $0x0,3859215(%rip) # 0xffffffff803bee48 <__tracepoint_irq_entry.10785+8>
/usr/src/debug/kernel-2.6.18/linux-2.6.18.x86_64/kernel/irq/handle.c: 134
0xffffffff80010b39 <handle_IRQ_event+9>: mov %rsi,%r14
0xffffffff80010b3c <handle_IRQ_event+12>: push %r13

所以，可以从handle_IRQ_event函数的栈帧中找到action的值。r13应该位于该栈帧中的第3个值，因为第一个必然为函数的返回地址，第二个值为r14（在r13之前压入）。
看看handle_IRQ_event函数的栈

点击(此处)折叠或打开
crash> bt -f
PID: 0 TASK: ffff81033ab0f7e0 CPU: 8 COMMAND: "swapper"
#0 [ffff81032fca7c80] crash_kexec at ffffffff800ac5b9
ffff81032fca7c88: ffff81032fca1df8 ffff81032fca1df8
ffff81032fca7c98: 0000000000000001 00000000000000b2
ffff81032fca7ca8: 0000000000000001 0000000000000000
ffff81032fca7cb8: ffff81032fca1ee8 ffff81032fca7f30
ffff81032fca7cc8: ffffffff800967c5 ffff81032fca0000
ffff81032fca7cd8: 0000000000000001 00000000000000b2
ffff81032fca7ce8: ffff810009028520 ffff81032fc98000
ffff81032fca7cf8: ffff81032b1c7180 ffffffffffffffff
ffff81032fca7d08: ffffffff80010b74 0000000000000010
ffff81032fca7d18: 0000000000010202 ffff81032fca7f28
ffff81032fca7d28: 0000000000000018 ffff81032fca7e78
ffff81032fca7d38: ffffffff802a4d0d ffffffff80065127
.......
#4 [ffff81032fca7f20] handle_IRQ_event at ffffffff80010b81
ffff81032fca7f28: ffffffff803e3580 000000000000b200
ffff81032fca7f38: 00000000000000b2 ffff81032acdee40
ffff81032fca7f48: ffffffff803e35bc ffffffff800b9808
#5 [ffff81032fca7f50] __do_IRQ at ffffffff800b9808
ffff81032fca7f58: ffffffff8001235a 00000000000000b2
ffff81032fca7f68: ffff81032fca1df8 00000000009c1418
ffff81032fca7f78: ffff81062dc4d000 0000000000000800
ffff81032fca7f88: ffffffff803ea360 ffffffff8006c997

可以看出action的值应该为ffff81032acdee40，看看其中的内容，顺便验证下。
action为irqaction类型的结构体：

点击(此处)折叠或打开
crash> struct irqaction ffff81032acdee40
struct irqaction {
  handler = 0xffffffff8827628b,
  flags = 0,
  mask = {
bits = {0, 0, 0, 0}
  },
  name = 0xffff81032b1c7000 "eth0-rx-3",
  dev_id = 0xffff81032bef56b8,
  next = 0x1,
  irq = 178,
  dir = 0xffff810328db2180
}

可以看出该irqaction结构体对应于eth0网卡的接收中断，中断号为178，注意其中的next，为0x1，这就是问题所在。
从log信息可以看出空指针具体的值为：0000000000000039 ，正好=0x1+38，所以说明分析是正确的。

分析代码逻辑和irqaction的定义：

点击(此处)折叠或打开
crash> struct irqaction
struct irqaction {
irqreturn_t (*handler)(int, void *, struct pt_regs *);
long unsigned int flags;
cpumask_t mask;
const char *name;
void *dev_id;
struct irqaction *next;
int irq;
struct proc_dir_entry *dir;
}
SIZE: 88

这里的next应该在有中断共享时使用，即同一个irq号对应多个ISR，如果有共享，那么这里的next指向共享该irq的下一个action.
从/proc/interrupts信息，可以看出178号中断并没有共享的情况，所以，这里的next应该为null，为0x1显然有问题了。
从irqaction中的值分析，next前后的数据都是正常的，只有next从0突变成1了，基本可以排除由于内存越界导致内存写坏的情况。
分析设置next指针的所有代码，只有设置地址和删除的代码，并没有发现有直接设置为1的地方。

那为什么如此呢？要继续分析就很困难了。

5、分析irq_desc
没有其它分析思路了，尝试分析action所在的结构体irq_desc，看看其中的内容，该结构体的值需要从上级函数__do_IRQ分析，见其代码176行：
176    struct irq_desc *desc = irq_desc + irq;
其中irq_desc为全局变量（数组），存放所有的irq_desc，按编号排列。
对照其汇编：
/usr/src/debug/kernel-2.6.18/linux-2.6.18.x86_64/kernel/irq/handle.c: 176
0xffffffff800b9784 <__do_IRQ+32>:    lea 0xffffffff803d8380(%rbp),%rbx
lea指令的意思是将0xffffffff803d8380(%rbp)地址(即rbp+0xffffffff803d8380)，赋值给rbx，这里显然0xffffffff803d8380就是irq_desc全局变量的地址。
确认一下：

点击(此处)折叠或打开
crash> struct irq_desc 0xffffffff803d8380
struct irq_desc {
  handle_irq = 0,
  chip = 0xffffffff803ec7e0,
  handler_data = 0x0,
  chip_data = 0x0,
  action = 0xffffffff803018a0,
  status = 0,
  depth = 0,
  wake_depth = 0,
  irq_count = 22386,
  irqs_unhandled = 0,
  lock = {
raw_lock = {
   slock = 1
}
  },
  affinity = {
bits = {1, 0, 0, 0}
  },
  cpu = 0,
  pending_mask = {
bits = {0, 0, 0, 0}
  },
  move_irq = 0,
  dir = 0xffff81062ddbd180
}
crash> struct irqaction 0xffffffff803018a0
struct irqaction {
  handler = 0xffffffff8006e9da <timer_interrupt>,
  flags = 32,
  mask = {
bits = {0, 0, 0, 0}
  },
  name = 0xffffffff802b3dfa "timer",
  dev_id = 0x0,
  next = 0x0,
  irq = 0,
  dir = 0x0
}

可以看出位于该全局变量的第一个元素为时钟中断对应的描述符，说明分析正确。但我们这里需要分析的是178号中断(irq好前面已经分析得到了)，应该怎么查找呢。
继续看汇编代码，可以看出178号中断对应的描述符在irq_desc数组中的偏移量存放在rbp中了，查看rbp后续的汇编代码，并没有对进行压栈处理，且当前函数不是最顶级的堆栈函数，所以无法直接从vmcore中获取rbp的值，只能想其它办法了。
继续看汇编代码：
/usr/src/debug/kernel-2.6.18/linux-2.6.18.x86_64/kernel/irq/handle.c: 176
0xffffffff800b977c <__do_IRQ+24>:    mov %rcx,%rbp
0xffffffff800b977f <__do_IRQ+27>:    shl $0x8,%rbp
这里的rcx应该存放的是irq的编号，也就是178，将rcx左移8位后即得到rbp(shl $0x8,%rbp)，即178*256=rbp=0xb200
0xffffffff803d8380+0xb200=0xffffffff803e3580，该地址即为178号中断对应的描述符的地址了：

点击(此处)折叠或打开
crash> struct irq_desc FFFFFFFF803E3580
struct irq_desc {
  handle_irq = 0,
  chip = 0xffffffff80323c40,
  handler_data = 0x0,
  chip_data = 0x0,
  action = 0xffff81032acdee40,
  status = 65536,
  depth = 0,
  wake_depth = 0,
  irq_count = 78785,
  irqs_unhandled = 0,
  lock = {
raw_lock = {
   slock = 1
}
  },
  affinity = {
bits = {256, 0, 0, 0}
  },
  cpu = 0,
  pending_mask = {
bits = {32768, 0, 0, 0}
  },
  move_irq = 1,
  dir = 0xffff810328db2380
}
crash> struct irqaction 0xffff81032acdee40
struct irqaction {
  handler = 0xffffffff8827628b,
  flags = 0,
  mask = {
bits = {0, 0, 0, 0}
  },
  name = 0xffff81032b1c7000 "eth0-rx-3",
  dev_id = 0xffff81032bef56b8,
  next = 0x1,
  irq = 178,
  dir = 0xffff810328db2180

exactly，正是我们需要的，于是找到了描述符，看看其内容，其中
irq_count = 78785,
irq_count用于监测中断是否挂起的计数，不为0表明之前已处理过该中断，说明该中断之前正在被正常处理，突然直接出了问题。

至此，确实无法继续分析了，从故障现象看，内核问题可能性不大，更像是是内存的1bit跳变导致的问题，但是通常的服务器环境中，内存(控制器)硬件应该有ECC校验功能，可以自动纠正1bit跳变的情况才对。
核对了一下出现问题的硬件环境，dmicode命令中可以看到内存硬件确实有ECC校验功能，但是发现CPU cache硬件中没有包含ECC校验功能：
Error Correction Type: None
看了看其它类型的服务器，一些服务器有ECC校验功能：
Error Correction Type: Single-bit ECC

因此，没有其它疑点，只能怀疑是内存(或者说是cache)的1bit跳变硬件故障导致。
但没有进一步证据了，有其它想法欢迎讨论。

作者: gaojl0728 时间: 2015-01-12 14:23
回复 6# humjb_1983

太长了，看的头疼，既然非法的action 地址为0x1, 为何Crash的地址是0x39, 理解不了。
正常情况下crash 的地址应该就是0x1

作者: gaojl0728 时间: 2015-01-12 15:49
不太可能是硬件错误，大部分这种空指针都是驱动bug引起的，不知道你的网卡是什么驱动？

我感觉next指针极可能是被当前的中断函数0xffffffff8827628b里面写坏的。
中断处理函数会访问action->dev_id，如果在访问这个字段的时候越界了，那就可能会把action->next写坏。

如果知道网卡的型号和驱动，可以一起研究研究。

作者: humjb_1983 时间: 2015-01-13 08:28

gaojl0728 发表于 2015-01-12 14:23
回复 6# humjb_1983

确实不好看，感谢费神看完~

0xffffffff80010b74 <handle_IRQ_event+68>: mov 0x38(%rbp),%rsi
出错的汇编代码如下，rbp是1，再加上0x38就是出错的地址0x39了。

作者: humjb_1983 时间: 2015-01-13 10:14

gaojl0728 发表于 2015-01-12 15:49
不太可能是硬件错误，大部分这种空指针都是驱动bug引起的，不知道你的网卡是什么驱动？

我感觉next指针 ...

看igb代码dev_id是在request_irq中传入的igb_adapter结构体，查看其内容，看起来是正常的，不像会越界。。。
struct igb_adapter {
  watchdog_timer = {
entry = {
   next = 0xffff81032ae53500,
   prev = 0xffff810321fb4000
},
expires = 13455015936,
function = 0x10000001000,
data = 14004156690161729791,
base = 0xffffc20000069000
  },
  phy_info_timer = {
entry = {
   next = 0x28800000010,
   prev = 0x9000000001690
},
expires = 0,
function = 0,
data = 0,
base = 0x0
  },
  vlgrp = 0x0,
  mng_vlan_id = 0,
  bd_number = 0,
  rx_buffer_len = 0,
  wol = 0,
  en_mng_pt = 0,
  link_speed = 0,
  link_duplex = 0,
  total_tx_bytes = 0,
  total_tx_packets = 0,
  total_rx_bytes = 0,
  total_rx_packets = 0,
  itr = 719663104,
  itr_setting = 4294934787,
  tx_itr = 0,
  rx_itr = 0,
  reset_task = {
pending = 0,
entry = {
   next = 0x0,
   prev = 0x0
},
func = 0xffff81032b1c7000,
data = 0x0,
wq_data = 0x0,
timer = {
   entry = {
      next = 0x0,
      prev = 0x0
   },
   expires = 0,
   function = 0,
   data = 0,
   base = 0x0
}
  },
  watchdog_task = {
pending = 0,
entry = {
   next = 0x0,
   prev = 0x0
},
func = 0,
data = 0x0,
wq_data = 0x0,
timer = {
   entry = {
      next = 0x0,
      prev = 0x0
   },
   expires = 0,
   function = 0x1,
   data = 18446604462036712560,
   base = 0xffff81061fd57c70
}
  },
  fc_autoneg = false,
  tx_timeout_factor = 0 '\0',
  blink_timer = {
entry = {
   next = 0x0,
   prev = 0x0
},
expires = 0,
function = 0,
data = 0,
base = 0x0
  },
  led_status = 0,
  tx_ring = 0x0,
  restart_queue = 0,
  tx_queue_len = 0,
  txd_cmd = 0,
  gotc = 0,
  gotc_old = 0,
  tpt_old = 0,
  colc_old = 0,
  tx_timeout_count = 0,
  rx_ring = 0x0,
  num_tx_queues = 0,
  num_rx_queues = 0,
  hw_csum_err = 0,
  hw_csum_good = 0,
  alloc_rx_buff_failed = 0,
  rx_csum = false,
  gorc = 0,
  gorc_old = 0,
  rx_ps_hdr_size = 0,
  max_frame_size = 0,
  min_frame_size = 0,
  netdev = 0x0,
  pdev = 0x0,
  net_stats = {
rx_packets = 0,
tx_packets = 0,
rx_bytes = 0,
tx_bytes = 0,
rx_errors = 0,
tx_errors = 0,
rx_dropped = 0,
tx_dropped = 0,
multicast = 0,
collisions = 0,
rx_length_errors = 0,
rx_over_errors = 0,
rx_crc_errors = 0,
rx_frame_errors = 0,
rx_fifo_errors = 0,
rx_missed_errors = 0,
tx_aborted_errors = 0,
tx_carrier_errors = 0,
tx_fifo_errors = 0,
tx_heartbeat_errors = 0,
tx_window_errors = 0,
rx_compressed = 0,
tx_compressed = 0
  },
  hw = {
back = 0x0,
hw_addr = 0x0,
flash_address = 0x0,
io_base = 0,
mac = {
   ops = {
      check_for_link = 0,
      reset_hw = 0,
      init_hw = 0,
      check_mng_mode = 0,
      setup_physical_interface = 0,
      rar_set = 0,
      read_mac_addr = 0,
      get_speed_and_duplex = 0
   },
   addr = "\000\000\000\000\000",
   perm_addr = "\000\000\000\000\000",
   type = e1000_undefined,
   collision_delta = 0,
   ledctl_default = 0,
   ledctl_mode1 = 0,
   ledctl_mode2 = 0,
   mc_filter_type = 0,
   tx_packet_delta = 1,
   txcw = 1,
   current_ifs_val = 0,
   ifs_max_val = 0,
   ifs_min_val = 1,
   ifs_ratio = 0,
   ifs_step_size = 1,
   mta_reg_count = 0,
   rar_entry_count = 0,
   forced_speed_duplex = 0 '\0',
   adaptive_ifs = false,
   arc_subsystem_valid = false,
   asf_firmware_present = false,
   autoneg = false,
   autoneg_failed = false,
   disable_hw_init_bits = false,
   get_link_status = false,
   ifs_params_forced = false,
   in_ifs_mode = false,
   report_tx_early = false,
   serdes_has_link = false,
   tx_pkt_filtering = false
},
fc = {
   high_water = 2921475440,
   low_water = 4294934786,
   pause_time = 0,
   send_xon = false,
   strict_ieee = false,
   type = e1000_fc_none,
   original_type = e1000_fc_none
},
phy = {
   ops = {
      acquire = 0,
      check_reset_block = 0,
      force_speed_duplex = 0,
      get_cfg_done = 0,
      get_cable_length = 0,
      get_phy_info = 0,
      read_reg = 0,
      release = 0,
      reset = 0,
      set_d0_lplu_state = 0,
      set_d3_lplu_state = 0,
      write_reg = 0
   },
   type = e1000_phy_unknown,
   local_rx = e1000_1000t_rx_status_not_ok,
   remote_rx = e1000_1000t_rx_status_not_ok,
   ms_type = e1000_ms_hw_default,
   original_ms_type = e1000_ms_hw_default,
   cable_polarity = e1000_rev_polarity_normal,
   smart_speed = e1000_smart_speed_default,
   addr = 0,
   id = 0,
   reset_delay_us = 0,
   revision = 0,
   media_type = e1000_media_type_unknown,
   autoneg_advertised = 0,
   autoneg_mask = 0,
   cable_length = 0,
   max_cable_length = 0,
   min_cable_length = 0,
   mdix = 0 '\0',
   disable_polarity_correction = false,
   is_mdix = false,
   polarity_correction = false,
   reset_disable = false,
   speed_downgraded = false,
   autoneg_wait_to_complete = false
},
....

作者: gaojl0728 时间: 2015-01-13 17:27
回复 9# humjb_1983

是的，dev_id的偏移值正好是0x38

作者: gaojl0728 时间: 2015-01-13 17:30
回复 1# humjb_1983

1.  发现了一点线索，中断178在panic之前发生了一次irq migratioin, 这也许跟panic有点关系。从打印信息能看到：
  move_irq = 1,
  pending_mask = {
bits = {32768, 0, 0, 0}
  },
  affinity = {
bits = {256, 0, 0, 0}
  },
因为irq_desc数组是全局数组不是SLAB，这几个值应该比较可信，这块内存被写坏的可能性不大
affinity是原来的值， pending_mask是将要迁移的目的值，

这说明从"上次178号中断执行完之后到本次178号开始执行并Crash"这段时间里发生了一次 irq migratioin

从linux 2.6.18 + X86_64内核代码看，只有一个内核路径可能会执行irq migratioin,

那就是:"用户空间写/proc/irq/178/smp_affinity" -> irq_affinity_write_proc -> proc_set_irq_affinity -> set_pending_irq

set_pending_irq会发起一次irq migratioin, 这仅仅是开始，
当__do_IRQ执行完中断处理函数之后，会调用desc->chip->end(irq)来终止本次irq migratioin
desc->chip->end 会调用move_native_irq执行真正的迁移并结束迁移，同时清空desc->move_irq = 0；
这也能说明irq migratioin 是从上次178号中断执行完之后才开始的，

不过从代码来看， irq migratioin执行的过程中没有发现明显的可能写坏irqaction->next的地方。

下一步我感觉也许可以手动修改/proc/irq/178/smp_affinity，尝试重现一下

2. 因为irqaction的内存是从slab分配的，这就是个内存池，如果别人写坏了内存一样可能把irqaction给写坏。如果crash的现场跟写坏的地方里的很远那就不好定位了。
有个疑问就是178中断的irqaction->handler字段为什么没有显示出来函数名而是直接显示了一个地址0xffffffff8827628b？这个字段也有可能被写坏了？
可以看看这个地址0xffffffff8827628b是不是指向正确的中断函数。
这可能需要加载网卡驱动的符号表。

作者: humjb_1983 时间: 2015-01-14 14:38

gaojl0728 发表于 2015-01-13 17:30
回复 1# humjb_1983

首先，需要再次感谢兄弟的热情。
1、irq迁移的问题，可能是irqbalance服务做的，确实没有直接操作next指针的地方，该指针看似只有在request_irq时才会操作，然后就不会再动了。
感觉irq迁移导致问题的可能性不大。
2、irqaction中的handler解析了一下：
crash> sym ffffffff8827628b
ffffffff8827628b (t) igb_msix_rx
应该是正常的，在igb驱动中注册的处理函数，只是没有自动解析成符号。

目前看irqaction结构体中next指针的前后数据应该都是正常的，应该不会是内存越界导致的。

谢谢！

作者: Tinnal 时间: 2015-01-14 22:22
回复 1# humjb_1983

不好意思，这么久才回你。看了一下你的blog的分析过程，我也是比较认同的结论的。

作者: humjb_1983 时间: 2015-01-15 08:36

Tinnal 发表于 2015-01-14 22:22
回复 1# humjb_1983

呵呵，年底忙，感谢兄弟！

作者: gaojl0728 时间: 2015-01-15 16:19
回复 13# humjb_1983

我大概找到Crash的原因了，你想知道吗

作者: gaojl0728 时间: 2015-01-15 16:30
回复 13# humjb_1983

一不留神看错代码了，请忽略我前面的留言。

作者: super皮波 时间: 2015-01-15 18:15
大致看了一下，感觉也是1bit跳变
因为struct irqaction这个结构体，只有在共享中断号的情况下next的成员才是不为0的，但是如果是共享中断线的话，这个action中的flags不为0
并且这个结构体next前后没有被覆盖的迹象
crash> struct irqaction 0xffffffff803018a0
struct irqaction {
  handler = 0xffffffff8006e9da <timer_interrupt>,
  flags = 32,
  mask = {
bits = {0, 0, 0, 0}
  },
  name = 0xffffffff802b3dfa "timer",
  dev_id = 0x0,
  next = 0x0,
  irq = 0,
  dir = 0x0
}

作者: humjb_1983 时间: 2015-01-15 18:38

super皮波发表于 2015-01-15 18:15
大致看了一下，感觉也是1bit跳变
因为struct irqaction这个结构体，只有在共享中断号的情况下next的成员才 ...

呵呵，我也是这么想的。

欢迎光临 Chinaunix (http://bbs.chinaunix.net/)