2015-07-05 18:34:05

by Arthur Marsh

[permalink] [raw]
Subject: lock-up with module: Optimize __module_address() using a latched RB-tree

On this machine, a single core Athlon 64 with a 32 bit current Linus'
git head kernel, I get a lock-up early in the boot process. (A dmesg
output of a successful boot-up of kernel 4.1.0 up to and slightly passed
the point where the git head kernel locks up is attached).

A photo of the lock-up appears at:

http://www.users.on.net/~arthur.marsh/20150706462.jpg


git-bisect reveals the bad commit as:


git bisect good
93c2e105f6bcee231c951ba0e56e84505c4b0483 is the first bad commit
commit 93c2e105f6bcee231c951ba0e56e84505c4b0483
Author: Peter Zijlstra <[email protected]>
Date: Wed May 27 11:09:37 2015 +0930

module: Optimize __module_address() using a latched RB-tree

Currently __module_address() is using a linear search through all
modules in order to find the module corresponding to the provided
address. With a lot of modules this can take a lot of time.

One of the users of this is kernel_text_address() which is employed
in many stack unwinders; which in turn are used by perf-callchain and
ftrace (possibly from NMI context).

So by optimizing __module_address() we optimize many stack unwinders
which are used by both perf and tracing in performance sensitive code.

Cc: Rusty Russell <[email protected]>
Cc: Steven Rostedt <[email protected]>
Cc: Mathieu Desnoyers <[email protected]>
Cc: Oleg Nesterov <[email protected]>
Cc: "Paul E. McKenney" <[email protected]>
Signed-off-by: Peter Zijlstra (Intel) <[email protected]>
Signed-off-by: Rusty Russell <[email protected]>

:040000 040000 1d6863a47d8521a4edbe44f9e7c3422ad1421d61
a209090da5e67f56f0997671f5a8b510338511ba M include
:040000 040000 da680638e9cebc8da54d43cc0e67b77b953430fa
31063f7ed575d22f0d27b24c76b9a0fb68c7cd40 M kernel


I am happy to supply further details and run further tests.

Arthur.


Attachments:
dmesg20150706.txt (43.23 kB)

2015-07-06 07:19:33

by Peter Zijlstra

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree

On Mon, Jul 06, 2015 at 04:03:45AM +0930, Arthur Marsh wrote:
> I am happy to supply further details and run further tests.

A .config and gcc version might be a good start. I'll see if 32bit
userspace in KVM can reproduce.

2015-07-06 07:36:06

by Arthur Marsh

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree



Peter Zijlstra wrote on 06/07/15 16:49:
> On Mon, Jul 06, 2015 at 04:03:45AM +0930, Arthur Marsh wrote:
>> I am happy to supply further details and run further tests.
>
> A .config and gcc version might be a good start. I'll see if 32bit
> userspace in KVM can reproduce.
>

Thanks, details are:

gcc version 5.1.1 20150616 (Debian 5.1.1-11)

(compiled on x86-64 using:
CONCURRENCY_LEVEL=4 DEB_HOST_ARCH=i386 \
MAKEFLAGS="CC=gcc-5 LD=ld.gold KCFLAGS=-march=athlon64" make-kpkg \
--initrd --config menuconfig --arch i386 \
--cross-compile - linux-image

)

.config from a test build near the problem commit attached.

Arthur.


Attachments:
config-4.1.0-rc5+ (158.37 kB)

2015-07-06 07:55:54

by Arthur Marsh

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree

Apologies if a duplicate, mailing list did not like the large .config.

Peter Zijlstra wrote on 06/07/15 16:49:
> On Mon, Jul 06, 2015 at 04:03:45AM +0930, Arthur Marsh wrote:
>> I am happy to supply further details and run further tests.
>
> A .config and gcc version might be a good start. I'll see if 32bit
> userspace in KVM can reproduce.
>

Thanks, details are:

gcc version 5.1.1 20150616 (Debian 5.1.1-11)

(compiled on x86-64 using:
CONCURRENCY_LEVEL=4 DEB_HOST_ARCH=i386 \
MAKEFLAGS="CC=gcc-5 LD=ld.gold KCFLAGS=-march=athlon64" make-kpkg \
--initrd --config menuconfig --arch i386 \
--cross-compile - linux-image

)

.config from a test build near the problem commit is at
http://www.users.on.net/~arthur.marsh/config-4.1.0-rc5+


Arthur.

2015-07-06 07:57:58

by Peter Zijlstra

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree

On Mon, Jul 06, 2015 at 09:19:11AM +0200, Peter Zijlstra wrote:
> On Mon, Jul 06, 2015 at 04:03:45AM +0930, Arthur Marsh wrote:
> > I am happy to supply further details and run further tests.
>
> A .config and gcc version might be a good start. I'll see if 32bit
> userspace in KVM can reproduce.

So I build i386_defconfig and i386_defconfig + CONFIG_SMP=n, installed
them in an old gentoo-stage3 userland diskimage and booted it with KVM
with only a single CPU, both booted just fine. Then I loaded a module
(iptable_nat) and that too worked on both.

So I'm a bit at a loss and will need more details.

