Re: NFS corruption, fixed by echo 1 > /proc/sys/vm/drop_caches -- next debugging steps?

[Matt Turner <mattst88@gmail.com>]

[-- Attachment #1: Type: text/plain, Size: 2614 bytes --]

On Mon, Mar 13, 2017 at 2:47 AM, James Hogan <james.hogan@imgtec.com> wrote:
> On Sun, Mar 12, 2017 at 06:43:47PM -0700, Matt Turner wrote:
>> On a Broadcom BCM91250a MIPS system I can reliably trigger NFS
>> corruption on the first file read.
>>
>> To demonstrate, I downloaded five identical copies of the gcc-5.4.0
>> source tarball. On the NFS server, they hash to the same value:
>>
>> server distfiles # md5sum gcc-5.4.0.tar.bz2*
>> 4c626ac2a83ef30dfb9260e6f59c2b30  gcc-5.4.0.tar.bz2
>> 4c626ac2a83ef30dfb9260e6f59c2b30  gcc-5.4.0.tar.bz2.1
>> 4c626ac2a83ef30dfb9260e6f59c2b30  gcc-5.4.0.tar.bz2.2
>> 4c626ac2a83ef30dfb9260e6f59c2b30  gcc-5.4.0.tar.bz2.3
>> 4c626ac2a83ef30dfb9260e6f59c2b30  gcc-5.4.0.tar.bz2.4
>>
>> On the MIPS system (the NFS client):
>>
>> bcm91250a-le distfiles # md5sum gcc-5.4.0.tar.bz2.2
>> 35346975989954df8a8db2b034da610d  gcc-5.4.0.tar.bz2.2
>> bcm91250a-le distfiles # md5sum gcc-5.4.0.tar.bz2*
>> 4c626ac2a83ef30dfb9260e6f59c2b30  gcc-5.4.0.tar.bz2
>> 4c626ac2a83ef30dfb9260e6f59c2b30  gcc-5.4.0.tar.bz2.1
>> 35346975989954df8a8db2b034da610d  gcc-5.4.0.tar.bz2.2
>> 4c626ac2a83ef30dfb9260e6f59c2b30  gcc-5.4.0.tar.bz2.3
>> 4c626ac2a83ef30dfb9260e6f59c2b30  gcc-5.4.0.tar.bz2.4
>>
>> The first file read will contain some corruption, and it is persistent until...
>>
>> bcm91250a-le distfiles # echo 1 > /proc/sys/vm/drop_caches
>> bcm91250a-le distfiles # md5sum gcc-5.4.0.tar.bz2*
>> 4c626ac2a83ef30dfb9260e6f59c2b30  gcc-5.4.0.tar.bz2
>> 4c626ac2a83ef30dfb9260e6f59c2b30  gcc-5.4.0.tar.bz2.1
>> 4c626ac2a83ef30dfb9260e6f59c2b30  gcc-5.4.0.tar.bz2.2
>> 4c626ac2a83ef30dfb9260e6f59c2b30  gcc-5.4.0.tar.bz2.3
>> 4c626ac2a83ef30dfb9260e6f59c2b30  gcc-5.4.0.tar.bz2.4
>>
>> the caches are dropped, at which point it reads back properly.
>>
>> Note that the corruption is different across reboots, both in the size
>> of the corruption and the location. I saw 1900~ and 1400~ byte
>> sequences corrupted on separate occasions, which don't correspond to
>> the system's 16kB page size.
>>
>> I've tested kernels from v3.19 to 4.11-rc1+ (master branch from
>> today). All exhibit this behavior with differing frequencies. Earlier
>> kernels seem to reproduce the issue less often, while more recent
>> kernels reliably exhibit the problem every boot.
>>
>> How can I further debug this?
>
> It smells a bit like a DMA / caching issue.
>
> Can you provide a full kernel log. That might provide some information
> about caching that might be relevant (e.g. does dcache have aliases?).

Thanks for the reply. Please find attached dmesg from a clean boot
(which reproduced the problem).

