BUG: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

BUG: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Koehrer Mathias (ETAS/ESW5)]

Hi all,

I have 3.18.13-rt10 running on a x86 PC (32bit) system.
Linux Distribution: Debian 8.1 "Jessie".
Fairly often (but not reproducible for me) I got the following kernel bug.
I looks like the systemd-journald reads some kind of /proc/PID/status file.


BUG: unable to handle kernel NULL pointer dereference at 0000001c
IP: [<c107fb62>] __try_to_take_rt_mutex+0x52/0x100
*pde = 00000000
Oops: 0000 [#1] PREEMPT SMP
Modules linked in: rtpc_dma(O) es53xx(O) nfsd nfs lockd grace sunrpc bridge stp llc e100 mii e1000 e1000e igb i2c_algo_bit ixgbe mdio ptp pps_core dca kvm_intel kvm ecikm(O) i2c_i801 pcspkr i2c_core video backlight processor coretemp autofs4 reiserfs microcode sg sd_mod ahci libahci ehci_pci ehci_hcd xhci_pci xhci_hcd fan thermal_sys hwmon
CPU: 0 PID: 1522 Comm: systemd-journal Tainted: G           O   3.18.13-rt10-2 #2
Hardware name: Supermicro X9SAE/X9SAE, BIOS 2.0b 07/10/2013
task: dff76000 ti: f4760000 task.ti: f4760000
EIP: 0060:[<c107fb62>] EFLAGS: 00010282 CPU: 0
EIP is at __try_to_take_rt_mutex+0x52/0x100
EAX: 00000000 EBX: 00000000 ECX: f4761df4 EDX: 00000000
ESI: dff76000 EDI: dfdec944 EBP: f4761dd4 ESP: f4761dc4
DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
CR0: 80050033 CR2: f8b5cbc0 CR3: 344ad000 CR4: 001407d0
Stack:
dff76000 dfdec944 dff764b0 f4761df4 f4761e28 c1404169 00000001 f4761fec
f3ba9201 dff76000 dff764b0 dff76000 00000001 00000000 00000000 f4761e00
00000000 00000000 dff76000 dfdec944 c1045b01 00000078 dff76000 f3bae000
Call Trace:
[<c1404169>] rt_spin_lock_slowlock+0xf9/0x240
[<c1045b01>] ? pin_current_cpu+0x31/0x1a0
[<c1405567>] rt_spin_lock+0x27/0x30
[<c1051508>] __lock_task_sighand+0x38/0x70
[<c119768b>] proc_pid_status+0x33b/0x620
[<c1193312>] proc_single_show+0x42/0x80
[<c1163d12>] seq_read+0x82/0x380
[<c11283fa>] ? do_mmap_pgoff+0x27a/0x350
[<c1080abd>] ? rt_up_write+0xd/0x10
[<c1163c90>] ? seq_lseek+0x1c0/0x1c0
[<c1142684>] vfs_read+0x74/0x140
[<c1142ca6>] SyS_read+0x46/0x90
[<c1405c54>] sysenter_do_call+0x12/0x12
Code: 83 cb 01 f0 0f b1 1e 39 d0 75 ee 8b 5f 0c 31 c0 83 e3 fe 74 0c 83 c4 04 5b 5e 5f 5d c3 8d 74 26 00 8b 75 f0 85 c9 74 1d 8b 57 08 <3b> 7a 1c 0f 85 93 00 00 00 89 d8 39 d1 75 db 89 ca 89 f8 e8 c6
EIP: [<c107fb62>] __try_to_take_rt_mutex+0x52/0x100 SS:ESP 0068:f4761dc4
CR2: 000000000000001c
---[ end trace 0000000000


Thanks for any support or proposals on this issue.

Mathias

Re: BUG: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Thomas Gleixner]

On Thu, 9 Jul 2015, Koehrer Mathias (ETAS/ESW5) wrote:
> BUG: unable to handle kernel NULL pointer dereference at 0000001c
> IP: [<c107fb62>] __try_to_take_rt_mutex+0x52/0x100
> *pde = 00000000
> Oops: 0000 [#1] PREEMPT SMP
> Modules linked in: rtpc_dma(O) es53xx(O) nfsd nfs lockd grace sunrpc bridge stp llc e100 mii e1000 e1000e igb i2c_algo_bit ixgbe mdio ptp pps_core dca kvm_intel kvm ecikm(O) i2c_i801 pcspkr i2c_core video backlight processor coretemp autofs4 reiserfs microcode sg sd_mod ahci libahci ehci_pci ehci_hcd xhci_pci xhci_hcd fan thermal_sys hwmon
> CPU: 0 PID: 1522 Comm: systemd-journal Tainted: G           O   3.18.13-rt10-2 #2
> Hardware name: Supermicro X9SAE/X9SAE, BIOS 2.0b 07/10/2013
> task: dff76000 ti: f4760000 task.ti: f4760000
> EIP: 0060:[<c107fb62>] EFLAGS: 00010282 CPU: 0
> EIP is at __try_to_take_rt_mutex+0x52/0x100
> EAX: 00000000 EBX: 00000000 ECX: f4761df4 EDX: 00000000
> ESI: dff76000 EDI: dfdec944 EBP: f4761dd4 ESP: f4761dc4
> DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
> CR0: 80050033 CR2: f8b5cbc0 CR3: 344ad000 CR4: 001407d0
> Stack:
> dff76000 dfdec944 dff764b0 f4761df4 f4761e28 c1404169 00000001 f4761fec
> f3ba9201 dff76000 dff764b0 dff76000 00000001 00000000 00000000 f4761e00
> 00000000 00000000 dff76000 dfdec944 c1045b01 00000078 dff76000 f3bae000
> Call Trace:
> [<c1404169>] rt_spin_lock_slowlock+0xf9/0x240
> [<c1045b01>] ? pin_current_cpu+0x31/0x1a0
> [<c1405567>] rt_spin_lock+0x27/0x30
> [<c1051508>] __lock_task_sighand+0x38/0x70
> [<c119768b>] proc_pid_status+0x33b/0x620
> [<c1193312>] proc_single_show+0x42/0x80
> [<c1163d12>] seq_read+0x82/0x380
> [<c11283fa>] ? do_mmap_pgoff+0x27a/0x350
> [<c1080abd>] ? rt_up_write+0xd/0x10
> [<c1163c90>] ? seq_lseek+0x1c0/0x1c0
> [<c1142684>] vfs_read+0x74/0x140
> [<c1142ca6>] SyS_read+0x46/0x90
> [<c1405c54>] sysenter_do_call+0x12/0x12
> Code: 83 cb 01 f0 0f b1 1e 39 d0 75 ee 8b 5f 0c 31 c0 83 e3 fe 74 0c 83 c4 04 5b 5e 5f 5d c3 8d 74 26 00 8b 75 f0 85 c9 74 1d 8b 57 08 <3b> 7a 1c 0f 85 93 00 00 00 89 d8 39 d1 75 db 89 ca 89 f8 e8 c6
> EIP: [<c107fb62>] __try_to_take_rt_mutex+0x52/0x100 SS:ESP 0068:f4761dc4
> CR2: 000000000000001c
> ---[ end trace 0000000000

Looks like the old ghosts of exit race conditions have come back to
haunt us.

I have no idea how this can happen because all protections are in
place. Can you try to reproduce that with function tracing enabled?

If the machine is still accessible you can retrieve the trace in the
usual way. Otherwise you need to enable ftrace_dump_on_oops and let it
spill out over the serial console.

Thanks,

	tglx

Re: BUG: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Josh Cartwright]

[-- Attachment #1: Type: text/plain, Size: 6770 bytes --]

On Thu, Jul 09, 2015 at 04:11:41PM +0200, Thomas Gleixner wrote:
> On Thu, 9 Jul 2015, Koehrer Mathias (ETAS/ESW5) wrote:
> > BUG: unable to handle kernel NULL pointer dereference at 0000001c
> > IP: [<c107fb62>] __try_to_take_rt_mutex+0x52/0x100
> > *pde = 00000000
> > Oops: 0000 [#1] PREEMPT SMP
> > Modules linked in: rtpc_dma(O) es53xx(O) nfsd nfs lockd grace sunrpc bridge stp llc e100 mii e1000 e1000e igb i2c_algo_bit ixgbe mdio ptp pps_core dca kvm_intel kvm ecikm(O) i2c_i801 pcspkr i2c_core video backlight processor coretemp autofs4 reiserfs microcode sg sd_mod ahci libahci ehci_pci ehci_hcd xhci_pci xhci_hcd fan thermal_sys hwmon
> > CPU: 0 PID: 1522 Comm: systemd-journal Tainted: G           O   3.18.13-rt10-2 #2
> > Hardware name: Supermicro X9SAE/X9SAE, BIOS 2.0b 07/10/2013
> > task: dff76000 ti: f4760000 task.ti: f4760000
> > EIP: 0060:[<c107fb62>] EFLAGS: 00010282 CPU: 0
> > EIP is at __try_to_take_rt_mutex+0x52/0x100
> > EAX: 00000000 EBX: 00000000 ECX: f4761df4 EDX: 00000000
> > ESI: dff76000 EDI: dfdec944 EBP: f4761dd4 ESP: f4761dc4
> > DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
> > CR0: 80050033 CR2: f8b5cbc0 CR3: 344ad000 CR4: 001407d0
> > Stack:
> > dff76000 dfdec944 dff764b0 f4761df4 f4761e28 c1404169 00000001 f4761fec
> > f3ba9201 dff76000 dff764b0 dff76000 00000001 00000000 00000000 f4761e00
> > 00000000 00000000 dff76000 dfdec944 c1045b01 00000078 dff76000 f3bae000
> > Call Trace:
> > [<c1404169>] rt_spin_lock_slowlock+0xf9/0x240
> > [<c1045b01>] ? pin_current_cpu+0x31/0x1a0
> > [<c1405567>] rt_spin_lock+0x27/0x30
> > [<c1051508>] __lock_task_sighand+0x38/0x70
> > [<c119768b>] proc_pid_status+0x33b/0x620
> > [<c1193312>] proc_single_show+0x42/0x80
> > [<c1163d12>] seq_read+0x82/0x380
> > [<c11283fa>] ? do_mmap_pgoff+0x27a/0x350
> > [<c1080abd>] ? rt_up_write+0xd/0x10
> > [<c1163c90>] ? seq_lseek+0x1c0/0x1c0
> > [<c1142684>] vfs_read+0x74/0x140
> > [<c1142ca6>] SyS_read+0x46/0x90
> > [<c1405c54>] sysenter_do_call+0x12/0x12
> > Code: 83 cb 01 f0 0f b1 1e 39 d0 75 ee 8b 5f 0c 31 c0 83 e3 fe 74 0c 83 c4 04 5b 5e 5f 5d c3 8d 74 26 00 8b 75 f0 85 c9 74 1d 8b 57 08 <3b> 7a 1c 0f 85 93 00 00 00 89 d8 39 d1 75 db 89 ca 89 f8 e8 c6
> > EIP: [<c107fb62>] __try_to_take_rt_mutex+0x52/0x100 SS:ESP 0068:f4761dc4
> > CR2: 000000000000001c
> > ---[ end trace 0000000000

I was able to trigger a similar-looking OOPs; not sure if it provides
any more meaningful data, but here it is:

 Unable to handle kernel NULL pointer dereference at virtual address 0000001c
 pgd = dd998000
 [0000001c] *pgd=1da24831, *pte=00000000, *ppte=00000000
 Internal error: Oops: 17 [#1] PREEMPT SMP ARM
 Modules linked in: ipv6 ehci_hcd
 CPU: 1 PID: 1169 Comm: busybox Not tainted 3.18.13-rt10-ni-00623-g6a5191f-dirty #8
 task: ded1cac0 ti: dea78000 task.ti: dea78000
 PC is at __try_to_take_rt_mutex+0x6c/0x150
 LR is at rt_spin_lock_slowlock+0x10c/0x29c
 pc : [<c00583bc>]    lr : [<c05291c0>]    psr: a00d0013
 sp : dea79d48  ip : 00000000  fp : dea79d64
 r10: dea79d68  r9 : dea79d68  r8 : dea79d68
 r7 : 00000000  r6 : 00000000  r5 : ded1cac0  r4 : dd93af04
 r3 : 00000000  r2 : dea79d68  r1 : dd93af10  r0 : 00000000
 Flags: NzCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment user
 Control: 18c5387d  Table: 1d99804a  DAC: 00000015
 Process busybox (pid: 1169, stack limit = 0xdea78240)
 Stack: (0xdea79d48 to 0xdea7a000)
 9d40:                   dd93af04 ded1cac0 dea78000 ded1cf50 dea79dbc dea79d68
 9d60: c05291c0 c005835c 00000001 00000000 00000000 dea79d74 00000000 00000000
 9d80: ded1cac0 dd93af04 dea79d01 00000078 dea79dac dd93aa00 debacac0 dd93af04
 9da0: dea79e60 c0768138 00000001 000003ff dea79dcc dea79dc0 c052a9d8 c05290c0
 9dc0: dea79dec dea79dd0 c0030110 c052a98c deb14580 debacac0 dee65180 deb14580
 9de0: dea79eb4 dea79df0 c01675d8 c00300d4 c011f8dc c011aae4 dea79e14 dda5bb00
 9e00: ded1cac0 df24a550 de921800 00000044 dea79e34 c012f8fc df41c600 ded9f180
 9e20: dea79e44 dea79e30 c012f8fc 002da000 dea79ee8 de921800 dea79e54 dea79e48
 9e40: beb7a178 b6e429f0 dea79e6c dea79e58 c0768138 c028f464 00000000 00000000
 9e60: 60000013 dea79e70 00000000 00000000 00000000 00000000 6c706669 2e646775
 9e80: 69746361 00006e6f 00001000 debacac0 dcafea40 dda5bb00 deb14580 c0768138
 9ea0: dea79f78 000003ff dea79ecc dea79eb8 c01684a8 c01674f8 00000001 dcafea40
 9ec0: dea79ef4 dea79ed0 c0162dd0 c0168490 c0162d7c 00000000 00000000 dea79f08
 9ee0: 00000001 deb14580 dea79f44 dea79ef8 c0133a64 c0162d88 dea79f44 deb145b0
 9f00: de921800 bec627d0 00000000 00000000 dea78000 dcafea40 dea79f3c 000003ff
 9f20: de921800 bec627d0 dea79f78 000003ff dea78000 bec627d0 dea79f74 dea79f48
 9f40: c011248c c0133888 c012d13c c012d0ac 00000000 00000000 de921800 de921800
 9f60: 000003ff bec627d0 dea79fa4 dea79f78 c0112588 c01123fc 00000000 00000000
 9f80: 0009a0a0 bec627d0 00000004 00000003 c000f384 00000000 00000000 dea79fa8
 9fa0: c000f140 c0112548 0009a0a0 bec627d0 00000004 bec627d0 000003ff 00000000
 9fc0: 0009a0a0 bec627d0 00000004 00000003 00081984 00000220 00099988 0000000b
 9fe0: 00000000 bec62784 00076be4 b6e8612c 60000010 00000004 00000000 00000000
 Backtrace:
 [<c0058350>] (__try_to_take_rt_mutex) from [<c05291c0>] (rt_spin_lock_slowlock+0x10c/0x29c)
  r7:ded1cf50 r6:dea78000 r5:ded1cac0 r4:dd93af04
 [<c05290b4>] (rt_spin_lock_slowlock) from [<c052a9d8>] (rt_spin_lock+0x58/0x5c)
  r10:000003ff r9:00000001 r8:c0768138 r7:dea79e60 r6:dd93af04 r5:debacac0
  r4:dd93aa00
 [<c052a980>] (rt_spin_lock) from [<c0030110>] (__lock_task_sighand+0x48/0x78)
 [<c00300c8>] (__lock_task_sighand) from [<c01675d8>] (do_task_stat+0xec/0x85c)
  r7:deb14580 r6:dee65180 r5:debacac0 r4:deb14580
 [<c01674ec>] (do_task_stat) from [<c01684a8>] (proc_tgid_stat+0x24/0x2c)
  r10:000003ff r9:dea79f78 r8:c0768138 r7:deb14580 r6:dda5bb00 r5:dcafea40
  r4:debacac0
 [<c0168484>] (proc_tgid_stat) from [<c0162dd0>] (proc_single_show+0x54/0xa4)
 [<c0162d7c>] (proc_single_show) from [<c0133a64>] (seq_read+0x1e8/0x468)
  r8:deb14580 r7:00000001 r6:dea79f08 r5:00000000 r4:00000000 r3:c0162d7c
 [<c013387c>] (seq_read) from [<c011248c>] (vfs_read+0x9c/0x14c)
  r10:bec627d0 r9:dea78000 r8:000003ff r7:dea79f78 r6:bec627d0 r5:de921800
  r4:000003ff
 [<c01123f0>] (vfs_read) from [<c0112588>] (SyS_read+0x4c/0x8c)
  r10:bec627d0 r8:000003ff r7:de921800 r6:de921800 r5:00000000 r4:00000000
 [<c011253c>] (SyS_read) from [<c000f140>] (ret_fast_syscall+0x0/0x30)
  r10:00000000 r8:c000f384 r7:00000003 r6:00000004 r5:bec627d0 r4:0009a0a0
 Code: 1a000036 e3520000 0a000009 e5943008 (e593101c)
 ---[ end trace 0000000000000002 ]---
 note: busybox[1169] exited with preempt_count 1

I hit it once before, but wasn't in any position to capture the logs.
The two times I hit the oops were both at boot.  I haven't seen this in
(yet?) in 4.0.5-rt4.

  Josh

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 473 bytes --]

RE: BUG: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Koehrer Mathias (ETAS/ESW5)]

Hi Thomas,

> Looks like the old ghosts of exit race conditions have come back to
> haunt us.
> 
> I have no idea how this can happen because all protections are in
> place. Can you try to reproduce that with function tracing enabled?
> 
> If the machine is still accessible you can retrieve the trace in the
> usual way. Otherwise you need to enable ftrace_dump_on_oops and let it
> spill out over the serial console.

I have been able to catch this BUG again on a different PC during a reboot. Unfortunately, it happened before I had enabled ftrace_dump_on_oops.
BTW: Is it possible to configure the tracing to be already active on boot?

[    4.844585] BUG: unable to handle kernel NULL pointer dereference at 0000001c
[    4.844598] IP: [<c107fb62>] __try_to_take_rt_mutex+0x52/0x100
[    4.844599] *pde = 00000000 
[    4.844600] Oops: 0000 [#1] PREEMPT SMP 
[    4.844620] Modules linked in: dis_irm(O+) es53xx(O) nfsd nfs lockd grace sunrpc bridge stp llc e100 mii e1000 kvm_intel kvm pcspkr psmouse i2c_i801 radeon drm_kms_helper ttm drm agpgart e1000e igb i2c_algo_bit i2c_core ixgbe mdio ptp pps_core dca parport_pc parport video backlight acpi_cpufreq processor coretemp autofs4 reiserfs microcode sg sd_mod ahci libahci ehci_pci ehci_hcd fan thermal_sys hwmon xhci_pci xhci_hcd
[    4.844621] CPU: 0 PID: 2392 Comm: ps Tainted: G           O   3.18.13-rt10-2 #1
[    4.844622] Hardware name: LENOVO 32282Z8/MAHOBAY, BIOS 9SKT70AUS 06/07/2013
[    4.844622] task: ea3d0000 ti: ea3cc000 task.ti: ea3cc000
[    4.844623] EIP: 0060:[<c107fb62>] EFLAGS: 00010282 CPU: 0
[    4.844624] EIP is at __try_to_take_rt_mutex+0x52/0x100
[    4.844625] EAX: 00000000 EBX: 00000000 ECX: ea3cdda8 EDX: 00000000
[    4.844625] ESI: ea3d0000 EDI: ea072f04 EBP: ea3cdd88 ESP: ea3cdd78
[    4.844625]  DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
[    4.844626] CR0: 80050033 CR2: 0000001c CR3: 2aff3000 CR4: 001407d0
[    4.844626] Stack:
[    4.844628]  ea3d0000 ea072f04 ea3d04b0 ea3cdda8 ea3cdddc c1404169 00000001 ea3cdfec
[    4.844629]  ea274201 ea3d0000 ea3d04b0 ea3d0000 00000001 00000000 00000000 ea3cddb4
[    4.844630]  00000000 00000000 ea3d0000 ea072f04 c1045b01 00000078 ea3d0000 ea274800
[    4.844630] Call Trace:
[    4.844633]  [<c1404169>] rt_spin_lock_slowlock+0xf9/0x240
[    4.844635]  [<c1045b01>] ? pin_current_cpu+0x31/0x1a0
[    4.844637]  [<c1405567>] rt_spin_lock+0x27/0x30
[    4.844638]  [<c1051508>] __lock_task_sighand+0x38/0x70
[    4.844640]  [<c1196662>] do_task_stat+0xf2/0xd40
[    4.844642]  [<c1069580>] ? migrate_enable+0x80/0x180
[    4.844644]  [<c11f77ac>] ? lockref_put_or_lock+0x2c/0x40
[    4.844646]  [<c1201bd2>] ? debug_smp_processor_id+0x12/0x20
[    4.844647]  [<c1045c83>] ? unpin_current_cpu+0x13/0x60
[    4.844647]  [<c1069580>] ? migrate_enable+0x80/0x180
[    4.844648]  [<c11f77ac>] ? lockref_put_or_lock+0x2c/0x40
[    4.844650]  [<c115f9f5>] ? mntput_no_expire+0x25/0x150
[    4.844651]  [<c115fb40>] ? mntput+0x20/0x40
[    4.844653]  [<c1150220>] ? path_openat+0x120/0x550
[    4.844654]  [<c1068fab>] ? get_parent_ip+0xb/0x40
[    4.844655]  [<c11979bf>] proc_tgid_stat+0x1f/0x30
[    4.844656]  [<c1193312>] proc_single_show+0x42/0x80
[    4.844657]  [<c1163d12>] seq_read+0x82/0x380
[    4.844658]  [<c1150a3d>] ? final_putname+0x1d/0x40
[    4.844659]  [<c1163c90>] ? seq_lseek+0x1c0/0x1c0
[    4.844660]  [<c1142684>] vfs_read+0x74/0x140
[    4.844661]  [<c1142ca6>] SyS_read+0x46/0x90
[    4.844662]  [<c1405c54>] sysenter_do_call+0x12/0x12
[    4.844669] Code: 83 cb 01 f0 0f b1 1e 39 d0 75 ee 8b 5f 0c 31 c0 83 e3 fe 74 0c 83 c4 04 5b 5e 5f 5d c3 8d 74 26 00 8b 75 f0 85 c9 74 1d 8b 57 08 <3b> 7a 1c 0f 85 93 00 00 00 89 d8 39 d1 75 db 89 ca 89 f8 e8 c6
[    4.844671] EIP: [<c107fb62>] __try_to_take_rt_mutex+0x52/0x100 SS:ESP 0068:ea3cdd78
[    4.844671] CR2: 000000000000001c
[    5.168516] ---[ end trace 0000000000000002 ]---
[    5.168517] note: ps[2392] exited with preempt_count 1
[    5.168554] ------------[ cut here ]-

Regards

Mathias

Re: BUG: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Sebastian Andrzej Siewior]

* Koehrer Mathias (ETAS/ESW5) | 2015-07-10 12:49:46 [+0000]:

>Hi Thomas,
Hi Mathias,

>I have been able to catch this BUG again on a different PC during a reboot. Unfortunately, it happened before I had enabled ftrace_dump_on_oops.

if you managed to trigger it that reliably, could you revert
slub_delay_ctor_on_rt.patch in the queue and try again?

Sebastian

RE: BUG: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Koehrer Mathias (ETAS/ESW5)]

> if you managed to trigger it that reliably, could you revert
> slub_delay_ctor_on_rt.patch in the queue and try again?
> 
Over the weekend I ran a test that rebooted the PC permanently.
After about 400 reboots I got another NULL pointer dereference. 
However the slub_delay_ctor_on_rt.patch has not been reverted yet.
And: This looks somehow differently than the previous BUGs.


[    3.299329] BUG: unable to handle kernel NULL pointer dereference at 0000008c
[    3.299332] IP: [<c10df66c>] function_trace_call+0xc/0x190
[    3.299334] *pde = 00000000 
[    3.299336] Oops: 0000 [#1] PREEMPT SMP 
[    3.299356] Modules linked in: e1000(+) kvm_intel kvm pcspkr psmouse i2c_i801 radeon(+) drm_kms_helper ttm drm agpgart e1000e igb i2c_algo_bit i2c_core ixgbe mdio ptp pps_core dca parport_pc parport video backlight acpi_cpufreq processor coretemp autofs4 reiserfs microcode sg sd_mod ahci libahci ehci_pci ehci_hcd xhci_pci xhci_hcd fan thermal_sys hwmon
[    3.299358] CPU: 0 PID: 1447 Comm: systemd-udevd Not tainted 3.18.13-rt10-2 #1
[    3.299359] Hardware name: LENOVO 32282Z8/MAHOBAY, BIOS 9SKT70AUS 06/07/2013
[    3.299360] task: eb76ec00 ti: eae30000 task.ti: eae30000
[    3.299361] EIP: 0060:[<c10df66c>] EFLAGS: 00010282 CPU: 0
[    3.299362] EIP is at function_trace_call+0xc/0x190
[    3.299363] EAX: c1068fe7 EBX: 00000000 ECX: c1633f80 EDX: c11f5e6c
[    3.299364] ESI: 060dbc0e EDI: 0033c321 EBP: eae31b3c ESP: eae31b20
[    3.299365]  DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
[    3.299366] CR0: 80050033 CR2: 0000008c CR3: 2ac3b000 CR4: 001407d0
[    3.299367] Stack:
[    3.299371]  c1068fec c160007b c11f007b c11f00d8 06328cee 060dbc0e 0033c321 eae31b6c
[    3.299375]  c14067da 00000000 80000001 00000000 00000001 c1068fec c1063f3b 060dbc0e
[    3.299380]  0033c321 eae31b6c 06328cee eae31b88 c11f5e6c eae31fec 00000000 00000027
[    3.299380] Call Trace:
[    3.299384]  [<c1068fec>] ? preempt_count_add+0xc/0xa0
[    3.299387]  [<c11f007b>] ? radix_tree_tag_clear+0x1b/0x110
[    3.299389]  [<c11f00d8>] ? radix_tree_tag_clear+0x78/0x110
[    3.299393]  [<c14067da>] ftrace_call+0x5/0xb
[    3.299395]  [<c1068fec>] ? preempt_count_add+0xc/0xa0
[    3.299397]  [<c1063f3b>] ? preempt_count_sub+0xb/0xd0
[    3.299400]  [<c11f5e6c>] delay_tsc+0x5c/0xf0
[    3.299402]  [<c11f5dae>] __const_udelay+0x1e/0x20
[    3.299428]  [<f0369f82>] evergreen_set_uvd_clocks+0x302/0x360 [radeon]
[    3.299450]  [<f03e3250>] uvd_v1_0_init+0x70/0x5a0 [radeon]
[    3.299471]  [<f0371339>] evergreen_startup+0x659/0x670 [radeon]
[    3.299489]  [<f03715b5>] evergreen_init+0x1c5/0x380 [radeon]
[    3.299504]  [<f02fa4e2>] radeon_device_init+0xba2/0xd70 [radeon]
[    3.299518]  [<f02f8400>] ? cail_mc_write+0x20/0x20 [radeon]
[    3.299533]  [<f02fc9ba>] radeon_driver_load_kms+0x8a/0x200 [radeon]
[    3.299541]  [<f007f7de>] drm_dev_register+0x8e/0xd0 [drm]
[    3.299548]  [<f0082389>] drm_get_pci_dev+0x79/0x1d0 [drm]
[    3.299550]  [<c113b24a>] ? kfree+0x1ba/0x1d0
[    3.299564]  [<f02f834e>] ? radeon_pci_probe+0x6e/0xa0 [radeon]
[    3.299576]  [<f02f834e>] ? radeon_pci_probe+0x6e/0xa0 [radeon]
[    3.299590]  [<f02f835c>] radeon_pci_probe+0x7c/0xa0 [radeon]
[    3.299593]  [<c121ac8f>] pci_device_probe+0x6f/0xd0
[    3.299595]  [<c11a25e5>] ? sysfs_create_link+0x25/0x50
[    3.299598]  [<c12c7a7f>] driver_probe_device+0x7f/0x3d0
[    3.299600]  [<c1069580>] ? migrate_enable+0x80/0x180
[    3.299602]  [<c121abb7>] ? pci_match_device+0xd7/0x110
[    3.299605]  [<c12c7e89>] __driver_attach+0x79/0x80
[    3.299607]  [<c12c7e10>] ? __device_attach+0x40/0x40
[    3.299609]  [<c12c5d9f>] bus_for_each_dev+0x4f/0x80
[    3.299611]  [<c12c758e>] driver_attach+0x1e/0x20
[    3.299613]  [<c12c7e10>] ? __device_attach+0x40/0x40
[    3.299615]  [<c12c71f7>] bus_add_driver+0x167/0x240
[    3.299617]  [<f0458000>] ? 0xf0458000
[    3.299619]  [<f0458000>] ? 0xf0458000
[    3.299621]  [<c12c864d>] driver_register+0x5d/0xf0
[    3.299623]  [<c121946f>] __pci_register_driver+0x5f/0x70
[    3.299629]  [<f00825bd>] drm_pci_init+0xdd/0x100 [drm]
[    3.299632]  [<f0458000>] ? 0xf0458000
[    3.299645]  [<f045808d>] radeon_init+0x8d/0xa8 [radeon]
[    3.299647]  [<c100044e>] do_one_initcall+0xae/0x1e0
[    3.299649]  [<f0458000>] ? 0xf0458000
[    3.299651]  [<c113b24a>] ? kfree+0x1ba/0x1d0
[    3.299653]  [<c112dca5>] ? __vunmap+0xa5/0xf0
[    3.299654]  [<c112dca5>] ? __vunmap+0xa5/0xf0
[    3.299657]  [<c112dca5>] ? __vunmap+0xa5/0xf0
[    3.299661]  [<c10b6a5b>] load_module+0x199b/0x21e0
[    3.299669]  [<c10b73fd>] SyS_finit_module+0x7d/0xc0
[    3.299672]  [<c1080abd>] ? rt_up_write+0xd/0x10
[    3.299678]  [<c1405c54>] sysenter_do_call+0x12/0x12
[    3.299712] Code: 85 c0 74 0f 83 f8 ff 74 05 83 e8 01 89 03 e8 6c 4c ff ff 5b 5d c3 89 f6 8d bc 27 00 00 00 00 55 89 e5 57 56 53 83 ec 10 8b 59 0c <8b> 8b 8c 00 00 00 85 c9 74 6e 89 45 ec 89 d6 64 a1 d0 f6 6b c1
[    3.299714] EIP: [<c10df66c>] function_trace_call+0xc/0x190 SS:ESP 0068:eae31b20
[    3.299715] CR2: 000000000000008c
[    3.735916] e1000 0000:04:0a.0: Receive Absolute Interrupt Delay set to 0
[    3.742722] e1000 0000:04:0a.0: Interrupt Throttling Rate (ints/sec) turned off
[    3.775061] ---[ end trace 0000000000000002 ]---


I will try again with a reverted slub_delay_ctor_on_rt.patch.
Regards

Mathias

RE: BUG: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Koehrer Mathias (ETAS/ESW5)]

[-- Attachment #1: Type: text/plain, Size: 565 bytes --]

Hi Sebastian, hi  Thomas,

> 
> >I have been able to catch this BUG again on a different PC during a reboot.
> Unfortunately, it happened before I had enabled ftrace_dump_on_oops.
> 
> if you managed to trigger it that reliably, could you revert
> slub_delay_ctor_on_rt.patch in the queue and try again?
> 

on another PC we got the kernel BUG during normal operation (not at reboot) and with this one ftrace was enabled.
Please see the output of the serial console in the attachment.
I hope this helps to identify the issue!

Regards

Mathias



[-- Attachment #2: serial-console.log.gz --]
[-- Type: application/x-gzip, Size: 33665 bytes --]

Re: BUG: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Sebastian Andrzej Siewior]

On 07/13/2015 09:39 AM, Koehrer Mathias (ETAS/ESW5) wrote:
> Hi Sebastian, hi  Thomas,

Hi Mathias,

>> if you managed to trigger it that reliably, could you revert
>> slub_delay_ctor_on_rt.patch in the queue and try again?
>>
> 
> on another PC we got the kernel BUG during normal operation (not at reboot) and with this one ftrace was enabled.
> Please see the output of the serial console in the attachment.
> I hope this helps to identify the issue!

Was this with or without the ctor patch I mentioned?

> 
> Regards
> 
> Mathias

Sebastian

RE: BUG: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Koehrer Mathias (ETAS/ESW5)]

Hi Sebastian,
> >> if you managed to trigger it that reliably, could you revert
> >> slub_delay_ctor_on_rt.patch in the queue and try again?
> >>
> >
> > on another PC we got the kernel BUG during normal operation (not at reboot) and
> with this one ftrace was enabled.
> > Please see the output of the serial console in the attachment.
> > I hope this helps to identify the issue!
> 
> Was this with or without the ctor patch I mentioned?
I was still without the reverted patch.

Mathias

Re: BUG: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Sebastian Andrzej Siewior]

On 07/13/2015 10:56 AM, Koehrer Mathias (ETAS/ESW5) wrote:
>> Was this with or without the ctor patch I mentioned?
> I was still without the reverted patch.

In that case I ignore this report unless you manage (or not) to
reproduce it without the patch.

> 
> Mathias
> 
Sebastian

Re: BUG: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Sebastian Andrzej Siewior]

* Koehrer Mathias (ETAS/ESW5) | 2015-07-13 06:18:22 [+0000]:

>> if you managed to trigger it that reliably, could you revert
>> slub_delay_ctor_on_rt.patch in the queue and try again?
>> 
>Over the weekend I ran a test that rebooted the PC permanently.
>After about 400 reboots I got another NULL pointer dereference. 
>However the slub_delay_ctor_on_rt.patch has not been reverted yet.
>And: This looks somehow differently than the previous BUGs.
>
>
>[    3.299329] BUG: unable to handle kernel NULL pointer dereference at 0000008c
>[    3.299332] IP: [<c10df66c>] function_trace_call+0xc/0x190

This is 
| static void
| function_trace_call(unsigned long ip, unsigned long parent_ip,
|                     struct ftrace_ops *op, struct pt_regs *pt_regs)
| {
|         struct trace_array *tr = op->private;
|…
| 
|         if (unlikely(!tr->function_enabled))
|                 return;

and it looks like tr is null. BUG_ON(!tr) should prove this.
Steven, is it somehow possible that on module load we get "op" set
without its private member initialized?

Sebastian
--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: BUG: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Steven Rostedt]

On Mon, 13 Jul 2015 11:12:37 +0200
Sebastian Andrzej Siewior <bigeasy@linutronix.de> wrote:

> * Koehrer Mathias (ETAS/ESW5) | 2015-07-13 06:18:22 [+0000]:
> 
> >> if you managed to trigger it that reliably, could you revert
> >> slub_delay_ctor_on_rt.patch in the queue and try again?
> >> 
> >Over the weekend I ran a test that rebooted the PC permanently.
> >After about 400 reboots I got another NULL pointer dereference. 
> >However the slub_delay_ctor_on_rt.patch has not been reverted yet.
> >And: This looks somehow differently than the previous BUGs.
> >
> >
> >[    3.299329] BUG: unable to handle kernel NULL pointer dereference at 0000008c
> >[    3.299332] IP: [<c10df66c>] function_trace_call+0xc/0x190
> 
> This is 
> | static void
> | function_trace_call(unsigned long ip, unsigned long parent_ip,
> |                     struct ftrace_ops *op, struct pt_regs *pt_regs)
> | {
> |         struct trace_array *tr = op->private;
> |…
> | 
> |         if (unlikely(!tr->function_enabled))
> |                 return;
> 
> and it looks like tr is null. BUG_ON(!tr) should prove this.
> Steven, is it somehow possible that on module load we get "op" set
> without its private member initialized?
> 

What's the test that was run, and how did it enable function tracing?

-- Steve
--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

RE: BUG: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Koehrer Mathias (ETAS/ESW5)]

Hi Steven,
> > >Over the weekend I ran a test that rebooted the PC permanently.
> > >After about 400 reboots I got another NULL pointer dereference.
> > >However the slub_delay_ctor_on_rt.patch has not been reverted yet.
> > >And: This looks somehow differently than the previous BUGs.
> > >
> > >
> > >[    3.299329] BUG: unable to handle kernel NULL pointer dereference at
> 0000008c
> > >[    3.299332] IP: [<c10df66c>] function_trace_call+0xc/0x190
> >
> > This is
> > | static void
> > | function_trace_call(unsigned long ip, unsigned long parent_ip,
> > |                     struct ftrace_ops *op, struct pt_regs *pt_regs)
> > | {
> > |         struct trace_array *tr = op->private;
> > |…
> > |
> > |         if (unlikely(!tr->function_enabled))
> > |                 return;
> >
> > and it looks like tr is null. BUG_ON(!tr) should prove this.
> > Steven, is it somehow possible that on module load we get "op" set
> > without its private member initialized?
> >
> 
> What's the test that was run, and how did it enable function tracing?

The tracing was enabled within an init script using the following bash commands:
    if ! grep -q "/sys/kernel/debug" /proc/mounts; then
        mount -t debugfs nodev /sys/kernel/debug
    fi
    if [ -d /sys/kernel/debug/tracing ]; then
        (
        cd /sys/kernel/debug/tracing
        echo "function" > current_tracer
        echo "1" > tracing_on

        echo "1" > /proc/sys/kernel/ftrace_dump_on_oops
        )
    fi


The test was to reboot the PC permanently (every minute).
The reboot has been initiated by another PC that remotely controls the PC under test.

Regards

Mathias

Re: BUG: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Steven Rostedt]

On Tue, 14 Jul 2015 07:38:46 +0000
"Koehrer Mathias (ETAS/ESW5)" <mathias.koehrer@etas.com> wrote:

> > What's the test that was run, and how did it enable function tracing?
> 
> The tracing was enabled within an init script using the following bash commands:
>     if ! grep -q "/sys/kernel/debug" /proc/mounts; then
>         mount -t debugfs nodev /sys/kernel/debug
>     fi
>     if [ -d /sys/kernel/debug/tracing ]; then
>         (
>         cd /sys/kernel/debug/tracing
>         echo "function" > current_tracer
>         echo "1" > tracing_on
> 
>         echo "1" > /proc/sys/kernel/ftrace_dump_on_oops
>         )
>     fi
> 
> 
> The test was to reboot the PC permanently (every minute).
> The reboot has been initiated by another PC that remotely controls the PC under test.
> 

How reproducible is this?

-- Steve

Re: BUG: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Mathias Koehrer]