Sadly I do not have access to AMD hardware of that vintage.

2015-07-06 08:12:23

by Peter Zijlstra

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree

On Mon, Jul 06, 2015 at 09:19:11AM +0200, Peter Zijlstra wrote:
> On Mon, Jul 06, 2015 at 04:03:45AM +0930, Arthur Marsh wrote:
> > I am happy to supply further details and run further tests.
>
> A .config and gcc version might be a good start. I'll see if 32bit
> userspace in KVM can reproduce.

If you can, can you also provide your bzImage and initrd, that would get
me closer to your setup. Feel free to provide those offlist if that's
better for you.

For the kernel that goes *Boom* obviously ;-)

2015-07-06 08:48:34

by Arthur Marsh

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree



Peter Zijlstra wrote on 06/07/15 17:42:
> On Mon, Jul 06, 2015 at 09:19:11AM +0200, Peter Zijlstra wrote:
>> On Mon, Jul 06, 2015 at 04:03:45AM +0930, Arthur Marsh wrote:
>>> I am happy to supply further details and run further tests.
>>
>> A .config and gcc version might be a good start. I'll see if 32bit
>> userspace in KVM can reproduce.
>
> If you can, can you also provide your bzImage and initrd, that would get
> me closer to your setup. Feel free to provide those offlist if that's
> better for you.
>
> For the kernel that goes *Boom* obviously ;-)
>

I hope that these files are what are useful to you:

http://www.users.on.net/~arthur.marsh/config-4.1.0+
http://www.users.on.net/~arthur.marsh/initrd.img-4.1.0+
http://www.users.on.net/~arthur.marsh/vmlinuz-4.1.0+

This kernel does go boom, after it locks up I have to do a major power
down, pull out the graphics card, reboot, shutdown, replace graphics
card to get things working again properly.

Arthur.

2015-07-06 09:01:38

by Peter Zijlstra

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree

On Mon, Jul 06, 2015 at 06:17:44PM +0930, Arthur Marsh wrote:

> This kernel does go boom, after it locks up I have to do a major power down,
> pull out the graphics card, reboot, shutdown, replace graphics card to get
> things working again properly.

*blink* that seems radical....

2015-07-06 10:04:56

by Peter Zijlstra

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree

On Mon, Jul 06, 2015 at 04:03:45AM +0930, Arthur Marsh wrote:
> On this machine, a single core Athlon 64 with a 32 bit current Linus' git
> head kernel, I get a lock-up early in the boot process. (A dmesg output of a
> successful boot-up of kernel 4.1.0 up to and slightly passed the point where
> the git head kernel locks up is attached).
>
> A photo of the lock-up appears at:
>
> http://www.users.on.net/~arthur.marsh/20150706462.jpg

So building a kernel with your .config (and a similar GCC) I was able to
match up the Code: with actual compiler output.

The faulting instruction is a dereference of mod->module_core through:

__modules_address()
mod_find()
latch_tree_find()
mod_tree_comp()
__mod_tree_val()

20e0: 8b 90 44 01 00 00 mov 0x144(%eax),%edx

Now eax is NULL, which will have given you the splat.

The curious thing is that the mod pointer is obtained from the
mod_tree_node structure:

20d0: 8b 46 fc mov -0x4(%esi),%eax

And esi looks like a regular kernel pointer.

Furthermore, we explicitly set the mod pointers in mod_tree_insert()
before linking in the nodes.

This all has the smell of memory corruption, this gfx card you need to
pull, you're not accidentally using a binary driver for that?

2015-07-06 10:11:45

by Arthur Marsh

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree



Peter Zijlstra wrote on 06/07/15 19:34:
> On Mon, Jul 06, 2015 at 04:03:45AM +0930, Arthur Marsh wrote:
>> On this machine, a single core Athlon 64 with a 32 bit current Linus' git
>> head kernel, I get a lock-up early in the boot process. (A dmesg output of a
>> successful boot-up of kernel 4.1.0 up to and slightly passed the point where
>> the git head kernel locks up is attached).
>>
>> A photo of the lock-up appears at:
>>
>> http://www.users.on.net/~arthur.marsh/20150706462.jpg
>
> So building a kernel with your .config (and a similar GCC) I was able to
> match up the Code: with actual compiler output.
>
> The faulting instruction is a dereference of mod->module_core through:
>
> __modules_address()
> mod_find()
> latch_tree_find()
> mod_tree_comp()
> __mod_tree_val()
>
> 20e0: 8b 90 44 01 00 00 mov 0x144(%eax),%edx
>
> Now eax is NULL, which will have given you the splat.
>
> The curious thing is that the mod pointer is obtained from the
> mod_tree_node structure:
>
> 20d0: 8b 46 fc mov -0x4(%esi),%eax
>
> And esi looks like a regular kernel pointer.
>
> Furthermore, we explicitly set the mod pointers in mod_tree_insert()
> before linking in the nodes.
>
> This all has the smell of memory corruption, this gfx card you need to
> pull, you're not accidentally using a binary driver for that?
>

No, it's the standard kernel radeon driver.

If it's of any use I can reboot the machine with the kernel that goes
boom and the video card removed.