[-- Attachment #2: dmesg --]
[-- Type: application/octet-stream, Size: 16527 bytes --]

[    0.000000] Linux version 4.11.0-rc1+ (mattst88@ivybridge) (gcc version 4.9.3 (Gentoo 4.9.3 p1.5, pie-0.6.4) ) #26 SMP Sun Mar 12 15:20:34 PDT 2017
[    0.000000] bootconsole [early0] enabled
[    0.000000] CPU0 revision is: 01040102 (SiByte SB1)
[    0.000000] FPU revision is: 000f0102
[    0.000000] Checking for the multiply/shift bug... no.
[    0.000000] Checking for the daddiu bug... no.
[    0.000000] Broadcom SiByte BCM1250 B2 @ 800 MHz (SB1 rev 2)
[    0.000000] Board type: SiByte BCM91250A (SWARM)
[    0.000000] Determined physical RAM map:
[    0.000000]  memory: 000000000fe7fe00 @ 0000000000000000 (usable)
[    0.000000]  memory: 000000001ffffe00 @ 0000000080000000 (usable)
[    0.000000]  memory: 000000000ffffe00 @ 00000000c0000000 (usable)
[    0.000000]  memory: 000000003ffffe00 @ 0000000100000000 (usable)
[    0.000000] Initrd not found or empty - disabling initrd
[    0.000000] Detected 1 available secondary CPU(s)
[    0.000000] Primary instruction cache 32kB, VIVT, 4-way, linesize 32 bytes.
[    0.000000] Primary data cache 32kB, 4-way, PIPT, no aliases, linesize 32 bytes
[    0.000000] Zone ranges:
[    0.000000]   DMA32    [mem 0x0000000000000000-0x00000000ffffffff]
[    0.000000]   Normal   [mem 0x0000000100000000-0x000000013fffbfff]
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000000000-0x000000000fe7bfff]
[    0.000000]   node   0: [mem 0x0000000080000000-0x000000009fffbfff]
[    0.000000]   node   0: [mem 0x00000000c0000000-0x00000000cfffbfff]
[    0.000000]   node   0: [mem 0x0000000100000000-0x000000013fffbfff]
[    0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x000000013fffbfff]
[    0.000000] On node 0 totalpages: 130972
[    0.000000] free_area_init_node: node 0, pgdat ffffffff80691080, node_mem_map a800000001000100
[    0.000000]   DMA32 zone: 896 pages used for memmap
[    0.000000]   DMA32 zone: 0 pages reserved
[    0.000000]   DMA32 zone: 65437 pages, LIFO batch:7
[    0.000000]   Normal zone: 224 pages used for memmap
[    0.000000]   Normal zone: 65535 pages, LIFO batch:7
[    0.000000] percpu: Embedded 5 pages/cpu @a80000000218c000 s41248 r8192 d32480 u81920
[    0.000000] pcpu-alloc: s41248 r8192 d32480 u81920 alloc=5*16384
[    0.000000] pcpu-alloc: [0] 0 [0] 1 
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 129852
[    0.000000] Kernel command line: root=/dev/sda3 console=duart0
[    0.000000] PID hash table entries: 4096 (order: 1, 32768 bytes)
[    0.000000] Dentry cache hash table entries: 262144 (order: 7, 2097152 bytes)
[    0.000000] Inode-cache hash table entries: 131072 (order: 6, 1048576 bytes)
[    0.000000] Memory: 2066384K/2095552K available (4388K kernel code, 326K rwdata, 1036K rodata, 368K init, 722K bss, 29168K reserved, 0K cma-reserved)
[    0.000000] Hierarchical RCU implementation.
[    0.000000] 	Build-time adjustment of leaf fanout to 64.
[    0.000000] NR_IRQS:128
[    0.000000] clocksource: bcm1250-counter-3: mask: 0x7fffff max_cycles: 0x7fffff, max_idle_ns: 3732930115 ns
[    0.000008] sched_clock: 23 bits at 1000kHz, resolution 1000ns, wraps every 4194303500ns
[    0.008970] kmemleak: Kernel memory leak detector disabled
[    0.013976] Console: colour dummy device 80x25
[    0.017845] console [duart0] enabled
[    0.023462] bootconsole [early0] disabled
[    0.033784] ODEBUG: selftest passed
[    0.037292] kmemleak: Early log buffer exceeded (1512), please increase DEBUG_KMEMLEAK_EARLY_LOG_SIZE
[    0.046373] Calibrating delay loop... 531.45 BogoMIPS (lpj=1062912)
[    0.082138] pid_max: default: 32768 minimum: 301
[    0.087545] Mount-cache hash table entries: 4096 (order: 1, 32768 bytes)
[    0.094131] Mountpoint-cache hash table entries: 4096 (order: 1, 32768 bytes)
[    0.102836] Checking for the daddi bug... no.
[    0.109339] smp: Bringing up secondary CPUs ...
[    0.115098] Primary instruction cache 32kB, VIVT, 4-way, linesize 32 bytes.
[    0.115107] Primary data cache 32kB, 4-way, PIPT, no aliases, linesize 32 bytes
[    0.115224] CPU1 revision is: 03040102 (SiByte SB1)
[    0.115228] FPU revision is: 000f0102
[    0.144150] smp: Brought up 1 node, 2 CPUs
[    0.172125] devtmpfs: initialized
[    0.177423] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.187036] futex hash table entries: 512 (order: 0, 16384 bytes)
[    0.193882] kworker/u4:0 (19) used greatest stack depth: 14536 bytes left
[    0.194164] NET: Registered protocol family 16
[    0.216505] kworker/u4:1 (104) used greatest stack depth: 14384 bytes left
[    0.228169] kworker/u4:1 (67) used greatest stack depth: 14064 bytes left
[    0.243215] SCSI subsystem initialized
[    0.247794] libata version 3.00 loaded.
[    0.248817] PCI host bridge to bus 0000:00
[    0.252837] pci_bus 0000:00: root bus resource [mem 0x40000000-0x5fffffff]
[    0.259606] pci_bus 0000:00: root bus resource [io  0x0000-0x1ffffff]
[    0.265975] pci_bus 0000:00: root bus resource [??? 0x00000000 flags 0x0]
[    0.272677] pci_bus 0000:00: No busn resource found for root bus, will use [bus 00-ff]
[    0.280549] pci 0000:00:00.0: [166d:0001] type 00 class 0x060000
[    0.280575] pci 0000:00:00.0: [Firmware Bug]: reg 0x10: invalid BAR (can't size)
[    0.287833] pci 0000:00:00.0: [Firmware Bug]: reg 0x18: invalid BAR (can't size)
[    0.295140] pci 0000:00:00.0: [Firmware Bug]: reg 0x1c: invalid BAR (can't size)
[    0.302454] pci 0000:00:00.0: reg 0x24: [mem 0x80000000-0xffffffff pref]
[    0.302463] pci 0000:00:00.0: [Firmware Bug]: reg 0x30: invalid BAR (can't size)
[    0.310043] pci 0000:00:01.0: [166d:0002] type 01 class 0x060000
[    0.310303] pci 0000:00:07.0: [1045:c861] type 00 class 0x0c0310
[    0.310325] pci 0000:00:07.0: reg 0x10: [mem 0x41000000-0x41000fff]
[    0.310775] pci 0000:01:01.0: [14d9:0010] type 01 class 0x060400
[    0.311101] pci 0000:00:01.0: PCI bridge to [bus 01-ff]
[    0.316226] pci 0000:00:01.0:   bridge window [io  0x8000-0x8fff]
[    0.316236] pci 0000:00:01.0:   bridge window [mem 0x41100000-0x411fffff]
[    0.316246] pci 0000:00:01.0:   bridge window [mem 0x00000000-0x000fffff pref]
[    0.316463] pci 0000:02:00.0: [1095:3124] type 00 class 0x010400
[    0.316501] pci 0000:02:00.0: reg 0x10: [mem 0x41188000-0x4118807f 64bit]
[    0.316520] pci 0000:02:00.0: reg 0x18: [mem 0x41180000-0x41187fff 64bit]
[    0.316535] pci 0000:02:00.0: reg 0x20: [io  0x8000-0x800f]
[    0.316558] pci 0000:02:00.0: reg 0x30: [mem 0x41100000-0x4117ffff pref]
[    0.316621] pci 0000:02:00.0: supports D1 D2
[    0.316854] pci 0000:01:01.0: PCI bridge to [bus 02-ff]
[    0.321978] pci 0000:01:01.0:   bridge window [io  0x8000-0x8fff]
[    0.321988] pci 0000:01:01.0:   bridge window [mem 0x41100000-0x411fffff]
[    0.322002] pci_bus 0000:02: busn_res: [bus 02-ff] end is updated to 02
[    0.322016] pci_bus 0000:01: busn_res: [bus 01-ff] end is updated to 02
[    0.322028] pci_bus 0000:00: busn_res: [bus 00-ff] end is updated to 02
[    0.322037] pci 0000:00:01.0: PCI bridge to [bus 01-02]
[    0.327142] pci 0000:00:01.0:   bridge window [io  0x8000-0x8fff]
[    0.327151] pci 0000:00:01.0:   bridge window [mem 0x41100000-0x411fffff]
[    0.327159] pci 0000:00:01.0:   bridge window [mem 0x00000000-0x000fffff pref]
[    0.327174] pci 0000:00:01.0: can't claim BAR 9 [mem 0x00000000-0x000fffff pref]: no compatible bridge window
[    0.336942] pci 0000:01:01.0: PCI bridge to [bus 02]
[    0.341846] pci 0000:01:01.0:   bridge window [io  0x8000-0x8fff]
[    0.341855] pci 0000:01:01.0:   bridge window [mem 0x41100000-0x411fffff]
[    0.341871] pci 0000:00:00.0: can't claim BAR 5 [mem 0x80000000-0xffffffff pref]: no compatible bridge window
[    0.353388] clocksource: Switched to clocksource bcm1250-counter-3
[    0.388173] NET: Registered protocol family 2
[    0.393827] TCP established hash table entries: 16384 (order: 3, 131072 bytes)
[    0.401179] TCP bind hash table entries: 16384 (order: 4, 262144 bytes)
[    0.408102] TCP: Hash tables configured (established 16384 bind 16384)
[    0.415436] UDP hash table entries: 1024 (order: 1, 32768 bytes)
[    0.421414] UDP-Lite hash table entries: 1024 (order: 1, 32768 bytes)
[    0.428233] NET: Registered protocol family 1
[    0.434376] RPC: Registered named UNIX socket transport module.
[    0.440204] RPC: Registered udp transport module.
[    0.444832] RPC: Registered tcp transport module.
[    0.449467] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.455906] PCI: CLS 32 bytes, default 32
[    0.458413] pata-swarm: PATA interface at GenBus slot 4
[    0.466900] workingset: timestamp_bits=62 max_order=17 bucket_order=0
[    0.476548] NFS: Registering the id_resolver key type
[    0.481605] Key type id_resolver registered
[    0.485919] Key type id_legacy registered
[    0.490865] io scheduler noop registered
[    0.494899] io scheduler cfq registered (default)
[    0.499508] io scheduler mq-deadline registered
[    0.505093] duart0 at MMIO 0x10060100 (irq = 8, base_baud = 5000000) is a SB1250 DUART
[    0.513261] duart1 at MMIO 0x10060200 (irq = 9, base_baud = 5000000) is a SB1250 DUART
[    0.521796] Uniform Multi-Platform E-IDE driver
[    0.526442] ide-gd driver 1.18
[    0.529685] Probing IDE interface ide0...
[    0.837030] hda: PQI IDE DiskOnModule, ATA DISK drive
[    1.201191] ide0 at 0x90000000100b3e00-0x90000000100b3ee0,0x90000000100b7ec0 on irq 36
[    1.209817] hda: max request size: 128KiB
[    1.213750] hda: 256000 sectors (131 MB) w/0KiB Cache, CHS=500/16/32
[    1.240559]  hda: hda1
[    1.244378] sata_sil24 0000:02:00.0: version 1.1
[    1.244407] PCI: Device 0000:00:01.0 not available because of resource collisions
[    1.251784] pci 0000:00:01.0: Error enabling bridge (-22), continuing
[    1.258126] PCI: Device 0000:00:01.0 not available because of resource collisions
[    1.265516] pci 0000:00:01.0: Error enabling bridge (-22), continuing
[    1.281869] scsi host0: sata_sil24
[    1.286244] scsi host1: sata_sil24
[    1.290209] scsi host2: sata_sil24
[    1.294218] scsi host3: sata_sil24
[    1.297845] ata1: SATA max UDMA/100 host m128@0x41188000 port 0x41180000 irq 57
[    1.305165] ata2: SATA max UDMA/100 host m128@0x41188000 port 0x41182000 irq 57
[    1.312347] ata3: SATA max UDMA/100 host m128@0x41188000 port 0x41184000 irq 57
[    1.319563] ata4: SATA max UDMA/100 host m128@0x41188000 port 0x41186000 irq 57
[    1.320889] random: fast init done
[    1.334568] libphy: sb1250-mac-mdio: probed
[    1.339631] sb1250-mac.0: registered as eth0
[    1.343814] eth0: enabling TCP rcv checksum
[    1.347929] eth0: SiByte Ethernet at 0x10064000, address: 00:02:4c:fe:49:74
[    1.356174] libphy: sb1250-mac-mdio: probed
[    1.361310] sb1250-mac.1: registered as eth1
[    1.365488] eth1: enabling TCP rcv checksum
[    1.369618] eth1: SiByte Ethernet at 0x10065000, address: 00:02:4c:fe:49:75
[    1.376709] i2c /dev entries driver
[    1.380202] i2c-sibyte: i2c SMBus adapter module for SiByte board
[    1.387144] i2c i2c-1: doesn't support I2C_FUNC_SMBUS_BYTE_DATA | I2C_FUNC_SMBUS_I2C_BLOCK
[    1.401925] device-mapper: ioctl: 4.35.0-ioctl (2016-06-23) initialised: dm-devel@redhat.com
[    1.410911] NET: Registered protocol family 17
[    1.415458] Key type dns_resolver registered
[    1.421033] hctosys: unable to open rtc device (rtc0)
[    3.380934] ata1: SATA link down (SStatus 0 SControl 0)
[    5.436927] ata2: SATA link down (SStatus 0 SControl 0)
[    7.516927] ata3: SATA link down (SStatus 0 SControl 0)
[    9.701087] ata4: SATA link up 3.0 Gbps (SStatus 123 SControl 0)
[    9.734140] ata4.00: ATA-8: WDC WD5000AAKS-00A7B2, 01.03B01, max UDMA/133
[    9.740813] ata4.00: 976773168 sectors, multi 0: LBA48 NCQ (depth 31/32)
[    9.748388] ata4.00: configured for UDMA/100
[    9.753869] scsi 3:0:0:0: Direct-Access     ATA      WDC WD5000AAKS-0 3B01 PQ: 0 ANSI: 5
[    9.763845] sd 3:0:0:0: [sda] 976773168 512-byte logical blocks: (500 GB/466 GiB)
[    9.764007] sd 3:0:0:0: Attached scsi generic sg0 type 0
[    9.776587] sd 3:0:0:0: [sda] Write Protect is off
[    9.781293] sd 3:0:0:0: [sda] Mode Sense: 00 3a 00 00
[    9.781471] sd 3:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    9.800638]  sda: sda1 sda2 sda3 sda4
[    9.806979] sd 3:0:0:0: [sda] Attached SCSI disk
[    9.835248] EXT4-fs (sda3): couldn't mount as ext3 due to feature incompatibilities
[    9.843448] EXT4-fs (sda3): couldn't mount as ext2 due to feature incompatibilities
[    9.881147] EXT4-fs (sda3): mounted filesystem with ordered data mode. Opts: (null)
[    9.888792] VFS: Mounted root (ext4 filesystem) readonly on device 8:3.
[    9.919488] devtmpfs: mounted
[    9.923058] Freeing unused kernel memory: 368K
[    9.927450] This architecture does not have kernel memory protection.
[   10.469077] kbd_mode (399) used greatest stack depth: 13832 bytes left
[   10.916773] loadkeys (401) used greatest stack depth: 13128 bytes left
[   10.924377] init-early.sh (398) used greatest stack depth: 12888 bytes left
[   11.976976] random: crng init done
[   13.693548] systemd-udevd[568]: starting version 230
[   14.577994] systemd-udevd[611]: Process 'net.sh eth1 start' failed with exit code 1.
[   14.779932] systemd-udevd[623]: Process 'net.sh eth0 start' failed with exit code 1.
[   15.875399] lvmetad (715) used greatest stack depth: 12832 bytes left
[   19.343421] EXT4-fs (sda3): re-mounted. Opts: (null)
[   20.153044] Adding 2000032k swap on /dev/sda1.  Priority:-1 extents:1 across:2000032k 
[   20.524491] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[   20.580432] REISERFS (device dm-6): found reiserfs format "3.6" with standard journal
[   20.580472] REISERFS (device dm-6): using ordered data mode
[   20.580476] reiserfs: using flush barriers
[   20.587008] REISERFS (device dm-6): journal params: device dm-6, size 8192, journal first block 18, max trans len 1024, max batch 900, max commit age 30, max trans age 30
[   20.589066] REISERFS (device dm-6): checking transaction log (dm-6)
[   20.633777] REISERFS (device dm-6): Using r5 hash to sort names
[   20.684144] REISERFS (device dm-7): found reiserfs format "3.6" with standard journal
[   20.684181] REISERFS (device dm-7): using ordered data mode
[   20.684185] reiserfs: using flush barriers
[   20.689143] REISERFS (device dm-7): journal params: device dm-7, size 8192, journal first block 18, max trans len 1024, max batch 900, max commit age 30, max trans age 30
[   20.691063] REISERFS (device dm-7): checking transaction log (dm-7)
[   20.724046] REISERFS (device dm-7): Using r5 hash to sort names
[   20.763974] REISERFS (device dm-8): found reiserfs format "3.6" with standard journal
[   20.764010] REISERFS (device dm-8): using ordered data mode
[   20.764014] reiserfs: using flush barriers
[   20.769758] REISERFS (device dm-8): journal params: device dm-8, size 8192, journal first block 18, max trans len 1024, max batch 900, max commit age 30, max trans age 30
[   20.771687] REISERFS (device dm-8): checking transaction log (dm-8)
[   20.819345] REISERFS (device dm-8): Using r5 hash to sort names
[   20.867772] REISERFS (device dm-9): found reiserfs format "3.6" with standard journal
[   20.867903] REISERFS (device dm-9): using ordered data mode
[   20.867907] reiserfs: using flush barriers
[   20.873535] REISERFS (device dm-9): journal params: device dm-9, size 8192, journal first block 18, max trans len 1024, max batch 900, max commit age 30, max trans age 30
[   20.875453] REISERFS (device dm-9): checking transaction log (dm-9)
[   20.920603] REISERFS (device dm-9): Using r5 hash to sort names
[   20.963361] REISERFS (device dm-10): found reiserfs format "3.6" with standard journal
[   20.963405] REISERFS (device dm-10): using ordered data mode
[   20.963409] reiserfs: using flush barriers
[   20.969120] REISERFS (device dm-10): journal params: device dm-10, size 8192, journal first block 18, max trans len 1024, max batch 900, max commit age 30, max trans age 30
[   20.971042] REISERFS (device dm-10): checking transaction log (dm-10)
[   21.007382] REISERFS (device dm-10): Using r5 hash to sort names
[   28.428975] Broadcom BCM5421 sb1250-mac-0:01: attached PHY driver [Broadcom BCM5421] (mii_bus:phy_addr=sb1250-mac-0:01, irq=-1)
[   32.516997] eth0: link available: 1000base-FD
[   37.854459] mount.nfs4 (1805) used greatest stack depth: 11872 bytes left