Hi Steve!
>>> What's the test that was run, and how did it enable function tracing?
>>
>> The tracing was enabled within an init script using the following bash commands:
>>      if ! grep -q "/sys/kernel/debug" /proc/mounts; then
>>          mount -t debugfs nodev /sys/kernel/debug
>>      fi
>>      if [ -d /sys/kernel/debug/tracing ]; then
>>          (
>>          cd /sys/kernel/debug/tracing
>>          echo "function" > current_tracer
>>          echo "1" > tracing_on
>>
>>          echo "1" > /proc/sys/kernel/ftrace_dump_on_oops
>>          )
>>      fi
>>
>>
>> The test was to reboot the PC permanently (every minute).
>> The reboot has been initiated by another PC that remotely controls the PC under test.
>>
>
> How reproducible is this?
Unfortunately this is not really reproducable.
I caught this bug after approx. 400 reboots while hunting another bug...

Regards

Mathias

Re: BUG: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Steven Rostedt]

On Tue, 14 Jul 2015 16:24:54 +0200
"Mathias Koehrer" <mathias.koehrer@etas.com> wrote:

> > How reproducible is this?
> Unfortunately this is not really reproducable.
> I caught this bug after approx. 400 reboots while hunting another bug...

Can you send me your config.

Thanks!

