Summary: | callout structure corruption and panic | ||
---|---|---|---|
Product: | Base System | Reporter: | Sean Bruno <sbruno> |
Component: | kern | Assignee: | Mark Johnston <markj> |
Status: | Closed DUPLICATE | ||
Severity: | Affects Only Me | CC: | cem, chris, emaste, jhb, kib, lstewart, markj, re, sigsys |
Priority: | --- | Keywords: | regression |
Version: | CURRENT | ||
Hardware: | Any | ||
OS: | Any | ||
Attachments: |
Description
Sean Bruno
2018-09-01 18:27:13 UTC
This has nothing to do with HPET. It is some callout handling issue, e.g. the callout memory freed or reused without proper stop. I would start with reproduction case. I've dropped the kernel + debug + crashdump in my homedir on freefall:~sbruno/service1.rbsd.tgz (In reply to Konstantin Belousov from comment #1) Indeed, this is the result of a corrupted callout structure: (kgdb) p *cc->cc_callwheel[firstb & callwheelmask].lh_first->c_links.le.le_next $12 = { c_links = { le = { le_next = 0x40, le_prev = 0xfffff800051ef9b0 }, sle = { sle_next = 0x40 }, tqe = { tqe_next = 0x40, tqe_prev = 0xfffff800051ef9b0 } }, c_time = 4, c_precision = 20, c_arg = 0x7fffffffef70, c_func = 0x15, c_lock = 0x18, c_flags = 22, c_iflags = 0, c_cpu = 0 } I've had this happen at least 2 more times on these lower end machine (atom class) in the freebsd cluster. This happens at svn 338340 but does not happen at svn 333388. That's not really "helpful" here, but its a start. ------- Copyright (c) 1992-2018 The FreeBSD Project. Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994 The Regents of the University of California. All rights reserved. FreeBSD is a registered trademark of The FreeBSD Foundation. FreeBSD 12.0-ALPHA3 #0 r338330: Sun Aug 26 19:06:44 UTC 2018 peter@build-12.freebsd.org:/usr/obj/usr/src/sys/CLUSTER12 amd64 FreeBSD clang version 6.0.1 (tags/RELEASE_601/final 335540) (based on LLVM 6.0.1) CPU: Intel(R) Atom(TM) CPU D525 @ 1.80GHz (1800.03-MHz K8-class CPU) Origin="GenuineIntel" Id=0x106ca Family=0x6 Model=0x1c Stepping=10 Features=0xbfebfbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CLFLUSH,DTS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE> Features2=0x40e31d<SSE3,DTES64,MON,DS_CPL,TM2,SSSE3,CX16,xTPR,PDCM,MOVBE> AMD Features=0x20100800<SYSCALL,NX,LM> AMD Features2=0x1<LAHF> TSC: P-state invariant, performance statistics real memory = 2147483648 (2048 MB) avail memory = 2050883584 (1955 MB) -------- Created attachment 196916 [details]
dmesg from atom servers that seem to be more likely to fall down
Created attachment 196917 [details]
Crash summary from igw0 (another Atom server) in the freebsd cluster
I've dropped the crashdump + kernel in my homedir on freefall:~sbruno/igw0_crash.tgz I believe I may have hit this too the other day on a big iron server at $work running GENERIC-NODEBUG r338290. % sudo kgdb /boot/kernel/kernel /var/crash/vmcore.0 GNU gdb (GDB) 8.1.1 [GDB v8.1.1 for FreeBSD] Copyright (C) 2018 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "x86_64-portbld-freebsd12.0". Type "show configuration" for configuration details. For bug reporting instructions, please see: <http://www.gnu.org/software/gdb/bugs/>. Find the GDB manual and other documentation resources online at: <http://www.gnu.org/software/gdb/documentation/>. For help, type "help". Type "apropos word" to search for commands related to "word"... Reading symbols from /boot/kernel/kernel...Reading symbols from /usr/lib/debug//boot/kernel/kernel.debug...done. done. Unread portion of the kernel message buffer: kernel trap 9 with interrupts disabled Fatal trap 9: general protection fault while in kernel mode cpuid = 0; apic id = 00 instruction pointer = 0x20:0xffffffff80bd94cf stack pointer = 0x28:0xfffffe0075f5a710 frame pointer = 0x28:0xfffffe0075f5a780 code segment = base rx0, limit 0xfffff, type 0x1b = DPL 0, pres 1, long 1, def32 0, gran 1 processor eflags = resume, IOPL = 0 current process = 11 (idle: cpu0) __curthread () at ./machine/pcpu.h:230 230 __asm("movq %%gs:%1,%0" : "=r" (td) (kgdb) bt #0 __curthread () at ./machine/pcpu.h:230 #1 doadump (textdump=1979032256) at /usr/src/sys/kern/kern_shutdown.c:366 #2 0xffffffff8043f76c in db_fncall_generic (addr=<optimized out>, rv=<optimized out>, nargs=<optimized out>, args=<optimized out>) at /usr/src/sys/ddb/db_command.c:609 #3 db_fncall (dummy1=<optimized out>, dummy2=<optimized out>, dummy3=<optimized out>, dummy4=<optimized out>) at /usr/src/sys/ddb/db_command.c:657 #4 0xffffffff8043f2a9 in db_command (last_cmdp=<optimized out>, cmd_table=<optimized out>, dopager=<optimized out>) at /usr/src/sys/ddb/db_command.c:481 #5 0xffffffff8043f024 in db_command_loop () at /usr/src/sys/ddb/db_command.c:534 #6 0xffffffff804422cf in db_trap (type=<optimized out>, code=<optimized out>) at /usr/src/sys/ddb/db_main.c:252 #7 0xffffffff80c0c443 in kdb_trap (type=9, code=0, tf=<optimized out>) at /usr/src/sys/kern/subr_kdb.c:693 #8 0xffffffff810a34a1 in trap_fatal (frame=0xfffffe0075f5a650, eva=0) at /usr/src/sys/amd64/amd64/trap.c:920 #9 0xffffffff810a299d in trap (frame=0xfffffe0075f5a650) at /usr/src/sys/amd64/amd64/trap.c:217 #10 <signal handler called> #11 0xffffffff80bd94cf in callout_process (now=3049912922371841) at /usr/src/sys/kern/kern_timeout.c:510 #12 0xffffffff811d14e8 in handleevents (now=3049912922371841, fake=0) at /usr/src/sys/kern/kern_clocksource.c:213 #13 0xffffffff811d1b59 in timercb (et=0xffffffff81f72fc8 <lapic_et>, arg=<optimized out>) at /usr/src/sys/kern/kern_clocksource.c:357 #14 0xffffffff81210766 in lapic_handle_timer (frame=0xfffffe0075f5a870) at /usr/src/sys/x86/x86/local_apic.c:1308 #15 <signal handler called> #16 0xffffffff8046540b in acpi_cpu_idle (sbt=<optimized out>) at /usr/src/sys/dev/acpica/acpi_cpu.c:1194 #17 0xffffffff812071af in cpu_idle_acpi (sbt=125307191) at /usr/src/sys/x86/x86/cpu_machdep.c:433 #18 0xffffffff81207267 in cpu_idle (busy=0) at /usr/src/sys/x86/x86/cpu_machdep.c:581 #19 0xffffffff80bf4005 in sched_idletd (dummy=<optimized out>) at /usr/src/sys/kern/sched_ule.c:2829 #20 0xffffffff80b7eb63 in fork_exit (callout=0xffffffff80bf3af0 <sched_idletd>, arg=0x0, frame=0xfffffe0075f5aac0) at /usr/src/sys/kern/kern_fork.c:1057 #21 <signal handler called> (kgdb) frame 11 #11 0xffffffff80bd94cf in callout_process (now=3049912922371841) at /usr/src/sys/kern/kern_timeout.c:510 510 LIST_REMOVE(tmp, c_links.le); (kgdb) p cc->cc_callwheel[firstb & callwheelmask].lh_first->c_links $4 = {le = {le_next = 0xb805000100000000, le_prev = 0x2}, sle = {sle_next = 0xb805000100000000}, tqe = {tqe_next = 0xb805000100000000, tqe_prev = 0x2}} So I see this happen on my freebsd.org machines testing -current about every other day. I'm only running about 8 machines at this point in the release process. Since its fairly consistent, is there some way to determine what the source of the corruption could be? (In reply to Sean Bruno from comment #9) All 8 machines are crashing this way? Or is it just the two so far? Can we identify the common configurations between service1 and igw0? It looks like the latter is using vlan, carp, and ZFS for instance, and the former is using pf. What exactly do the two machines have in common? (In reply to Mark Johnston from comment #10) I have only seen the Atom servers (service1, igw0) crash in this way. igw0 is acting as a router/firewall/gateway service1 is acting as a jail host with a dns(bind), ldap and kerberos jail. What's very odd is how *idle* these machines are on a day to day basis. They don't do a lot at the moment. The ftp mirror and pkg mirror that I upgraded do *not* manifest this problem and they are far busier doing the projects business. (they are most definitely not Atom servers). (In reply to Mark Johnston from comment #10) I added the boot dmesg from one of the example machines earlier in this ticket. You could try adding KTR with KTR_CALLOUT enabled in KTR_COMPILE and KTR_MASK. We could then see if we can find the most recent actions for the offending callout structure and work back from there. (In reply to John Baldwin from comment #13) Sean's also trying an INVARIANTS kernel at the moment, so we'll see if that provides any insight. I've only seen this once on the machine I have access to, so can't be much help with reproduction or debugging unfortunately unless there's something useful I can poke at in the core file. Similar to Sean's observation, the machine was likely almost entirely idle at the time of the panic. INVARIANTS does not crash. I waited for several days and no fault detected. I updated the hosts to ALPHA6 and one of the hosts crashed after a few days of uptime. I have dumped the crash/kernel/debug into freefall.freebsd.org:~sbruno/service1.rbsd.tar again. It still looks like corruption of the callout structs. I can try bisecting, but I'm unsure how to make the machine reliably fall over except to wait for 48 hours. (In reply to Sean Bruno from comment #16) The new kernel dump is more useful. The callout looks like this: $2 = { c_links = { le = { le_next = 0x11777be9162acbc1, le_prev = 0xffffffff80c9a01a }, sle = { sle_next = 0x11777be9162acbc1 }, tqe = { tqe_next = 0x11777be9162acbc1, tqe_prev = 0xffffffff80c9a01a } }, c_time = 577765376, c_precision = 0, c_arg = 0x6, c_func = 0x158, c_lock = 0x0, c_flags = 0, c_iflags = 0, c_cpu = 0 } (kgdb) x/s 0xffffffff80c9a01a 0xffffffff80c9a01a: "dr->dt.di.dr_mtx" So the second long word is the beginning of the dr_mtx field of a dbuf_dirty_record_t. (The 0x6 indicates that the lock is already destroyed.) It thus looks like the structure containing the callout was freed and reused for a dbuf_dirty_record_t. These records are allocated using malloc(9) and would come from the 512 byte zone (the mutex is at byte offset 192), so we're looking for a structure between 256 and 512 bytes in size containing a struct callout at byte offset 184, assuming that nothing called uma_reclaim() before the dbuf_dirty_record_t was allocated. Since there's been very little page daemon activity on this system, I think that's a safe assumption for now. Using ctfdump -t on the kernel and modules, I find two structures with these properties: struct ata_request and struct lle_entry. The latter seems to be a more likely candidate for use-after-free. (In reply to Mark Johnston from comment #17) s/lle_entry/llentry/ Sean, do you have some idea when the panic was introduced? Seems it was first seen at r338350; which revision were the systems running before that? Created attachment 197531 [details]
debug patch
Please give the attached patch a try. It adds some panic()s that will hopefully catch the problem closer to where it occurs. In any case, I'd be interested in looking at any other kernel dumps caused by this bug.
(In reply to Mark Johnston from comment #19) 333388 seems to be where I started and these systems were not crashing at that point. The machine did crash last night, finally. However it did *not* hit the code we were hoping and died somewhere else. I've dumped the kernel and assorted crash files to freefall.freebsd.org:~sbruno/service1_softclock.rbsd.tar (In reply to Sean Bruno from comment #22) Thanks. That suggests that the callout was scheduled after the llentry was freed (or that I'm completely off-base), so let's use a bigger hammer. Can you try the following instead of my patch? 1. compile the kernel with "options DEBUG_MEMGUARD" 2. set vm.memguard.desc="512" after boot I'm reading the llentry code and am concerned that the change of the if_adata read lock to epoch_enter() breaks synchronization of updates to llentry state. In particular, IF_AFDATA_RLOCK and _WLOCK aren't mutually exclusive anymore, but I suspect that we have some code that doesn't handle that quite correctly. However, I don't see a bug yet. I take it this has stopped occurring? (In reply to Mark Johnston from comment #24) Hrm. I thought so, its definitely still happening at: FreeBSD 12.0-BETA3 (CLUSTER12) #0 r340050: Thu Nov 8 14:29:24 UTC 2018 I've dropped the crash files + kernel in my homedir on freefall again: freefall.freebsd.org:~sbruno/ftpmirror.tar.gz Fatal trap 12: page fault while in kernel mode cpuid = 0; apic id = 00 fault virtual address = 0x20 fault code = supervisor read data, page not present instruction pointer = 0x20:0xffffffff80859e82 stack pointer = 0x28:0xfffffe0075472930 frame pointer = 0x28:0xfffffe00754729d0 code segment = base rx0, limit 0xfffff, type 0x1b = DPL 0, pres 1, long 1, def32 0, gran 1 processor eflags = resume, IOPL = 0 current process = 11 (idle: cpu0) #0 doadump (textdump=16777216) at pcpu.h:230 230 pcpu.h: No such file or directory. in pcpu.h (kgdb) #0 doadump (textdump=16777216) at pcpu.h:230 #1 0xffffffff804cda6c in db_fncall (dummy1=<value optimized out>, dummy2=<value optimized out>, dummy3=<value optimized out>, dummy4=<value optimized out>) at /usr/src/sys/ddb/db_command.c:609 #2 0xffffffff804cd5a9 in db_command (cmd_table=<value optimized out>) at /usr/src/sys/ddb/db_command.c:481 #3 0xffffffff804cd324 in db_command_loop () at /usr/src/sys/ddb/db_command.c:534 #4 0xffffffff804d05cf in db_trap (type=<value optimized out>, code=<value optimized out>) at /usr/src/sys/ddb/db_main.c:252 #5 0xffffffff8088bc83 in kdb_trap (type=12, code=0, tf=<value optimized out>) at /usr/src/sys/kern/subr_kdb.c:693 #6 0xffffffff80bb2981 in trap_fatal (frame=0xfffffe0075472870, eva=32) at /usr/src/sys/amd64/amd64/trap.c:921 #7 0xffffffff80bb2a89 in trap_pfault (frame=0xfffffe0075472870, usermode=0) at pcpu.h:230 #8 0xffffffff80bb20ae in trap (frame=0xfffffe0075472870) at /usr/src/sys/amd64/amd64/trap.c:441 #9 0xffffffff80b8eb15 in calltrap () at /usr/src/sys/amd64/amd64/exception.S:232 #10 0xffffffff80859e82 in softclock_call_cc (c=<value optimized out>, cc=0xffffffff81347e00, direct=<value optimized out>) at /usr/src/sys/kern/kern_timeout.c:693 #11 0xffffffff80859c0e in callout_process (now=3074382601577533) at /usr/src/sys/kern/kern_timeout.c:501 #12 0xffffffff80c37b08 in handleevents (now=3074382601577533, fake=1) at /usr/src/sys/kern/kern_clocksource.c:213 #13 0xffffffff80c39307 in cpu_activeclock () at /usr/src/sys/kern/kern_clocksource.c:812 #14 0xffffffff80c6d830 in cpu_idle (busy=0) at /usr/src/sys/x86/x86/cpu_machdep.c:585 #15 0xffffffff80874365 in sched_idletd (dummy=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:2829 #16 0xffffffff80806f03 in fork_exit ( callout=0xffffffff80873e50 <sched_idletd>, arg=0x0, frame=0xfffffe0075472c00) at /usr/src/sys/kern/kern_fork.c:1057 #17 0xffffffff80b8fafe in fork_trampoline () at /usr/src/sys/amd64/amd64/exception.S:993 #18 0x0000000000000000 in ?? () (In reply to Sean Bruno from comment #25) I'll need the contents of /usr/lib/debug/boot/kernel in order to look at the vmcore. (In reply to Mark Johnston from comment #26) I updated freefall.freebsd.org:~sbruno/ftpmirror.tar.gz with the debug files. *** This bug has been marked as a duplicate of bug 234296 *** |