Bug 234906 - kernel panic: softdep_setup_inomapdep: dependency 0xfffff80107d15c00 for newinode already exists
Summary: kernel panic: softdep_setup_inomapdep: dependency 0xfffff80107d15c00 for newi...
Status: New
Alias: None
Product: Base System
Classification: Unclassified
Component: kern (show other bugs)
Version: 12.0-RELEASE
Hardware: amd64 Any
: --- Affects Only Me
Assignee: freebsd-fs (Nobody)
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-01-12 19:13 UTC by johan van Zanten
Modified: 2020-07-02 14:43 UTC (History)
5 users (show)

See Also:


Attachments
core.txt from panic (192.93 KB, text/plain)
2019-01-12 19:13 UTC, johan van Zanten
no flags Details
custom kernel config (less hardware) (14.29 KB, text/plain)
2019-01-12 19:13 UTC, johan van Zanten
no flags Details
core.txt from from the first softdep panic (184.49 KB, text/plain)
2019-01-12 21:20 UTC, johan van Zanten
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description johan van Zanten 2019-01-12 19:13:03 UTC
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.
Comment 1 johan van Zanten 2019-01-12 19:13:49 UTC
Created attachment 201076 [details]
custom kernel config (less hardware)
Comment 2 johan van Zanten 2019-01-12 19:17:32 UTC
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"
Comment 3 Conrad Meyer freebsd_committer 2019-01-12 20:33:01 UTC
(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.
Comment 4 Conrad Meyer freebsd_committer 2019-01-12 20:46:27 UTC
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
Comment 5 Conrad Meyer freebsd_committer 2019-01-12 20:50:11 UTC
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.
Comment 6 johan van Zanten 2019-01-12 21:12:28 UTC
(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.
Comment 7 johan van Zanten 2019-01-12 21:16:57 UTC
(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.
Comment 8 johan van Zanten 2019-01-12 21:20:26 UTC
Created attachment 201082 [details]
core.txt from from the first softdep panic

Here's core.txt.1 as requested.
Comment 9 johan van Zanten 2019-01-12 21:25:19 UTC
(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.
Comment 10 Conrad Meyer freebsd_committer 2019-01-12 22:06:52 UTC
(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?)
Comment 11 Conrad Meyer freebsd_committer 2019-01-12 22:14:31 UTC
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.
Comment 12 johan van Zanten 2019-01-13 11:56:19 UTC
(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.
Comment 13 johan van Zanten 2019-01-13 21:19:31 UTC
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.
Comment 14 Conrad Meyer freebsd_committer 2019-01-13 23:08:53 UTC
(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.
Comment 15 Kirk McKusick freebsd_committer 2019-01-13 23:28:25 UTC
(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.
Comment 16 Conrad Meyer freebsd_committer 2019-01-13 23:56:14 UTC
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.
Comment 17 Conrad Meyer freebsd_committer 2019-01-13 23:57:21 UTC
(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).
Comment 18 johan van Zanten 2019-01-16 07:43:54 UTC
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
Comment 19 johan van Zanten 2019-01-20 22:04:02 UTC
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.
Comment 20 Warner Losh freebsd_committer 2019-01-21 00:22:51 UTC
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.
Comment 21 Conrad Meyer freebsd_committer 2019-01-21 00:41:10 UTC
(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.
Comment 22 Josh Paetzel freebsd_committer 2020-07-02 14:43:35 UTC
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.