-- Steve

RE: BUG: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Koehrer Mathias (ETAS/ESW5)]

[-- Attachment #1: Type: text/plain, Size: 214 bytes --]

Hi Steve,
> > Unfortunately this is not really reproducable.
> > I caught this bug after approx. 400 reboots while hunting another bug...
> 
> Can you send me your config.
here it is...

Regards

Mathias

[-- Attachment #2: config.i386-v3.18.gz --]
[-- Type: application/x-gzip, Size: 22792 bytes --]

Re: BUG: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Mathias Koehrer]

Hi Sebastian,

>>> Was this with or without the ctor patch I mentioned?
>> I was still without the reverted patch.
>
> In that case I ignore this report unless you manage (or not) to
> reproduce it without the patch.
since I have reverted the patch the BUG has not occurred anymore.
Even if this is not a proof that this was the reason, it improved the 
stability.

Regards

Mathias

AW: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[eg Engleder Gerhard]

Hello Sebastian,

similar situation here with 3.18.11-rt7. The problem occurred once so far.

<1>[127209.359676] BUG: unable to handle kernel NULL pointer dereference at 0000001c
<1>[127209.359685] IP: [<c107ada9>] __try_to_take_rt_mutex.part.15+0x19/0x110
<4>[127209.359687] *pde = 00000000 
<4>[127209.359689] Oops: 0000 [#1] PREEMPT SMP 
<4>[127209.359716] Modules linked in: tun krfb serport max6639 rtc_isl12058 ramoops reed_solomon kmmi_cp300 led_class kbatt_leg i2c_keba_leg at25 m25p80 spi_nor ktick_cp300 kspimaster ksram kspi2 ecm cp300 ecmpci powerfail i2c_i801 video backlight processor adt7475 hwmon_vid emc1403 regmap_i2c coretemp loop fuse autofs4 uvesafb cfbfillrect cfbimgblt cn cfbcopyarea sg sd_mod ata_generic usb_storage ata_piix ehci_pci ehci_hcd e1000e ptp pps_core thermal thermal_sys hwmon
<0>[127209.359721] CPU: 0 PID: 2254 Comm: varpvprf Not tainted 3.18.0-none-keba-rt-686 #1 KEBA 3.18.11-1~~Test3+~d8
<0>[127209.359722] Hardware name:    /BM67/BS67/TM67/TS67, BIOS BH67R98 17/12/2012
<0>[127209.359724] task: f5879880 ti: f504c000 task.ti: f504c000
<4>[127209.359727] EIP: 0060:[<c107ada9>] EFLAGS: 00010286 CPU: 0
<4>[127209.359730] EIP is at __try_to_take_rt_mutex.part.15+0x19/0x110
<4>[127209.359732] EAX: f5170504 EBX: f5170504 ECX: f504dda0 EDX: 00000000
<4>[127209.359733] ESI: f5879880 EDI: f5879d2c EBP: f504dd84 ESP: f504dd74
<4>[127209.359735]  DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
<4>[127209.359737] CR0: 80050033 CR2: 0000001c CR3: 328cc000 CR4: 000407d0
<0>[127209.359737] Stack:
<4>[127209.359742]  d84b24c0 f5170504 d84b24c0 f5879d2c f504dde0 c14ad99c 00000001 f5879880
<4>[127209.359746]  f504dfec f5879880 f5879d2c 00000001 00000000 00000000 f504ddac 00000000
<4>[127209.359750]  00000000 f5879880 f5170504 11111101 11111111 00000000 11111111 00000078
<0>[127209.359751] Call Trace:
<4>[127209.359759]  [<c14ad99c>] rt_spin_lock_slowlock+0x1ac/0x2f0
<4>[127209.359765]  [<c14aee9d>] rt_spin_lock+0xd/0x10
<4>[127209.359769]  [<c104f5d8>] __lock_task_sighand+0x38/0x70
<4>[127209.359774]  [<c118ea82>] do_task_stat+0xf2/0xd30
<4>[127209.359778]  [<c14ada84>] ? rt_spin_lock_slowlock+0x294/0x2f0
<4>[127209.359783]  [<c1156785>] ? mntput_no_expire+0x25/0x150
<4>[127209.359788]  [<c10649e5>] ? preempt_count_sub+0x45/0x50
<4>[127209.359792]  [<c1064f00>] ? migrate_enable+0x80/0x180
<4>[127209.359797]  [<c12b6607>] ? __percpu_counter_add+0xa7/0xf0
<4>[127209.359801]  [<c14aeb85>] ? _raw_spin_lock+0x15/0x60
<4>[127209.359805]  [<c14adcb0>] ? rt_mutex_slowlock+0x1d0/0x310
<4>[127209.359809]  [<c10649e5>] ? preempt_count_sub+0x45/0x50
<4>[127209.359812]  [<c14adcb0>] ? rt_mutex_slowlock+0x1d0/0x310
<4>[127209.359817]  [<c118fdbf>] proc_tid_stat+0x1f/0x30
<4>[127209.359820]  [<c118b7e2>] proc_single_show+0x42/0x80
<4>[127209.359825]  [<c115aab2>] seq_read+0x82/0x380
<4>[127209.359829]  [<c115aa30>] ? seq_lseek+0x1c0/0x1c0
<4>[127209.359834]  [<c1138714>] vfs_read+0x74/0x140
<4>[127209.359838]  [<c14aef9d>] ? _mutex_lock+0xd/0x10
<4>[127209.359842]  [<c1138d36>] SyS_read+0x46/0x90
<4>[127209.359847]  [<c14af59c>] sysenter_do_call+0x12/0x12
<0>[127209.359874] Code: 76 00 0f 0b 8d b4 26 00 00 00 00 8d bc 27 00 00 00 00 55 89 e5 57 56 53 83 ec 04 66 66 66 66 90 85 c9 89 c3 89 d6 74 22 8b 50 08 <3b> 42 1c 0f 85 ce 00 00 00 31 c0 39 d1 0f 84 cc 00 00 00 83 c4
<0>[127209.359879] EIP: [<c107ada9>] __try_to_take_rt_mutex.part.15+0x19/0x110 SS:ESP 0068:f504dd74
<4>[127209.359880] CR2: 000000000000001c
<4>[127209.396217] ---[ end trace 0000000000000002 ]---

regards, Gerhard Engleder

Re: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Sebastian Andrzej Siewior]

* eg Engleder Gerhard | 2015-07-20 09:38:35 [+0200]:

>Hello Sebastian,
Hi Gerhard,

>similar situation here with 3.18.11-rt7. The problem occurred once so far.

Is this _with_ or _without_ the patch in question?

>regards, Gerhard Engleder

Sebastian

AW: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[eg Engleder Gerhard]

Hello Sebastian,

> >Hello Sebastian,
> Hi Gerhard,
> 
> >similar situation here with 3.18.11-rt7. The problem occurred once so far.
> 
> Is this _with_ or _without_ the patch in question?

With the patch. slub_delay_ctor_on_rt.patch is applied. It is 3.18.11-rt7 with additional drivers
for our hardware.

> >regards, Gerhard Engleder
> 
> Sebastian

regards, Gerhard

RE: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Koehrer Mathias (ETAS/ESW5)]