Arthur.

2015-07-06 10:32:52

by Peter Zijlstra

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree

On Mon, Jul 06, 2015 at 07:41:38PM +0930, Arthur Marsh wrote:
> No, it's the standard kernel radeon driver.
>
> If it's of any use I can reboot the machine with the kernel that goes boom
> and the video card removed.

You're saying the same kernel boots without issue if you remove the
Radeon?

Most peculiar...

2015-07-06 11:27:04

by Arthur Marsh

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree



Peter Zijlstra wrote on 06/07/15 20:02:
> On Mon, Jul 06, 2015 at 07:41:38PM +0930, Arthur Marsh wrote:
>> No, it's the standard kernel radeon driver.
>>
>> If it's of any use I can reboot the machine with the kernel that goes boom
>> and the video card removed.
>
> You're saying the same kernel boots without issue if you remove the
> Radeon?
>
> Most peculiar...
>

No, I had previously suspected another card (the DPT SCSI card with eata
driver) and pulled that out to eliminate that as a possibility.

I just pulled out the Radeon 9200SE video card and in a couple of
separate boot attempts with the kernel that goes boom saw very similar
output:

http://www.users.on.net/~arthur.marsh/20150706465.jpg
http://www.users.on.net/~arthur.marsh/20150706466.jpg

Arthur.

2015-07-07 05:30:04

by Arthur Marsh

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree

I had a single, non-reproducible case of the same lock-up happening on
my other machine running the Linus git head kernel in 64-bit mode.

The kernel was built very similarly to the 32-bit mode kernel, using:

CONCURRENCY_LEVEL=4 MAKEFLAGS="CC=gcc-5 LD=ld.gold
KCFLAGS=-march=athlon64" \
make-kpkg --config menuconfig --initrd linux-image


That machine has the following cpu:

processor : 0
vendor_id : AuthenticAMD
cpu family : 16
model : 5
model name : AMD Athlon(tm) II X4 640 Processor
stepping : 3
microcode : 0x10000c8
cpu MHz : 3000.000
cache size : 512 KB
physical id : 0
siblings : 4
core id : 0
cpu cores : 4
apicid : 0
initial apicid : 0
fpu : yes
fpu_exception : yes
cpuid level : 5
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov
pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt
pdpe1gb rdtscp lm 3dnowext 3dnow constant_tsc rep_good nopl nonstop_tsc
extd_apicid pni monitor cx16 popcnt lahf_lm cmp_legacy svm extapic
cr8_legacy abm sse4a misalignsse 3dnowprefetch osvw ibs skinit wdt
hw_pstate npt lbrv svm_lock nrip_save vmmcall
bugs : tlb_mmatch apic_c1e fxsave_leak sysret_ss_attrs
bogomips : 6015.47
TLB size : 1024 4K pages
clflush size : 64
cache_alignment : 64
address sizes : 48 bits physical, 48 bits virtual
power management: ts ttp tm stc 100mhzsteps hwpstate

The start of dmesg shows:

