Re: "Memory modified after free" - by whom?

From: Garrett Cooper <yanegomi_at_gmail.com>
Date: Fri, 21 Dec 2012 17:34:42 -0800
(clipping off mdf and adrian so they don't get directly spammed :)..)
    Crud. Continuing the processor after panic didn't work, so it
might be a case of cxgbe "shot the sheriff" or something else in the
stack is doing something wonky:

db> c

Memory modified after free 0xffffff8000405000(9216) val=0 _at_ 0xffffff8000405000
Memory modified after free 0xffffff800040d000(9216) val=0 _at_ 0xffffff800040d000



Fatal trap 1: privileged instruction fault while in kernel mode
Memory modified after free 0xffffff8000409000(9216) val=0 _at_ 0xffffff8000409000

cpuid = 0;
Fatal trap 1: privileged instruction fault while in kernel mode
apic id = 00
cpuid = 1; Fatal trap 1: privileged instruction fault while in kernel mode
instruction pointer     = 0x20:0xffffffff80af5099
cpuid = 2; stack pointer                = 0x28:0xffffff8496f41910
apic id = 04
apic id = 02
instruction pointer     = 0x20:0xffffffff80af5099
instruction pointer     = 0x20:0xffffffff80af5099

stack pointer           = 0x28:0xffffff849705d880
frame pointer           = 0x28:0xffffff8496f41940

stack pointer           = 0x28:0xffffff8497067880
code segment            = base 0x0, limit 0xfffff, type 0x1b
frame pointer           = 0x28:0xffffff849705d8b0
                        = DPL 0, pres 1, long 1, def32 0, gran 1
frame pointer           = 0x28:0xffffff84970678b0
Fatal trap 1: privileged instruction fault while in kernel mode
code segment            = base 0x0, limit 0xfffff, type 0x1b
code segment            = base 0x0, limit 0xfffff, type 0x1b
processor eflags        =                       = DPL 0, pres 1, long
1, def32 0, gran 1
                        = DPL 0, pres 1, long 1, def32 0, gran 1
cpuid = 3; interrupt enabled, processor eflags  = processor eflags
 = resume, interrupt enabled, apic id = 06
interrupt enabled, instruction pointer  = 0x20:0xffffffff80af5099
resume, resume, stack pointer           = 0x28:0xffffff8497071880
IOPL = 0
frame pointer           = 0x28:0xffffff84970718b0
IOPL = 0
current process         = code segment          = base 0x0, limit
0xfffff, type 0x1b
12 (irq283: ix1:que 1)
Ilock order reversal: (Giant after non-sleepable)
 1st 0xfffffe009a295918 ix1:rx(1) (ix1:rx(1)) _at_
/usr/src/sys/modules/ixgbe/../../dev/ixgbe/ixgbe.c:4298
 2nd 0xffffffff814457b8 Giant (Giant) _at_ /usr/src/sys/dev/usb/input/ukbd.c:1946
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame 0xffffff849705d320
kdb_backtrace() at kdb_backtrace+0x39/frame 0xffffff849705d3d0
witness_checkorder() at witness_checkorder+0xc47/frame 0xffffff849705d450
__mtx_lock_flags() at __mtx_lock_flags+0x89/frame 0xffffff849705d490
ukbd_poll() at ukbd_poll+0x28/frame 0xffffff849705d4b0
kbdmux_poll() at kbdmux_poll+0x5b/frame 0xffffff849705d4d0
cngrab() at cngrab+0x35/frame 0xffffff849705d4f0
kdb_trap() at kdb_trap+0x124/frame 0xffffff849705d550
trap_fatal() at trap_fatal+0x345/frame 0xffffff849705d5b0
trap() at trap+0x836/frame 0xffffff849705d7c0
calltrap() at calltrap+0x8/frame 0xffffff849705d7c0
--- trap 0x1, rip = 0xffffffff80af5099, rsp = 0xffffff849705d880, rbp
= 0xffffff849705d8b0 ---
uma_find_refcnt() at uma_find_refcnt+0x79/frame 0xffffff849705d8b0
mb_ctor_clust() at mb_ctor_clust+0x8f/frame 0xffffff849705d8e0
uma_zalloc_arg() at uma_zalloc_arg+0xe7/frame 0xffffff849705d960
m_getjcl() at m_getjcl+0xce/frame 0xffffff849705d9a0
ixgbe_refresh_mbufs() at ixgbe_refresh_mbufs+0x77/frame 0xffffff849705da20
ixgbe_rxeof() at ixgbe_rxeof+0x4e9/frame 0xffffff849705dad0
ixgbe_msix_que() at ixgbe_msix_que+0x9b/frame 0xffffff849705db20
intr_event_execute_handlers() at
intr_event_execute_handlers+0x90/frame 0xffffff849705db60
ithread_loop() at ithread_loop+0x161/frame 0xffffff849705dbb0
fork_exit() at fork_exit+0x84/frame 0xffffff849705dbf0
fork_trampoline() at fork_trampoline+0xe/frame 0xffffff849705dbf0
--- trap 0, rip = 0, rsp = 0xffffff849705dcb0, rbp = 0 ---
[ thread pid 12 tid 100224 ]
Stopped at      uma_find_refcnt+0x79:



    I setup asymmetric MTUs to see if I can narrow down whether the
issue is a jumbo frame or cxgbe/ixgbe issue and so far so good. Trying
again with jumbo frames paniced on boot when loading the module
(really...?):

# Memory modified after free 0xffffff8000401000(9216) val=0 _at_ 0xffffff8000401000


Fatal trap 1: privileged instruction fault while in kernel mode
cpuid = 1; apic id = 02
instruction pointer     = 0x20:0xffffffff80af5099
stack pointer           = 0x28:0xffffff8496fc9750
frame pointer           = 0x28:0xffffff8496fc9780
code segment            = base 0x0, limit 0xfffff, type 0x1b
                        = DPL 0, pres 1, long 1, def32 0, gran 1
processor eflags        = interrupt enabled, resume, IOPL = 0
current process         = 3280 (ifconfig)
lock order reversal: (Giant after non-sleepable)
 1st 0xfffffe00462f7808 ix0:rx(0) (ix0:rx(0)) _at_
/usr/src/sys/modules/ixgbe/../../dev/ixgbe/ixgbe.c:3938
 2nd 0xffffffff814457b8 Giant (Giant) _at_ /usr/src/sys/dev/usb/input/ukbd.c:1946
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame 0xffffff8496fc91f0
kdb_backtrace() at kdb_backtrace+0x39/frame 0xffffff8496fc92a0
witness_checkorder() at witness_checkorder+0xc47/frame 0xffffff8496fc9320
__mtx_lock_flags() at __mtx_lock_flags+0x89/frame 0xffffff8496fc9360
ukbd_poll() at ukbd_poll+0x28/frame 0xffffff8496fc9380
kbdmux_poll() at kbdmux_poll+0x5b/frame 0xffffff8496fc93a0
cngrab() at cngrab+0x35/frame 0xffffff8496fc93c0
kdb_trap() at kdb_trap+0x124/frame 0xffffff8496fc9420
trap_fatal() at trap_fatal+0x345/frame 0xffffff8496fc9480
trap() at trap+0x836/frame 0xffffff8496fc9690
calltrap() at calltrap+0x8/frame 0xffffff8496fc9690
--- trap 0x1, rip = 0xffffffff80af5099, rsp = 0xffffff8496fc9750, rbp
= 0xffffff8496fc9780 ---
uma_find_refcnt() at uma_find_refcnt+0x79/frame 0xffffff8496fc9780
mb_ctor_clust() at mb_ctor_clust+0x8f/frame 0xffffff8496fc97b0
uma_zalloc_arg() at uma_zalloc_arg+0xe7/frame 0xffffff8496fc9830
m_getjcl() at m_getjcl+0xce/frame 0xffffff8496fc9870
ixgbe_init_locked() at ixgbe_init_locked+0x62c/frame 0xffffff8496fc9930
ixgbe_ioctl() at ixgbe_ioctl+0x32d/frame 0xffffff8496fc9980
ifioctl() at ifioctl+0xc84/frame 0xffffff8496fc9a40
kern_ioctl() at kern_ioctl+0x1ce/frame 0xffffff8496fc9a90
sys_ioctl() at sys_ioctl+0x11f/frame 0xffffff8496fc9ae0
amd64_syscall() at amd64_syscall+0x265/frame 0xffffff8496fc9bf0
Xfast_syscall() at Xfast_syscall+0xfb/frame 0xffffff8496fc9bf0
--- syscall (54, FreeBSD ELF64, sys_ioctl), rip = 0x80118481a, rsp =
0x7fffffffd488, rbp = 0x7fffffffd4a0 ---
[ thread pid 3280 tid 100220 ]
Stopped at      uma_find_refcnt+0x79:

    Setting the MTU exhibits the same problem... just with smaller mbufs:

Memory modified after free 0xfffffe014ce86800(2048) val=cc0c0001 _at_
0xfffffe014ce86800
Memory modified after free 0xfffffe00bd86f000(2048) val=cc0c0001 _at_
0xfffffe00bd86f000
Memory modified after free 0xfffffe00bd3a4000(2048) val=cc0c0001 _at_
0xfffffe00bd3a4000
Memory modified after free 0xfffffe011a55c000(2048) val=2d290c00 _at_
0xfffffe011a55c000
Memory modified after free 0xfffffe011a5fa800(2048) val=cc0c0001 _at_
0xfffffe011a5fa800
Memory modified after free 0xfffffe00bd018800(2048) val=ffffffff _at_
0xfffffe00bd018800
Memory modified after free 0xfffffe00bd1c4000(2048) val=7f565000 _at_
0xfffffe00bd1c4000
Memory modified after free 0xfffffe011a521800(2048) val=529c0a00 _at_
0xfffffe011a521800
Memory modified after free 0xfffffe011a521800(2048) val=cc0c0001 _at_
0xfffffe011a521800
Memory modified after free 0xfffffe00bd0ce800(2048) val=cc0c0001 _at_
0xfffffe00bd0ce800
Memory modified after free 0xfffffe00bd9a3000(2048) val=ffffffff _at_
0xfffffe00bd9a3000
Memory modified after free 0xfffffe00bd8b6800(2048) val=cc0c0001 _at_
0xfffffe00bd8b6800
Memory modified after free 0xfffffe00bd923000(2048) val=cc0c0001 _at_
0xfffffe00bd923000
Memory modified after free 0xfffffe0188f70800(2048) val=2d290c00 _at_
0xfffffe0188f70800
Memory modified after free 0xfffffe0180452000(2048) val=ffffffff _at_
0xfffffe0180452000
Memory modified after free 0xfffffe014cd6b800(2048) val=cc0c0001 _at_
0xfffffe014cd6b800
Memory modified after free 0xfffffe014c967800(2048) val=cc0c0001 _at_
0xfffffe014c967800
Memory modified after free 0xfffffe01800d1000(2048) val=cc0c0001 _at_
0xfffffe01800d1000
Memory modified after free 0xfffffe014c967800(2048) val=cc0c0001 _at_
0xfffffe014c967800
Memory modified after free 0xfffffe0188fdf000(2048) val=cc0c0001 _at_
0xfffffe0188fdf000
Memory modified after free 0xfffffe0188fdf000(2048) val=cc0c0001 _at_
0xfffffe0188fdf000
Memory modified after free 0xfffffe00bd9a3000(2048) val=cc0c0001 _at_
0xfffffe00bd9a3000
Memory modified after free 0xfffffe011a6cb000(2048) val=cc0c0001 _at_
0xfffffe011a6cb000

    Setting sysctl vm.memguard.desc=mbuf sends the kernel into a
spiral of "use-after-frees". FWIW, I was able to repro the issue with
ixgbe kldloading the module after boot sometimes, so I'm thinking that
the locking/memory management in the recent set of changes is
potentially off.
Thanks,
-Garrett

PS Thanks np for the recent fix for cxgbe :).
Received on Sat Dec 22 2012 - 00:34:43 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:40:33 UTC