Hi all,
> > >similar situation here with 3.18.11-rt7. The problem occurred once so far.
> >
> > Is this _with_ or _without_ the patch in question?
> 
> With the patch. slub_delay_ctor_on_rt.patch is applied. It is 3.18.11-rt7 with
> additional drivers
> for our hardware.

Since I have removed the slub_delay_ctor_on_rt.patch from 3.18.13-rt10 I have never seen this issue anymore on our systems.

Now I had a look at the latest 3.18.17-rt14: Here I do not see that patch anymore.
Has it been removed from the patchset? 
Is there still a need to ignore one of the patches?
Neither in the announcement to 3.18.16-rt13 nor to 3.18.17-rt14 I read any comment on that.

Regards

Mathias

Re: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Steven Rostedt]

On Wed, 22 Jul 2015 06:26:42 +0000
"Koehrer Mathias (ETAS/ESW5)" <mathias.koehrer@etas.com> wrote:

> Hi all,
> > > >similar situation here with 3.18.11-rt7. The problem occurred once so far.
> > >
> > > Is this _with_ or _without_ the patch in question?
> > 
> > With the patch. slub_delay_ctor_on_rt.patch is applied. It is 3.18.11-rt7 with
> > additional drivers
> > for our hardware.
> 
> Since I have removed the slub_delay_ctor_on_rt.patch from 3.18.13-rt10 I have never seen this issue anymore on our systems.