[ 0.000000] Initializing cgroup subsys cpuset
[ 0.000000] Initializing cgroup subsys cpu
[ 0.000000] Initializing cgroup subsys cpuacct
[ 0.000000] Linux version 4.2.0-rc1+ (root@am64) (gcc version 5.1.1
20150622 (Debian 5.1.1-12) ) #1815 SMP PREEMPT Tue Jul 7 13:13:00 ACST 2015
[ 0.000000] Command line: BOOT_IMAGE=/vmlinuz-4.2.0-rc1+
root=UUID=39706f53-7c27-4310-b22a-36c7b042d1a1 ro radeon.audio=1
[ 0.000000] tseg: 0000000000
[ 0.000000] x86/fpu: Legacy x87 FPU detected.
[ 0.000000] x86/fpu: Using 'lazy' FPU context switches.
[ 0.000000] e820: BIOS-provided physical RAM map:
[ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009efff] usable
[ 0.000000] BIOS-e820: [mem 0x000000000009f000-0x000000000009ffff]
reserved
[ 0.000000] BIOS-e820: [mem 0x00000000000e4000-0x00000000000fffff]
reserved
[ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000cffaffff] usable
[ 0.000000] BIOS-e820: [mem 0x00000000cffb0000-0x00000000cffbdfff]
ACPI data
[ 0.000000] BIOS-e820: [mem 0x00000000cffbe000-0x00000000cffdffff]
ACPI NVS
[ 0.000000] BIOS-e820: [mem 0x00000000cffe0000-0x00000000cfffffff]
reserved
[ 0.000000] BIOS-e820: [mem 0x00000000ff700000-0x00000000ffffffff]
reserved
[ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x000000022fffffff] usable
[ 0.000000] NX (Execute Disable) protection: active
[ 0.000000] SMBIOS 2.5 present.
[ 0.000000] DMI: System manufacturer System Product Name/M3A78 PRO,
BIOS 1701 01/27/2011
[ 0.000000] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
[ 0.000000] e820: remove [mem 0x000a0000-0x000fffff] usable
[ 0.000000] e820: last_pfn = 0x230000 max_arch_pfn = 0x400000000
[ 0.000000] MTRR default type: uncachable
[ 0.000000] MTRR fixed ranges enabled:
[ 0.000000] 00000-9FFFF write-back
[ 0.000000] A0000-EFFFF uncachable
[ 0.000000] F0000-FFFFF write-protect
[ 0.000000] MTRR variable ranges enabled:
[ 0.000000] 0 base 000000000000 mask FFFF80000000 write-back
[ 0.000000] 1 base 000080000000 mask FFFFC0000000 write-back
[ 0.000000] 2 base 0000C0000000 mask FFFFF0000000 write-back
[ 0.000000] 3 disabled
[ 0.000000] 4 disabled
[ 0.000000] 5 disabled
[ 0.000000] 6 disabled
[ 0.000000] 7 disabled
[ 0.000000] TOM2: 0000000230000000 aka 8960M
[ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WC UC-
WT
[ 0.000000] e820: update [mem 0xd0000000-0xffffffff] usable ==> reserved
[ 0.000000] e820: last_pfn = 0xcffb0 max_arch_pfn = 0x400000000
[ 0.000000] found SMP MP-table at [mem 0x000ff780-0x000ff78f] mapped
at [ffff8800000ff780]
[ 0.000000] Base memory trampoline at [ffff880000098000] 98000 size 28672
[ 0.000000] Using GB pages for direct mapping
[ 0.000000] init_memory_mapping: [mem 0x00000000-0x000fffff]
[ 0.000000] [mem 0x00000000-0x000fffff] page 4k
[ 0.000000] BRK [0x0292e000, 0x0292efff] PGTABLE
[ 0.000000] BRK [0x0292f000, 0x0292ffff] PGTABLE
[ 0.000000] BRK [0x02930000, 0x02930fff] PGTABLE
[ 0.000000] init_memory_mapping: [mem 0x22fe00000-0x22fffffff]
[ 0.000000] [mem 0x22fe00000-0x22fffffff] page 2M
[ 0.000000] BRK [0x02931000, 0x02931fff] PGTABLE
[ 0.000000] init_memory_mapping: [mem 0x220000000-0x22fdfffff]
[ 0.000000] [mem 0x220000000-0x22fdfffff] page 2M
[ 0.000000] init_memory_mapping: [mem 0x200000000-0x21fffffff]
[ 0.000000] [mem 0x200000000-0x21fffffff] page 2M
[ 0.000000] init_memory_mapping: [mem 0x00100000-0xcffaffff]
[ 0.000000] [mem 0x00100000-0x001fffff] page 4k
[ 0.000000] [mem 0x00200000-0x3fffffff] page 2M
[ 0.000000] [mem 0x40000000-0xbfffffff] page 1G
[ 0.000000] [mem 0xc0000000-0xcfdfffff] page 2M
[ 0.000000] [mem 0xcfe00000-0xcffaffff] page 4k
[ 0.000000] init_memory_mapping: [mem 0x100000000-0x1ffffffff]
[ 0.000000] [mem 0x100000000-0x1ffffffff] page 1G
[ 0.000000] RAMDISK: [mem 0x35f72000-0x36fb0fff]
[ 0.000000] ACPI: Early table checksum verification disabled
[ 0.000000] ACPI: RSDP 0x00000000000FA820 000024 (v02 ACPIAM)
[ 0.000000] ACPI: XSDT 0x00000000CFFB0100 00005C (v01 012711 OEMXSDT
20110127 MSFT 00000097)
[ 0.000000] ACPI: FACP 0x00000000CFFB0290 0000F4 (v03 012711 OEMFACP
20110127 MSFT 00000097)
[ 0.000000] ACPI BIOS Warning (bug): 32/64X length mismatch in
FADT/Gpe0Block: 64/32 (20150619/tbfadt-623)
[ 0.000000] ACPI: DSDT 0x00000000CFFB0450 0090C5 (v01 P0020 P0020000
00000000 INTL 20051117)
[ 0.000000] ACPI: FACS 0x00000000CFFBE000 000040
[ 0.000000] ACPI: FACS 0x00000000CFFBE000 000040
[ 0.000000] ACPI: APIC 0x00000000CFFB0390 00007C (v01 012711 OEMAPIC
20110127 MSFT 00000097)
[ 0.000000] ACPI: MCFG 0x00000000CFFB0410 00003C (v01 012711 OEMMCFG
20110127 MSFT 00000097)
[ 0.000000] ACPI: OEMB 0x00000000CFFBE040 000071 (v01 012711 AMI_OEM
20110127 MSFT 00000097)
[ 0.000000] ACPI: SRAT 0x00000000CFFB9520 0000E8 (v03 AMD FAM_F_10
00000002 AMD 00000001)
[ 0.000000] ACPI: HPET 0x00000000CFFB9610 000038 (v01 012711 OEMHPET
20110127 MSFT 00000097)
[ 0.000000] ACPI: SSDT 0x00000000CFFB9650 00088C (v01 A M I POWERNOW
00000001 AMD 00000001)
[ 0.000000] ACPI: Local APIC address 0xfee00000
[ 0.000000] [ffffea0000000000-ffffea0008bfffff] PMD ->
[ffff880227600000-ffff88022f5fffff] on node 0
[ 0.000000] Zone ranges:
[ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff]
[ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff]
[ 0.000000] Normal [mem 0x0000000100000000-0x000000022fffffff]
[ 0.000000] Movable zone start for each node
[ 0.000000] Early memory node ranges
[ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff]
[ 0.000000] node 0: [mem 0x0000000000100000-0x00000000cffaffff]
[ 0.000000] node 0: [mem 0x0000000100000000-0x000000022fffffff]
[ 0.000000] Initmem setup node 0 [mem
0x0000000000001000-0x000000022fffffff]
[ 0.000000] On node 0 totalpages: 2096974
[ 0.000000] DMA zone: 64 pages used for memmap
[ 0.000000] DMA zone: 22 pages reserved
[ 0.000000] DMA zone: 3998 pages, LIFO batch:0
[ 0.000000] DMA32 zone: 13247 pages used for memmap
[ 0.000000] DMA32 zone: 847792 pages, LIFO batch:31
[ 0.000000] Normal zone: 19456 pages used for memmap
[ 0.000000] Normal zone: 1245184 pages, LIFO batch:31
[ 0.000000] ACPI: PM-Timer IO Port: 0x808
[ 0.000000] ACPI: Local APIC address 0xfee00000
[ 0.000000] IOAPIC[0]: apic_id 4, version 33, address 0xfec00000, GSI
0-23
[ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 low level)
[ 0.000000] ACPI: IRQ0 used by override.
[ 0.000000] ACPI: IRQ9 used by override.
[ 0.000000] Using ACPI (MADT) for SMP configuration information
[ 0.000000] ACPI: HPET id: 0x8300 base: 0xfed00000
[ 0.000000] smpboot: Allowing 6 CPUs, 2 hotplug CPUs
[ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff]
[ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff]
[ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000e3fff]
[ 0.000000] PM: Registered nosave memory: [mem 0x000e4000-0x000fffff]
[ 0.000000] PM: Registered nosave memory: [mem 0xcffb0000-0xcffbdfff]
[ 0.000000] PM: Registered nosave memory: [mem 0xcffbe000-0xcffdffff]
[ 0.000000] PM: Registered nosave memory: [mem 0xcffe0000-0xcfffffff]
[ 0.000000] PM: Registered nosave memory: [mem 0xd0000000-0xff6fffff]
[ 0.000000] PM: Registered nosave memory: [mem 0xff700000-0xffffffff]
[ 0.000000] e820: [mem 0xd0000000-0xff6fffff] available for PCI devices
[ 0.000000] Booting paravirtualized kernel on bare hardware
[ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff
max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns
[ 0.000000] setup_percpu: NR_CPUS:8 nr_cpumask_bits:8 nr_cpu_ids:6
nr_node_ids:1
[ 0.000000] PERCPU: Embedded 31 pages/cpu @ffff88022fc00000 s88840
r8192 d29944 u262144
[ 0.000000] pcpu-alloc: s88840 r8192 d29944 u262144 alloc=1*2097152
[ 0.000000] pcpu-alloc: [0] 0 1 2 3 4 5 - -
[ 0.000000] Built 1 zonelists in Zone order, mobility grouping on.
Total pages: 2064185
[ 0.000000] Kernel command line: BOOT_IMAGE=/vmlinuz-4.2.0-rc1+
root=UUID=39706f53-7c27-4310-b22a-36c7b042d1a1 ro radeon.audio=1
[ 0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes)
[ 0.000000] Dentry cache hash table entries: 1048576 (order: 11,
8388608 bytes)
[ 0.000000] Inode-cache hash table entries: 524288 (order: 10,
4194304 bytes)
[ 0.000000] Memory: 8134376K/8387896K available (5820K kernel code,
810K rwdata, 2524K rodata, 928K init, 13772K bss, 253520K reserved, 0K
cma-reserved)

If I get any repeat lock-ups on the machine running the kernel in 64 bit
mode I'll try to photograph them.

Arthur.

2015-07-07 07:30:25

by Peter Zijlstra

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree

On Tue, Jul 07, 2015 at 02:59:06PM +0930, Arthur Marsh wrote:
> I had a single, non-reproducible case of the same lock-up happening on my
> other machine running the Linus git head kernel in 64-bit mode.

Hmm, disturbing.. I've had my machines run this stuff for weeks and not
had anything like this :/

Do you have a serial cable between those machines? serial console output
will allow capturing more complete traces than these pictures can and
might also aid in capturing some extra debug info.

In any case, I'll go try and build some debug code.

2015-07-07 15:58:33

by Arthur Marsh

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree



Peter Zijlstra wrote on 07/07/15 16:59:

> Do you have a serial cable between those machines? serial console output
> will allow capturing more complete traces than these pictures can and
> might also aid in capturing some extra debug info.
>
> In any case, I'll go try and build some debug code.
>

I do have eia-232 serial ports on both machines and a serial cable but
would need to hunt down a null modem adapter or cable and a how-to on
booting with a serial console - I'll ask around in the next 24 hours.

Arthur.

2015-07-07 16:33:35

by Mathieu Desnoyers

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree

----- On Jul 7, 2015, at 3:29 AM, Peter Zijlstra [email protected] wrote:

> On Tue, Jul 07, 2015 at 02:59:06PM +0930, Arthur Marsh wrote:
>> I had a single, non-reproducible case of the same lock-up happening on my
>> other machine running the Linus git head kernel in 64-bit mode.
>
> Hmm, disturbing.. I've had my machines run this stuff for weeks and not
> had anything like this :/
>
> Do you have a serial cable between those machines? serial console output
> will allow capturing more complete traces than these pictures can and
> might also aid in capturing some extra debug info.
>
> In any case, I'll go try and build some debug code.

Arthur: can you double-check if you load any module with --force ?
This could cause a module header layout mismatch, which can be an
issue with the changes done by the identified commit: the module
header layout changes there.

Also, I'm attaching a small patch which serializes both updates and
reads of the module rbree. Can you try it out ? If the problem
still shows with the spinlocks in place, that would mean the issue
is *not* a race between latched rbtree updates and traversals.

Thanks!

Mathieu

--
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com


Attachments:
0001-TESTING-add-spinlock-to-module.c-rb-latch-tree.patch (2.17 kB)

2015-07-07 20:16:02

by Arthur Marsh

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree



Mathieu Desnoyers wrote on 08/07/15 02:03:
> ----- On Jul 7, 2015, at 3:29 AM, Peter Zijlstra [email protected] wrote:
>
>> On Tue, Jul 07, 2015 at 02:59:06PM +0930, Arthur Marsh wrote:
>>> I had a single, non-reproducible case of the same lock-up happening on my
>>> other machine running the Linus git head kernel in 64-bit mode.
>>
>> Hmm, disturbing.. I've had my machines run this stuff for weeks and not
>> had anything like this :/
>>
>> Do you have a serial cable between those machines? serial console output
>> will allow capturing more complete traces than these pictures can and
>> might also aid in capturing some extra debug info.
>>
>> In any case, I'll go try and build some debug code.
>
> Arthur: can you double-check if you load any module with --force ?
> This could cause a module header layout mismatch, which can be an
> issue with the changes done by the identified commit: the module
> header layout changes there.
>
> Also, I'm attaching a small patch which serializes both updates and
> reads of the module rbree. Can you try it out ? If the problem
> still shows with the spinlocks in place, that would mean the issue
> is *not* a race between latched rbtree updates and traversals.
>
> Thanks!
>
> Mathieu
>

I'm not aware of any modules being loaded with --force .

I've applied the patch, thanks!

The resultant kernel locked up as follows:

http://www.users.on.net/~arthur.marsh/20150708469.jpg
http://www.users.on.net/~arthur.marsh/20150708470.jpg

Sorry that the first image isn't as clear as the second - it only
appears for a few seconds.

Hopefully these will provide some clue as to what is happening.

Arthur.

2015-07-07 21:56:38

by Peter Zijlstra

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree

On Wed, Jul 08, 2015 at 05:45:45AM +0930, Arthur Marsh wrote:
> I'm not aware of any modules being loaded with --force .
>
> I've applied the patch, thanks!
>
> The resultant kernel locked up as follows:
>
> http://www.users.on.net/~arthur.marsh/20150708469.jpg

This has "Not tainted" which would indeed rule out forced loading. So
much for that idea :/

> http://www.users.on.net/~arthur.marsh/20150708470.jpg

And that one has a bunch of NMI prints, curious those. But given Mathieu
made them return NULL, that completely rules out the most interesting
races.



You could have a look at Documentation/networking/netconsole.txt and see
if you can get that working between your machines; if you can get that
to work you can maybe stop looking for that null-modem bit.

2015-07-07 22:11:47

by Peter Zijlstra

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree

On Tue, Jul 07, 2015 at 11:56:20PM +0200, Peter Zijlstra wrote:
> On Wed, Jul 08, 2015 at 05:45:45AM +0930, Arthur Marsh wrote:
> > I'm not aware of any modules being loaded with --force .
> >
> > I've applied the patch, thanks!
> >
> > The resultant kernel locked up as follows:
> >
> > http://www.users.on.net/~arthur.marsh/20150708469.jpg
>
> This has "Not tainted" which would indeed rule out forced loading. So
> much for that idea :/
>
> > http://www.users.on.net/~arthur.marsh/20150708470.jpg
>
> And that one has a bunch of NMI prints, curious those. But given Mathieu
> made them return NULL, that completely rules out the most interesting
> races.

Could you try the below? It appears there was a spot freeing modules
that forgot to take them out of the tree.

If that fails, try and disable CONFIG_MODULE_UNLOAD.

---
kernel/module.c | 1 +
1 file changed, 1 insertion(+)

diff --git a/kernel/module.c b/kernel/module.c
index 3e0e19763d24..4d2b82e610e2 100644
--- a/kernel/module.c
+++ b/kernel/module.c
@@ -3557,6 +3557,7 @@ static int load_module(struct load_info *info, const char __user *uargs,
mutex_lock(&module_mutex);
/* Unlink carefully: kallsyms could be walking list. */
list_del_rcu(&mod->list);
+ mod_tree_remove(mod);
wake_up_all(&module_wq);
/* Wait for RCU-sched synchronizing before releasing mod->list. */
synchronize_sched();

2015-07-08 00:56:06

by Rusty Russell

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree

Peter Zijlstra <[email protected]> writes:
> On Tue, Jul 07, 2015 at 11:56:20PM +0200, Peter Zijlstra wrote:
>> On Wed, Jul 08, 2015 at 05:45:45AM +0930, Arthur Marsh wrote:
>> > I'm not aware of any modules being loaded with --force .
>> >
>> > I've applied the patch, thanks!
>> >
>> > The resultant kernel locked up as follows:
>> >
>> > http://www.users.on.net/~arthur.marsh/20150708469.jpg
>>
>> This has "Not tainted" which would indeed rule out forced loading. So
>> much for that idea :/
>>
>> > http://www.users.on.net/~arthur.marsh/20150708470.jpg
>>
>> And that one has a bunch of NMI prints, curious those. But given Mathieu
>> made them return NULL, that completely rules out the most interesting
>> races.
>
> Could you try the below? It appears there was a spot freeing modules
> that forgot to take them out of the tree.

Ouch! Good catch.

I'm testing that here.... Yep, "modprobe lp reset=7" (which fails to
parse) three times and then oops in __mod_tree_insert.

If you want to wrap that with a SOB and Reported-by/Tested-by if my
compatriot acks...

Thanks!
Rusty.

> ---
> kernel/module.c | 1 +
> 1 file changed, 1 insertion(+)
>
> diff --git a/kernel/module.c b/kernel/module.c
> index 3e0e19763d24..4d2b82e610e2 100644
> --- a/kernel/module.c
> +++ b/kernel/module.c
> @@ -3557,6 +3557,7 @@ static int load_module(struct load_info *info, const char __user *uargs,
> mutex_lock(&module_mutex);
> /* Unlink carefully: kallsyms could be walking list. */
> list_del_rcu(&mod->list);
> + mod_tree_remove(mod);
> wake_up_all(&module_wq);
> /* Wait for RCU-sched synchronizing before releasing mod->list. */
> synchronize_sched();

2015-07-08 08:32:11

by Arthur Marsh

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree



Peter Zijlstra wrote on 08/07/15 07:41:
> On Tue, Jul 07, 2015 at 11:56:20PM +0200, Peter Zijlstra wrote:

> Could you try the below? It appears there was a spot freeing modules
> that forgot to take them out of the tree.
>
> If that fails, try and disable CONFIG_MODULE_UNLOAD.

I tried the patch below, re-built and installed and booted the kernel
and saw:

http://www.users.on.net/~arthur.marsh/20150708471.jpg
http://www.users.on.net/~arthur.marsh/20150708472.jpg

I'm now rebuilding the kernel with CONFIG_MODULE_UNLOAD disabled.

Arthur.

>
> ---
> kernel/module.c | 1 +
> 1 file changed, 1 insertion(+)
>
> diff --git a/kernel/module.c b/kernel/module.c
> index 3e0e19763d24..4d2b82e610e2 100644
> --- a/kernel/module.c
> +++ b/kernel/module.c
> @@ -3557,6 +3557,7 @@ static int load_module(struct load_info *info, const char __user *uargs,
> mutex_lock(&module_mutex);
> /* Unlink carefully: kallsyms could be walking list. */
> list_del_rcu(&mod->list);
> + mod_tree_remove(mod);
> wake_up_all(&module_wq);
> /* Wait for RCU-sched synchronizing before releasing mod->list. */
> synchronize_sched();
>

2015-07-08 09:04:50

by Peter Zijlstra

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree

On Wed, Jul 08, 2015 at 06:01:29PM +0930, Arthur Marsh wrote:
>
>
> Peter Zijlstra wrote on 08/07/15 07:41:
> >On Tue, Jul 07, 2015 at 11:56:20PM +0200, Peter Zijlstra wrote:
>
> >Could you try the below? It appears there was a spot freeing modules
> >that forgot to take them out of the tree.
> >
> >If that fails, try and disable CONFIG_MODULE_UNLOAD.
>
> I tried the patch below, re-built and installed and booted the kernel and
> saw:
>
> http://www.users.on.net/~arthur.marsh/20150708471.jpg
> http://www.users.on.net/~arthur.marsh/20150708472.jpg

Ah, that's a lockdep splat, caused by Mathieu's patch. Did the system
boot otherwise?

Maybe take that patch from Mathieu out again.

2015-07-08 11:43:42

by Arthur Marsh

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree



Peter Zijlstra wrote on 08/07/15 18:34:
> On Wed, Jul 08, 2015 at 06:01:29PM +0930, Arthur Marsh wrote:
>>
>>
>> Peter Zijlstra wrote on 08/07/15 07:41:
>>> On Tue, Jul 07, 2015 at 11:56:20PM +0200, Peter Zijlstra wrote:
>>
>>> Could you try the below? It appears there was a spot freeing modules
>>> that forgot to take them out of the tree.
>>>
>>> If that fails, try and disable CONFIG_MODULE_UNLOAD.
>>
>> I tried the patch below, re-built and installed and booted the kernel and
>> saw:
>>
>> http://www.users.on.net/~arthur.marsh/20150708471.jpg
>> http://www.users.on.net/~arthur.marsh/20150708472.jpg
>
> Ah, that's a lockdep splat, caused by Mathieu's patch. Did the system
> boot otherwise?
>
> Maybe take that patch from Mathieu out again.
>

OK, I removed Mathieu's
0001-TESTING-add-spinlock-to-module.c-rb-latch-tree.patch
but left in the the patch Peter wrote:

---
kernel/module.c | 1 +
1 file changed, 1 insertion(+)

diff --git a/kernel/module.c b/kernel/module.c
index 3e0e19763d24..4d2b82e610e2 100644
--- a/kernel/module.c
+++ b/kernel/module.c
@@ -3557,6 +3557,7 @@ static int load_module(struct load_info *info,
const char __user *uargs,
mutex_lock(&module_mutex);
/* Unlink carefully: kallsyms could be walking list. */
list_del_rcu(&mod->list);
+ mod_tree_remove(mod);
wake_up_all(&module_wq);
/* Wait for RCU-sched synchronizing before releasing mod->list. */
synchronize_sched();

and disabled CONFIG_MODULE_UNLOAD and the resulting kernel booted fine.

I rebuilt again with CONFIG_MODULE_UNLOAD enabled and Peter's patch
above and the resulting kernel also booted fine.

Thanks for everyone's help!

Arthur.

2015-07-08 12:32:53

by Peter Zijlstra

[permalink] [raw]
Subject: Re: lock-up with module: Optimize __module_address() using a latched RB-tree

On Wed, Jul 08, 2015 at 09:13:15PM +0930, Arthur Marsh wrote:
> I rebuilt again with CONFIG_MODULE_UNLOAD enabled and Peter's patch above
> and the resulting kernel also booted fine.
>
> Thanks for everyone's help!

Awesome, lemme go write up a proper patch to make Rusty happy too ;-)

2015-07-08 12:41:34

by Peter Zijlstra

[permalink] [raw]
Subject: [PATCH] module: Fix load_module() error path

On Wed, Jul 08, 2015 at 02:32:44PM +0200, Peter Zijlstra wrote:

> Awesome, lemme go write up a proper patch to make Rusty happy too ;-)

---
Subject: module: Fix load_module() error path
From: Peter Zijlstra <[email protected]>
Date: Wed Jul 8 14:35:58 CEST 2015

The load_module() error path frees a module but forgot to take it out
of the mod_tree, leaving a dangling entry in the tree, causing havoc.

Cc: Mathieu Desnoyers <[email protected]>
Reported-by: Arthur Marsh <[email protected]>
Tested-by: Arthur Marsh <[email protected]>
Fixes: 93c2e105f6bc ("module: Optimize __module_address() using a latched RB-tree")
Signed-off-by: Peter Zijlstra (Intel) <[email protected]>
---
kernel/module.c | 1 +
1 file changed, 1 insertion(+)

--- a/kernel/module.c
+++ b/kernel/module.c
@@ -3557,6 +3557,7 @@ static int load_module(struct load_info
mutex_lock(&module_mutex);
/* Unlink carefully: kallsyms could be walking list. */
list_del_rcu(&mod->list);
+ mod_tree_remove(mod);
wake_up_all(&module_wq);
/* Wait for RCU-sched synchronizing before releasing mod->list. */
synchronize_sched();

2015-07-08 21:44:50

by Rusty Russell

[permalink] [raw]
Subject: Re: [PATCH] module: Fix load_module() error path

Peter Zijlstra <[email protected]> writes:
> On Wed, Jul 08, 2015 at 02:32:44PM +0200, Peter Zijlstra wrote:
>
>> Awesome, lemme go write up a proper patch to make Rusty happy too ;-)

Thanks, Rusty is happy :)

Applied, and pushed to Linus.

Cheers,
Rusty.

> ---
> Subject: module: Fix load_module() error path
> From: Peter Zijlstra <[email protected]>
> Date: Wed Jul 8 14:35:58 CEST 2015
>
> The load_module() error path frees a module but forgot to take it out
> of the mod_tree, leaving a dangling entry in the tree, causing havoc.
>
> Cc: Mathieu Desnoyers <[email protected]>
> Reported-by: Arthur Marsh <[email protected]>
> Tested-by: Arthur Marsh <[email protected]>
> Fixes: 93c2e105f6bc ("module: Optimize __module_address() using a latched RB-tree")
> Signed-off-by: Peter Zijlstra (Intel) <[email protected]>
> ---
> kernel/module.c | 1 +
> 1 file changed, 1 insertion(+)
>
> --- a/kernel/module.c
> +++ b/kernel/module.c
> @@ -3557,6 +3557,7 @@ static int load_module(struct load_info
> mutex_lock(&module_mutex);
> /* Unlink carefully: kallsyms could be walking list. */
> list_del_rcu(&mod->list);
> + mod_tree_remove(mod);
> wake_up_all(&module_wq);
> /* Wait for RCU-sched synchronizing before releasing mod->list. */
> synchronize_sched();