Created attachment 201075 [details] core.txt from panic Since upgrading to 12.0-RELEASE about a week ago, i've had two of these kernel panic. Both occurred were when i was compiling a kernel with: cd /usr/src && make -j 4 buildkernel ... The machine running FreeBSD is my desktop, so there's also been firefox and emacs running. It's an Intel i3 M 330 CPU with 8 GB or RAM. I'll attach dmesg from the boot. I was running 11.2 without issues more of last year. After he latest 11.2 in Oct-Nov., i had a reproducible panic at the very end of shutting down, see 223563. The reason i mention this is mainly i had a stable system until recently, so unless the hardware is suffering bit rot, it's otherwise unchanged. I'm afraid this softdep panic is not 100% reproducible. After the machine crashes and reboots, i can complete the same kernel compile without provoking the panic. I'm attaching: /var/crash/core.txt.2 PAPADUM - custom kernel config -- it's mainly just a stripped down to only the limited hardware i need.
Created attachment 201076 [details] custom kernel config (less hardware)
the other possibly relevant changes: loader.conf: kern.cam.boot_delay="10000" # Delay (in ms) of root mount for CAM bus # registration, useful for USB sticks as root #kern.cam.scsi_delay="2000" # Delay (in ms) before probing SCSI usb_load="YES" # USB subsystem umass_load="YES" # Mass Storage Devices # i think these were to reduce power consumption # https://people.freebsd.org/~bcr/laptop_article.html hint.apic.0.clock=0 kern.hz=100 hint.atrtc.0.clock=0 # this is because i'm not use ZFS, and disabling it gives me 4 or 5 GB of RAM back. zfs_load="NO"
(In reply to johan van Zanten from comment #0) PR 223563 appears to be a Firefox port issue, not a shutdown panic? (In reply to johan van Zanten from comment #2) > # this is because i'm not use ZFS, and disabling it gives me 4 or 5 GB of RAM back. > zfs_load="NO" If you aren't using ZFS, the module should not load by default? That line shouldn't be needed.
From core.txt, this wasn't the first softdep panic you encountered; the first was: panic: handle_allocdirect_partdone: lost dep cpuid = 2 time = 1547073542 KDB: stack backtrace: #0 0xffffffff80701677 at kdb_backtrace+0x67 #1 0xffffffff806b6d93 at vpanic+0x1a3 #2 0xffffffff806b6be3 at panic+0x43 #3 0xffffffff80964e98 at handle_allocdirect_partdone+0xd8 #4 0xffffffff8096f503 at handle_written_bmsafemap+0x583 #5 0xffffffff80953962 at softdep_disk_write_complete+0x4e2 #6 0xffffffff80764d14 at bufdone+0x2a4 #7 0xffffffff80603c30 at g_io_deliver+0x230 #8 0xffffffff80603c30 at g_io_deliver+0x230 #9 0xffffffff806012b3 at g_disk_done+0x123 #10 0xffffffff803278e5 at dadone+0x5e5 #11 0xffffffff802cc4a1 at xpt_done_process+0x6a1 #12 0xffffffff802ce726 at xpt_done_td+0x116 #13 0xffffffff80678b23 at fork_exit+0x83 #14 0xffffffff809c944e at fork_trampoline+0xe So at that time, all of your filesystems were detached in an unclean state. After reboot, GEOM reports GPT corruption and background fsck kicks in due to unclean mount. ... WARNING: / was not properly dismounted WARNING: /: mount pending error: blocks 2688 files 2 ... ZFS filesystem version: 5 ZFS storage pool version: features support (5000) Starting file system checks: /dev/ada0p2: UNREF FILE I=15168749 OWNER=johan MODE=100644 /dev/ada0p2: SIZE=1584 MTIME=Jan 7 07:53 2019 (CLEARED) /dev/ada0p2: FREE BLK COUNT(S) WRONG IN SUPERBLK (SALVAGED) /dev/ada0p2: SUMMARY INFORMATION BAD (SALVAGED) /dev/ada0p2: BLK(S) MISSING IN BIT MAPS (SALVAGED) /dev/ada0p2: 705641 files, 13986522 used, 16285630 free (33934 frags, 2031462 blocks, 0.1% fragmentation) /dev/da0p4: DEFER FOR BACKGROUND CHECKING Mounting local filesystems: WARNING: /u was not properly dismounted WARNING: /u: mount pending error: blocks 12048 files 119 ... GEOM: da1: the secondary GPT table is corrupt or invalid. GEOM: da1: using the primary only -- recovery suggested. GEOM: ufsid/5c32f4b585a9f480: the secondary GPT table is corrupt or invalid. GEOM: ufsid/5c32f4b585a9f480: using the primary only -- recovery suggested. GEOM: diskid/DISK-4C530002671026104222: the secondary GPT table is corrupt or invalid. GEOM: diskid/DISK-4C530002671026104222: using the primary only -- recovery suggested. ... The USB device disconnects itself and reconnects for some reason; same error messages from GEOM again. ugen1.6: <SanDisk Cruzer Fit> at usbus1 (disconnected) umass1: at uhub3, port 2, addr 6 (disconnected) da1 at umass-sim1 bus 1 scbus7 target 0 lun 0 da1: <SanDisk Cruzer Fit 1.26> s/n 4C530002671026104222 detached (da1:umass-sim1:1:0:0): Periph destroyed ... da1 at umass-sim1 bus 1 scbus7 target 0 lun 0 da1: <SanDisk Cruzer Fit 1.26> Fixed Direct Access SPC-4 SCSI device da1: Serial Number 4C530002671026104222 da1: 40.000MB/s transfers da1: 30532MB (62530624 512 byte sectors) ... This bit looks like fsck, then our panic as filed: free inode /u/37962415 had -128 blocks free inode /u/37962556 had -4480 blocks free inode /u/37962623 had -13824 blocks free inode /u/37962767 had -192 blocks free inode /u/37962771 had -8000 blocks free inode /u/37962774 had -6080 blocks panic: softdep_setup_inomapdep: dependency 0xfffff80107d15c00 for newinode already exists
I think the subsequent panic after we knew a dirty shutdown occurred is less interesting than the initial panic. Do you have core.txt.1 and can it be attached? (The secondary panic may still be something we would prefer to harden in UFS, but it probably isn't the root cause here.) Another good thing to confirm is that these disks are intact and not corrupting contents. For the ones that support SMART, kick off a long self-test with 'smartctl --test=long /dev/foo' and in a few hours check results with 'smartctl --all /dev/foo'. If you see Reallocated_Sector_ct >0 that's generally a sign a disk is dead.
(In reply to Conrad Meyer from comment #3) > If you aren't using ZFS, the module should not load by default? That line shouldn't be needed. Thanks -- i'd forgotten i'd enabled it in /etc/rc.conf ; i'll remove the enable from rc.conf.
(In reply to Conrad Meyer from comment #3) > PR 223563 appears to be a Firefox port issue, not a shutdown panic? Sorry, i gave you the wrong PR -- it should be 231884 > If you aren't using ZFS, the module should not load by default? That line shouldn't be needed. Thanks -- i'd forgotten i'd enabled it in /etc/rc.conf ; i'll remove the enable from rc.conf.
Created attachment 201082 [details] core.txt from from the first softdep panic Here's core.txt.1 as requested.
(In reply to Conrad Meyer from comment #4) >The USB device disconnects itself and reconnects for some reason; same error messages from GEOM again. > ugen1.6: <SanDisk Cruzer Fit> at usbus1 (disconnected) This (/dev/da1) is a USB thumb drive that i physically removed -- it's not used for any data the computer "depends" upon for normal operation. /dev/da0 is an external-USB-attached hard drive with swap and some non-OS data. It should not be disconnecting. :) /dev/ada0 is an SSD internal to the laptop, and is where / is mounted.
(In reply to johan van Zanten from comment #9) Thanks! Can you show 'tunefs -p /dev/foo' on the UFS filesystem partition(s)? (SU is clearly enabled, but is SU+J?)
Nothing jumps out at me from dmesg in crash.txt.1 prior to the initial panic. Could be bad RAM? i3's don't support ECC but you could try running memtest86 to determine if RAM is an issue. It could also be a softdep bug, but crash.txt doesn't give us much information.
(In reply to Conrad Meyer from comment #10) Thank you for checking into this! root file system (SSD): dejacque:~ # tunefs -p /dev/ada0p2 tunefs: POSIX.1e ACLs: (-a) disabled tunefs: NFSv4 ACLs: (-N) disabled tunefs: MAC multilabel: (-l) disabled tunefs: soft updates: (-n) enabled tunefs: soft update journaling: (-j) disabled tunefs: gjournal: (-J) disabled tunefs: trim: (-t) enabled tunefs: maximum blocks per file in a cylinder group: (-e) 4096 tunefs: average file size: (-f) 16384 tunefs: average number of files in a directory: (-s) 64 tunefs: minimum percentage of free space: (-m) 8% tunefs: space to hold for metadata blocks: (-k) 6408 tunefs: optimization preference: (-o) time /u (data) file system, USB connected HD: dejacque:~ # tunefs -p /dev/da0p4 tunefs: POSIX.1e ACLs: (-a) disabled tunefs: NFSv4 ACLs: (-N) disabled tunefs: MAC multilabel: (-l) disabled tunefs: soft updates: (-n) enabled tunefs: soft update journaling: (-j) disabled tunefs: gjournal: (-J) disabled tunefs: trim: (-t) disabled tunefs: maximum blocks per file in a cylinder group: (-e) 4096 tunefs: average file size: (-f) 16384 tunefs: average number of files in a directory: (-s) 64 tunefs: minimum percentage of free space: (-m) 8% tunefs: space to hold for metadata blocks: (-k) 6408 tunefs: optimization preference: (-o) time tunefs: volume label: (-L) I'll give memtest86 a shot.
regarding the memory testing: = memtest86+ -- my laptop can't boot the ISO image on a USB stick ; maybe a UEFI compat problem. I installed the memtest86+ package and tried to boot from the FreeBSD menu (unload ; load /boot/opt/memtest86+). As soon as i hit return, i get a black screen, and then the machine immediately reboots without doing any work. = memtester -- i ran three instances concurrently to test 6.83 GB of the 8 GB of RAM (any more RAM and the OS started paging). After four loops, no errors were found. Given that i wasn't have any problems using this same config as a desktop running FreeBSD 10 or 11, with the same sort of workload, it seems less likely that RAM is the problem. Lines 11214 to 11234 from /usr/src/sys/ufs/ffs/ffs_softdep.c: /* * If we have reached the end of the current list without * finding the just finished dependency, then it must be * on the future dependency list. Future dependencies cannot * be freed until they are moved to the current list. */ if (listadp == NULL) { #ifdef DEBUG if (adp->ad_state & EXTDATA) listhead = &inodedep->id_newextupdt; else listhead = &inodedep->id_newinoupdt; TAILQ_FOREACH(listadp, listhead, ad_next) /* found our block */ if (listadp == adp) break; if (listadp == NULL) panic("handle_allocdirect_partdone: lost dep"); #endif /* DEBUG */ return; } --- That matches the panic sting from Wed Jan 9 23:41:29 CET 2019, but assuming that's where the system is panicking, one still needs to find out how the system is arriving in that state.
(In reply to johan van Zanten from comment #13) > memtest86+ -- my laptop can't boot the ISO image on a USB stick ; maybe a UEFI compat problem Yeah, memtest86+ is legacy BIOS only :-(. > Given that i wasn't have any problems using this same config as a desktop > running FreeBSD 10 or 11, with the same sort of workload, it seems less likely > that RAM is the problem. Sure. > That matches the panic sting from Wed Jan 9 23:41:29 CET 2019, but assuming > that's where the system is panicking, one still needs to find out how the > system is arriving in that state. Yes, that's definitely the panic. The latter is the open question :-). One thing that landed in 12 for UFS was TRIM consolidation, which does interact with softupdates and could plausibly explain this. You have trim enabled on ada0p2 (root) but not the other disk. You could try either disabling consolidation (sysctl vfs.ffs.dotrimcons=0) or disabling TRIM on the filesystem (tunefs -t disable /dev/ada0p2). Also, kib did some softdep refactoring in 327722 and 327723; Kirk did something in this area back in 2016 in r304239. I don't know what if any of that was already backported to 11.x and landed in 11.2 or whatever. I'm not sure about the secondary panic.
(In reply to Conrad Meyer from comment #14) Just catching up on recently reported bugs. Thanks for working on tracking this down. Your suggestion on turning off TRIM consolidation is a good one. My 2016 change, -r304239 was to fix softdep roll-forward after transient write failure. It was MFC'ed to 10-stable and 11-stable on 17-October-2016 so is not likely to be the cause of this bug. kib's 2018 changes, -r327722 and -r327723 were to fix some missing locking issues. They were MFC'ed to 11-stable on 16-January-2018.
Re secondary panic, we drop UMP lock around setup_inomapdep, but that should be ok because we still hold the CG buf exclusively -- no one else should be able to allocate the same inode number. I think the panic could be explained by the inode being allocated but unreferenced in the CG bitmap. Possibly due to violation of ordering constraints implied by the first panic — e.g., inode and directory entry written, but CG bitmap stale. Or perhaps dirent is stale. Or possibly due to write-cache enabled disk (which is another way SU ordering constraints can be violated). But the handle_written_bmsafemap <-> softdep_setup_inomapdep link is suspicious to me and I suspect they are directly related. I would guess CG bitmap accuracy is enforced for non-SU filesystems by a more thorough fsck on dirty mount, but might be mistaken. On non-SU we would not hit this panic because the inodedep would not exist, of course. But we would hit 'ffs_valloc: dup alloc' shortly afterwards when we noticed the dinode was already initialized. Either way, (as far as I can tell) path lookup does not confirm that an inode referred to by a directory entry is actually allocated in the CG bitmap. It is simply assumed to be consistent. So you might have an active UFS vnode with that inode number with inodedeps for a variety of reasons, and some thread comes along and tries to create a file; that number is free in the CG bitmap, so the second thread acquires it; and then the creating thread collides with the existing softdep work. I don't know of a good way to fix the secondary panic. A good next step would be to determine if your drives have write caching disabled, and if the drive model is known to respect that bit or not.
(In reply to Kirk McKusick from comment #15) Thanks! The MFC history helps narrow down the scope of suspect SU changes (if it is a new regression).
Thanks for the suggestions Kirk & Conrad. I'll do some experiments this weekend and see if i can come up with a way to reliably trigger the panic, and then look at disabling TRIM and then the disk's write cache. As for the disk cache on the hard disk, here's information about it: dejacque:~ # camcontrol identify da0 pass3: <HGST HTS541010A9E680 JA0OA560> ATA8-ACS SATA 3.x device pass3: 40.000MB/s transfers protocol ATA/ATAPI-8 SATA 3.x device model HGST HTS541010A9E680 firmware revision JA0OA560 serial number JD1008DM0W2BEV WWN 5000cca827cc4ee9 cylinders 16383 heads 16 sectors/track 63 sector size logical 512, physical 4096, offset 0 LBA supported 268435455 sectors LBA48 supported 1953525168 sectors PIO supported PIO4 DMA supported WDMA2 UDMA6 media RPM 5400 Zoned-Device Commands no Feature Support Enabled Value Vendor read ahead yes yes write cache yes yes flush cache yes yes overlap no Tagged Command Queuing (TCQ) no no Native Command Queuing (NCQ) yes 32 tags NCQ Queue Management no NCQ Streaming no Receive & Send FPDMA Queued no SMART yes yes microcode download yes yes security yes no power management yes yes advanced power management yes yes 128/0x80 automatic acoustic management no no media status notification no no power-up in Standby yes no write-read-verify no no unload yes yes general purpose logging yes yes free-fall no no Data Set Management (DSM/TRIM) no Host Protected Area (HPA) yes no 1953525168/1953525168 HPA - Security no
This is mostly an insubstantial update: I've not seen either file system related panic since 12 Jan (the ones already documented here). I have tried recompiling kernels a few times, to no effect. FWiW, most of the I/O in these situations is with the HD (not the SSD) as i've deliberately kept things off of the SSD that "change a lot" in order to prolong the life of the SSD. So while the OS and installed packages are on the SSD, my homedir and /usr/src are on the HD. I do this with nullfs mounts and symlinks. This might be significant because my web browser's cache is on the HD, and there's a certain about of randomish churn that takes place. Perhaps the combination of the browser I/O and a 4-job build (with ccache) that sometimes produces the panic. If i can isolate something that seems to cause the panics, i'll try disabling TRIM and see if the panics go away.
Unless the drives you are using have firmware bugs with TRIMs, I don't think that you'll change anything. TRIM bugs in firmware are rare, but when they happen they usually result in weird data corruption. While FreeBSD doesn't need the TRIMs, your SSD will do a lot of extra writes if you don't do them, wearing it out sooner.
(In reply to Warner Losh from comment #20) The hypothesis isn't that the drive is corrupting data, but that the UFS trim consolidate logic in particular may have a softdep bug which lead to corrupt state. Disabling trim is just a proxy for disabling trim consolidation. I guess another way to target that specifically would just be vfs.ffs.dotrimcons=0. Separate from that, there is the possibility that some function of the drive itself injected corruption (volatile write cache or whatever) -- but that explanation is unrelated to TRIM.
Just as a data point: We just saw this panic yesterday on a system running FreeBSD 12.0-CURRENT #2 r332472 The machine is a VM on ESXi 6.5. It paniced when it's virtual disks went out to lunch, then had this panic when it rebooted and was running bg_fsck. I think the SU code is a victim here of the disks.