>From my files, that is this patch:

----
From: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
Subject: slub: delay ctor until the object is requested

It seems that allocation of plenty objects causes latency on ARM since that code can not be preempted

Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
---
 mm/slub.c |    6 ++++++
 1 file changed, 6 insertions(+)

--- a/mm/slub.c
+++ b/mm/slub.c
@@ -1376,8 +1376,10 @@ static void setup_object(struct kmem_cac
                                void *object)
 {
        setup_object_debug(s, page, object);
+#ifndef CONFIG_PREEMPT_RT_FULL
        if (unlikely(s->ctor))
                s->ctor(object);
+#endif
 }
 
 static struct page *new_slab(struct kmem_cache *s, gfp_t flags, int node)
@@ -2499,6 +2501,10 @@ static __always_inline void *slab_alloc_
 
        if (unlikely(gfpflags & __GFP_ZERO) && object)
                memset(object, 0, s->object_size);
+#ifdef CONFIG_PREEMPT_RT_FULL
+       if (unlikely(s->ctor) && object)
+               s->ctor(object);
+#endif
 
        slab_post_alloc_hook(s, gfpflags, object);
----


> 
> Now I had a look at the latest 3.18.17-rt14: Here I do not see that patch anymore.

It's still there. Note, that when I pull -rt into stable, I do a
 git quiltimport, which renames the patch set. It's now called:

 0089-slub-delay-ctor-until-the-object-is-requested.patch

-- Steve

> Has it been removed from the patchset? 
> Is there still a need to ignore one of the patches?
> Neither in the announcement to 3.18.16-rt13 nor to 3.18.17-rt14 I read any comment on that.
> 
> Regards
> 
> Mathias

Re: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Thomas Gleixner]

On Wed, 22 Jul 2015, Steven Rostedt wrote:
> It's still there. Note, that when I pull -rt into stable, I do a
>  git quiltimport, which renames the patch set. It's now called:
> 
>  0089-slub-delay-ctor-until-the-object-is-requested.patch

>From the 4.0.8-rt6 announce:

- The delayed kmem_cache constructor caused problems. Steven Rostedt
  reported problems versus the signal handling code and Koehrer
  Mathias reported the same. The patch in question has been reverted
  and a patch currently sitting in -mm has been added which provides
  the same functionality (running the constructor with enabled
  interrupts). Patch provided by Thomas Gleixner. 

The stable trees which carry the delay-ctor patches should be updated
to this.

Reverting the patch at least prevents the BUG. Latencywise the slub patch

   mm-slub-move-slab-initialization-into-irq-enabled-re.patch

is the one which wants to be ported back.

Thanks,

	tglx

Re: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Steven Rostedt]

On Fri, 24 Jul 2015 21:02:26 +0200 (CEST)
Thomas Gleixner <tglx@linutronix.de> wrote:

> On Wed, 22 Jul 2015, Steven Rostedt wrote:
> > It's still there. Note, that when I pull -rt into stable, I do a
> >  git quiltimport, which renames the patch set. It's now called:
> > 
> >  0089-slub-delay-ctor-until-the-object-is-requested.patch
> 
> >From the 4.0.8-rt6 announce:
> 
> - The delayed kmem_cache constructor caused problems. Steven Rostedt
>   reported problems versus the signal handling code and Koehrer
>   Mathias reported the same. The patch in question has been reverted
>   and a patch currently sitting in -mm has been added which provides
>   the same functionality (running the constructor with enabled
>   interrupts). Patch provided by Thomas Gleixner. 
> 
> The stable trees which carry the delay-ctor patches should be updated
> to this.
> 
> Reverting the patch at least prevents the BUG. Latencywise the slub patch
> 
>    mm-slub-move-slab-initialization-into-irq-enabled-re.patch
> 
> is the one which wants to be ported back.
> 

OK, thanks.

Just to let people know. I'm going to be traveling next week and when I
get back in August, my top priority is to work on the stable patches.
For 3.18, I'll be looking at the patches that have been emailed to the
list, and I want to fix NO_HZ for 3.10-3.14.

I'll be also looking at the patches in the latest development RT
release that needs to be backported.

-- Steve

Re: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Gratian Crisan]

On 07/24/2015 02:21 PM, Steven Rostedt wrote:
> On Fri, 24 Jul 2015 21:02:26 +0200 (CEST)
> Thomas Gleixner <tglx@linutronix.de> wrote:
> 
>> On Wed, 22 Jul 2015, Steven Rostedt wrote:
>>> It's still there. Note, that when I pull -rt into stable, I do a
>>>  git quiltimport, which renames the patch set. It's now called:
>>>
>>>  0089-slub-delay-ctor-until-the-object-is-requested.patch
>>
>> >From the 4.0.8-rt6 announce:
>>
>> - The delayed kmem_cache constructor caused problems. Steven Rostedt
>>   reported problems versus the signal handling code and Koehrer
>>   Mathias reported the same. The patch in question has been reverted
>>   and a patch currently sitting in -mm has been added which provides
>>   the same functionality (running the constructor with enabled
>>   interrupts). Patch provided by Thomas Gleixner. 
>>
>> The stable trees which carry the delay-ctor patches should be updated
>> to this.
>>
>> Reverting the patch at least prevents the BUG. Latencywise the slub patch
>>
>>    mm-slub-move-slab-initialization-into-irq-enabled-re.patch
>>
>> is the one which wants to be ported back.
>>
> 
> OK, thanks.
> 
> Just to let people know. I'm going to be traveling next week and when I
> get back in August, my top priority is to work on the stable patches.
> For 3.18, I'll be looking at the patches that have been emailed to the
> list, and I want to fix NO_HZ for 3.10-3.14.
> 

In case it saves you some work, we've had some success getting NO_HZ to
work on 3.14 (x86_64) after back-porting the following commit:

3010279f0fc36f0388872203e63ca49912f648fd x86: Tell irq work about self
IPI support

-Gratian

Re: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Steven Rostedt]

On Fri, 24 Jul 2015 15:21:18 -0500
Gratian Crisan <gratian.crisan@ni.com> wrote:

> 
> In case it saves you some work, we've had some success getting NO_HZ to
> work on 3.14 (x86_64) after back-porting the following commit:
> 
> 3010279f0fc36f0388872203e63ca49912f648fd x86: Tell irq work about self
> IPI support

Thanks, I marked this email so that I see it when I get back.

-- Steve

Re: unable to handle kernel NULL pointer dereference on 3.18.13-rt10

[Steven Rostedt]

On Fri, 24 Jul 2015 21:02:26 +0200 (CEST)
Thomas Gleixner <tglx@linutronix.de> wrote:

> On Wed, 22 Jul 2015, Steven Rostedt wrote:
> > It's still there. Note, that when I pull -rt into stable, I do a
> >  git quiltimport, which renames the patch set. It's now called:
> > 
> >  0089-slub-delay-ctor-until-the-object-is-requested.patch
> 
> >From the 4.0.8-rt6 announce:
> 
> - The delayed kmem_cache constructor caused problems. Steven Rostedt
>   reported problems versus the signal handling code and Koehrer
>   Mathias reported the same. The patch in question has been reverted
>   and a patch currently sitting in -mm has been added which provides
>   the same functionality (running the constructor with enabled
>   interrupts). Patch provided by Thomas Gleixner. 
> 
> The stable trees which carry the delay-ctor patches should be updated
> to this.
> 
> Reverting the patch at least prevents the BUG. Latencywise the slub patch
> 
>    mm-slub-move-slab-initialization-into-irq-enabled-re.patch
> 
> is the one which wants to be ported back.
> 

OK, I hope I did this right. Please go and test the latest 3.18-rc to
see if things work better.

To build 3.18.18-rt16-rc1 directly, the following patches should be applied:

  http://www.kernel.org/pub/linux/kernel/v3.x/linux-3.18.tar.xz

  http://www.kernel.org/pub/linux/kernel/v3.x/patch-3.18.18.xz

  http://www.kernel.org/pub/linux/kernel/projects/rt/3.18/patch-3.18.18-rt16-rc1.patch.xz

You can also build from 3.18.18-rt15 by applying the incremental patch:

http://www.kernel.org/pub/linux/kernel/projects/rt/3.18/incr/patch-3.18.18-rt15-rt16-rc1.patch.xz


-- Steve