Bug 202441 - Possibly vfs cache related replicable xfs regression since 4.19.0 on sata hdd:s
Summary: Possibly vfs cache related replicable xfs regression since 4.19.0 on sata hdd:s
Status: NEW
Alias: None
Product: File System
Classification: Unclassified
Component: XFS (show other bugs)
Hardware: x86-64 Linux
: P1 normal
Assignee: FileSystem/XFS Default Virtual Assignee
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-01-28 20:41 UTC by Roger
Modified: 2019-02-03 08:12 UTC (History)
1 user (show)

See Also:
Kernel Version: 4.19.0 - 5.0-rc3
Tree: Mainline
Regression: Yes


Attachments
meminfo and xfs_info 4.19.0-rc1 (3.85 KB, text/plain)
2019-01-29 09:09 UTC, Roger
Details
dmesg with sysrq show blocked state for a run on 4.19.0-rc1 (101.25 KB, text/plain)
2019-01-29 09:11 UTC, Roger
Details
revert patch (822 bytes, patch)
2019-01-29 22:23 UTC, Dave Chinner
Details | Diff

Description Roger 2019-01-28 20:41:36 UTC
I have a file system related problem where a compile job on a sata hdd almost stops and ui becomes unresponsive when copying large files at the same time, regardless of to what disk or from where they are copied.

All testing has been done on "bare metal" without even md, lvm or similar.
I have done a lot of testing of many different kernel versions on two different systems (Slackware 14.2 and "current") and I feel confident that this is a kernel regression.

The problem is _very_ pronounced when using xfs and it is only present from kernel version 4.19.0 and all following versions NOT before (I have not tested any 4.19 rc versions). I have tested many of them including the latest 4.19.18 and 5.0-rc3 with varying configurations and some very limited testing on 4.20.4.

It affects jfs, ext2, ext3, ext4 also but to a much lesser extent.
btrfs and reiserfs does not seem to be affected at all, at least not on the 4.19 series.

After adding another 16GB ram on one of my testing machines I noticed that it took much more time before the compile job slowed down and ui became unresponsive, so I suspected some cache related issue.
I made a few test runs and while watching "top" I observed that as soon as buff/cache passed ~ 23G (total 24G) while copying, the compile job slowed down to almost a halt, while the copying also slowed down significantly.

After echo 0 >/proc/sys/vm/vfs_cache_pressure the compilation runs without slowdown all the way through, while copying retains its steady +100MB/sec.
This "solution" is tested on 4.19.17-18 with "generic" Slackware config
and 5.0-rc3 both on xfs.

Here's how I hit this issue every time on a pre-zen AMD:

1. A decent amount of data to copy, probably at least 5-10 times as much as ram and reasonably fast media (~100Mb/sec) to copy from and to (Gbit nfs mount, usb3 drive, regular hard drive...).

2. A dedicated xfs formatted regular rotating hard drive for the compile job (I suppose any io-latency sensitive parallellizable job will do), This problem is probably present for ssd's as well, but because they are so fast, cache becomes less of an issue and you will maybe not notice much, at least I don't.

Compile job: defconfig linux kernel compile (parallellizable easy to redo).
Now open a few terminals with "top" in one of them, start copying in another (use mc, easy to start and stop). Watch buff/cache grow in top, as is reaches to within 70-80% of your ram, start compilation in another terminal, I use "time make -j16" on my eight core 9590 AMD.

Under these circumstances a defconfig kernel compile (ver 4.19.17) takes about 3min 35s on 4.18.20 (xfs) and sometimes more than an hour using any version after it. On Slackware "current" I use gcc 8.2.0 multilib, on 14.2 regular gcc 5.5.0 which seemed to produce slightly better results.
Comment 1 Dave Chinner 2019-01-28 22:00:12 UTC
Hi roger,

On Mon, Jan 28, 2019 at 08:41:36PM +0000, bugzilla-daemon@bugzilla.kernel.org wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=202441

[...]

> I have a file system related problem where a compile job on a sata hdd almost
> stops and ui becomes unresponsive when copying large files at the same time,
> regardless of to what disk or from where they are copied.

Thanks for the detailed bug report! I'll need some more information
about your system and storage to understand (and hopefully
reproduce) the symptoms you are seeing. Can you provide the
information listed here, please?

http://xfs.org/index.php/XFS_FAQ#Q:_What_information_should_I_include_when_reporting_a_problem.3F

> All testing has been done on "bare metal" without even md, lvm or similar.
> I have done a lot of testing of many different kernel versions on two
> different
> systems (Slackware 14.2 and "current") and I feel confident that this is a
> kernel regression.
> 
> The problem is _very_ pronounced when using xfs and it is only present from
> kernel version 4.19.0 and all following versions NOT before (I have not
> tested
> any 4.19 rc versions). I have tested many of them including the latest
> 4.19.18
> and 5.0-rc3 with varying configurations and some very limited testing on
> 4.20.4.
> 
> It affects jfs, ext2, ext3, ext4 also but to a much lesser extent.
> btrfs and reiserfs does not seem to be affected at all, at least not on the
> 4.19 series.

Ok, that's interesting, because it's the second report of similar
problems on 4.19:

https://bugzilla.kernel.org/show_bug.cgi?id=202349

I've not been able to reproduce the problems as documented in that
bug because all my test systems are headless, but in trying to
reproduce it I have seen some concerning behaviour that leads to
massive slowdowns that I don't ever recall seeing before. I'm hoping
that your problem is what I've seen, and not something different.

> After adding another 16GB ram on one of my testing machines I noticed that it
> took much more time before the compile job slowed down and ui became
> unresponsive, so I suspected some cache related issue.
> I made a few test runs and while watching "top" I observed that as soon as
> buff/cache passed ~ 23G (total 24G) while copying, the compile job slowed
> down
> to almost a halt, while the copying also slowed down significantly.
> 
> After echo 0 >/proc/sys/vm/vfs_cache_pressure the compilation runs without
> slowdown all the way through, while copying retains its steady +100MB/sec.
> This "solution" is tested on 4.19.17-18 with "generic" Slackware config
> and 5.0-rc3 both on xfs.

Ok, so you turn off inode reclaim, and so page cache pressure
doesn't cause inodes to be reclaimed anymore. That's something I've
tested, and while it does alleviate the symptoms it eventually ends
up OOM killing the test machines dead because the inode cache takes
all of memory and can't be reclaimed. This is a documented side
effect of this modification - Documentation/sysctl/vm.txt:

	[....] When vfs_cache_pressure=0, the kernel will never
	reclaim dentries and inodes due to memory pressure and this
	can easily lead to out-of-memory conditions. [....]

> Here's how I hit this issue every time on a pre-zen AMD:
> 
> 1. A decent amount of data to copy, probably at least 5-10 times as much as
> ram
> and reasonably fast media (~100Mb/sec) to copy from and to (Gbit nfs mount,
> usb3 drive, regular hard drive...).

Ok, so you add a large amount of page cache pressure, some dirty
inodes.

> 2. A dedicated xfs formatted regular rotating hard drive for the compile job
> (I
> suppose any io-latency sensitive parallellizable job will do), This problem
> is
> probably present for ssd's as well, but because they are so fast, cache
> becomes
> less of an issue and you will maybe not notice much, at least I don't.

Ok, so now you add memory pressure (gcc) along with temporary and
dirty XFS inodes. Is the system swapping?

Can you get me the dmesg output of several samples (maybe 10?) of
"echo w > /sysrq/trigger" a few seconds apart when the compile job
is running?

> Under these circumstances a defconfig kernel compile (ver 4.19.17) takes
> about
> 3min 35s on 4.18.20 (xfs) and sometimes more than an hour using any version
> after it. On Slackware "current" I use gcc 8.2.0 multilib, on 14.2 regular
> gcc
> 5.5.0 which seemed to produce slightly better results.

I note that in 4.19 there was a significant rework of the mm/ code
that drives the shrinkers that do inode cache reclaim. I suspect
we are seeing the fallout of these changes - are you able to confirm
that the change occurred between 4.18 and 4.19-rc1 and perhaps run a
bisect on the mm/ directory over that window?

Thanks again for the detailed bug report!

Cheers,

Dave.
Comment 2 Roger 2019-01-28 23:26:32 UTC
Hello Dave !
Thanks for the really fast reply :)
Here is most of the (rather lengthy) system information:

Single "eight" core processor:

rogan@trooper:~$ uname -a
Linux trooper.morgoth.org 4.19.18 #2 SMP Sat Jan 26 13:43:16 CST 2019 x86_64 AMD FX(tm)-9590 Eight-Core Processor AuthenticAMD GNU/Linux

root@trooper:~# xfs_repair -V
xfs_repair version 4.19.0

root@trooper:~# cat /proc/meminfo 
MemTotal:       24645396 kB
MemFree:          358452 kB
MemAvailable:   22044292 kB
Buffers:            3152 kB
Cached:         22005216 kB
SwapCached:            0 kB
Active:          1713092 kB
Inactive:       21824100 kB
Active(anon):    1157816 kB
Inactive(anon):   555736 kB
Active(file):     555276 kB
Inactive(file): 21268364 kB
Unevictable:           0 kB
Mlocked:               0 kB
SwapTotal:       8388604 kB
SwapFree:        8388604 kB
Dirty:              5980 kB
Writeback:             0 kB
AnonPages:       1528944 kB
Mapped:           531340 kB
Shmem:            254920 kB
Slab:             565012 kB
SReclaimable:     502684 kB
SUnreclaim:        62328 kB
KernelStack:       10448 kB
PageTables:        18100 kB
NFS_Unstable:          0 kB
Bounce:                0 kB
WritebackTmp:          0 kB
CommitLimit:    20711300 kB
Committed_AS:    5195092 kB
VmallocTotal:   34359738367 kB
VmallocUsed:           0 kB
VmallocChunk:          0 kB
Percpu:             3232 kB
HardwareCorrupted:     0 kB
AnonHugePages:         0 kB
ShmemHugePages:        0 kB
ShmemPmdMapped:        0 kB
CmaTotal:              0 kB
CmaFree:               0 kB
DirectMap4k:     2698836 kB
DirectMap2M:    22364160 kB
DirectMap1G:           0 kB

root@trooper:~# cat /proc/mounts 
proc /proc proc rw,relatime 0 0
sysfs /sys sysfs rw,relatime 0 0
tmpfs /run tmpfs rw,nosuid,nodev,noexec,relatime,size=32768k,mode=755 0 0
devtmpfs /dev devtmpfs rw,relatime,size=8192k,nr_inodes=3070316,mode=755 0 0
/dev/sda1 / xfs rw,relatime,attr2,inode64,noquota 0 0
devpts /dev/pts devpts rw,relatime,gid=5,mode=620,ptmxmode=000 0 0
tmpfs /dev/shm tmpfs rw,relatime 0 0
cgroup_root /sys/fs/cgroup tmpfs rw,relatime,size=8192k,mode=755 0 0
cpuset /sys/fs/cgroup/cpuset cgroup rw,relatime,cpuset,clone_children 0 0
cpu /sys/fs/cgroup/cpu cgroup rw,relatime,cpu 0 0
cpuacct /sys/fs/cgroup/cpuacct cgroup rw,relatime,cpuacct 0 0
blkio /sys/fs/cgroup/blkio cgroup rw,relatime,blkio 0 0
memory /sys/fs/cgroup/memory cgroup rw,relatime,memory 0 0
devices /sys/fs/cgroup/devices cgroup rw,relatime,devices 0 0
freezer /sys/fs/cgroup/freezer cgroup rw,relatime,freezer 0 0
net_cls /sys/fs/cgroup/net_cls cgroup rw,relatime,net_cls 0 0
perf_event /sys/fs/cgroup/perf_event cgroup rw,relatime,perf_event,release_agent=/run/cgmanager/agents/cgm-release-agent.perf_event 0 0
net_prio /sys/fs/cgroup/net_prio cgroup rw,relatime,net_prio 0 0
pids /sys/fs/cgroup/pids cgroup rw,relatime,pids,release_agent=/run/cgmanager/agents/cgm-release-agent.pids 0 0
/dev/sdb1 /home xfs rw,nosuid,nodev,relatime,attr2,inode64,noquota 0 0
192.168.1.2:/export/vol0 /export/vol0 nfs rw,relatime,vers=3,rsize=8192,wsize=8192,namlen=255,hard,proto=tcp,timeo=10,retrans=2,sec=sys,mountaddr=192.168.1.2,mountvers=3,mountport=887,mountproto=tcp,local_lock=none,addr=192.168.1.2 0 0
192.168.1.2:/export/vol1 /export/vol1 nfs rw,relatime,vers=3,rsize=8192,wsize=8192,namlen=255,hard,proto=tcp,timeo=10,retrans=2,sec=sys,mountaddr=192.168.1.2,mountvers=3,mountport=887,mountproto=tcp,local_lock=none,addr=192.168.1.2 0 0
192.168.1.2:/export/vol2 /export/vol2 nfs rw,relatime,vers=3,rsize=8192,wsize=8192,namlen=255,hard,proto=tcp,timeo=10,retrans=2,sec=sys,mountaddr=192.168.1.2,mountvers=3,mountport=887,mountproto=tcp,local_lock=none,addr=192.168.1.2 0 0
192.168.1.2:/export/vol3 /export/vol3 nfs rw,relatime,vers=3,rsize=8192,wsize=8192,namlen=255,hard,proto=tcp,timeo=10,retrans=2,sec=sys,mountaddr=192.168.1.2,mountvers=3,mountport=887,mountproto=tcp,local_lock=none,addr=192.168.1.2 0 0
192.168.1.2:/export/vol4 /export/vol4 nfs rw,relatime,vers=3,rsize=8192,wsize=8192,namlen=255,hard,proto=tcp,timeo=10,retrans=2,sec=sys,mountaddr=192.168.1.2,mountvers=3,mountport=887,mountproto=tcp,local_lock=none,addr=192.168.1.2 0 0
devpts /dev/pts devpts rw,relatime,gid=5,mode=620,ptmxmode=000 0 0
fusectl /sys/fs/fuse/connections fusectl rw,relatime 0 0
gvfsd-fuse /home/rogan/.gvfs fuse.gvfsd-fuse rw,nosuid,nodev,relatime,user_id=1000,group_id=100 0 0
/dev/sdc1 /mnt/d0 xfs rw,relatime,attr2,inode64,noquota 0 0
/dev/sdd1 /mnt/d1 xfs rw,relatime,attr2,inode64,noquota 0 0
/dev/sde1 /mnt/d2 xfs rw,relatime,attr2,inode64,noquota 0 0

root@trooper:~# cat /proc/partitions 
major minor  #blocks  name

   1        0      16384 ram0
   1        1      16384 ram1
   1        2      16384 ram2
   1        3      16384 ram3
   1        4      16384 ram4
   1        5      16384 ram5
   1        6      16384 ram6
   1        7      16384 ram7
   1        8      16384 ram8
   1        9      16384 ram9
   1       10      16384 ram10
   1       11      16384 ram11
   1       12      16384 ram12
   1       13      16384 ram13
   1       14      16384 ram14
   1       15      16384 ram15
   8        0  244198584 sda
   8        1  244198535 sda1
   8       16  468851544 sdb
   8       17  468851495 sdb1
   8       32  976762584 sdc
   8       33  976761560 sdc1
   8       48  976762584 sdd
   8       49  976761560 sdd1
   8       64  976762584 sde
   8       65  976761560 sde1
  11        0    1048575 sr0

root@trooper:~# hdparm -I /dev/sd[abcde]

/dev/sda:

ATA device, with non-removable media
	Model Number:       WDC WDS250G2B0A-00SM50                  
	Serial Number:      173859420723        
	Firmware Revision:  X61130WD
	Media Serial Num:   
	Media Manufacturer: 
	Transport:          Serial, ATA8-AST, SATA 1.0a, SATA II Extensions, SATA Rev 2.5, SATA Rev 2.6, SATA Rev 3.0
Standards:
	Used: unknown (minor revision code 0x005e) 
	Supported: 11 10 9 8 7 6 5 
	Likely used: 11
Configuration:
	Logical		max	current
	cylinders	16383	0
	heads		16	0
	sectors/track	63	0
	--
	LBA    user addressable sectors:   268435455
	LBA48  user addressable sectors:   488397168
	Logical  Sector size:                   512 bytes
	Physical Sector size:                   512 bytes
	Logical Sector-0 offset:                  0 bytes
	device size with M = 1024*1024:      238475 MBytes
	device size with M = 1000*1000:      250059 MBytes (250 GB)
	cache/buffer size  = unknown
	Form Factor: 2.5 inch
	Nominal Media Rotation Rate: Solid State Device
Capabilities:
	LBA, IORDY(can be disabled)
	Queue depth: 32
	Standby timer values: spec'd by Standard, no device specific minimum
	R/W multiple sector transfer: Max = 1	Current = 1
	Advanced power management level: 128
	DMA: mdma0 mdma1 mdma2 udma0 udma1 udma2 udma3 udma4 udma5 *udma6 
	     Cycle time: min=120ns recommended=120ns
	PIO: pio0 pio1 pio2 pio3 pio4 
	     Cycle time: no flow control=120ns  IORDY flow control=120ns
Commands/features:
	Enabled	Supported:
	   *	SMART feature set
	    	Security Mode feature set
	   *	Power Management feature set
	   *	Write cache
	   *	Look-ahead
	   *	WRITE_BUFFER command
	   *	READ_BUFFER command
	   *	DOWNLOAD_MICROCODE
	   *	Advanced Power Management feature set
	   *	48-bit Address feature set
	   *	Mandatory FLUSH_CACHE
	   *	FLUSH_CACHE_EXT
	   *	SMART error logging
	   *	SMART self-test
	   *	General Purpose Logging feature set
	   *	64-bit World wide name
	   *	WRITE_UNCORRECTABLE_EXT command
	   *	{READ,WRITE}_DMA_EXT_GPL commands
	   *	Segmented DOWNLOAD_MICROCODE
	    	unknown 119[8]
	   *	Gen1 signaling speed (1.5Gb/s)
	   *	Gen2 signaling speed (3.0Gb/s)
	   *	Gen3 signaling speed (6.0Gb/s)
	   *	Native Command Queueing (NCQ)
	   *	Phy event counters
	   *	READ_LOG_DMA_EXT equivalent to READ_LOG_EXT
	   *	DMA Setup Auto-Activate optimization
	    	Device-initiated interface power management
	    	Asynchronous notification (eg. media change)
	   *	Software settings preservation
	    	Device Sleep (DEVSLP)
	   *	SANITIZE feature set
	   *	BLOCK_ERASE_EXT command
	   *	DOWNLOAD MICROCODE DMA command
	   *	WRITE BUFFER DMA command
	   *	READ BUFFER DMA command
	   *	Data Set Management TRIM supported (limit 8 blocks)
	   *	Deterministic read ZEROs after TRIM
Security: 
	Master password revision code = 65534
		supported
	not	enabled
	not	locked
		frozen
	not	expired: security count
		supported: enhanced erase
	2min for SECURITY ERASE UNIT. 2min for ENHANCED SECURITY ERASE UNIT.
Logical Unit WWN Device Identifier: 5001b444a973c828
	NAA		: 5
	IEEE OUI	: 001b44
	Unique ID	: 4a973c828
Device Sleep:
	DEVSLP Exit Timeout (DETO): 30 ms (drive)
	Minimum DEVSLP Assertion Time (MDAT): 30 ms (drive)
Checksum: correct

/dev/sdb:

ATA device, with non-removable media
	Model Number:       INTEL SSDSC2KW480H6                     
	Serial Number:      CVLT62460810480EGN  
	Firmware Revision:  LSF031C
	Transport:          Serial, ATA8-AST, SATA 1.0a, SATA II Extensions, SATA Rev 2.5, SATA Rev 2.6, SATA Rev 3.0
Standards:
	Used: unknown (minor revision code 0xffff) 
	Supported: 10 9 8 7 6 5 
	Likely used: 10
Configuration:
	Logical		max	current
	cylinders	16383	16383
	heads		16	16
	sectors/track	63	63
	--
	CHS current addressable sectors:    16514064
	LBA    user addressable sectors:   268435455
	LBA48  user addressable sectors:   937703088
	Logical  Sector size:                   512 bytes
	Physical Sector size:                   512 bytes
	Logical Sector-0 offset:                  0 bytes
	device size with M = 1024*1024:      457862 MBytes
	device size with M = 1000*1000:      480103 MBytes (480 GB)
	cache/buffer size  = unknown
	Form Factor: 2.5 inch
	Nominal Media Rotation Rate: Solid State Device
Capabilities:
	LBA, IORDY(can be disabled)
	Queue depth: 32
	Standby timer values: spec'd by Standard, no device specific minimum
	R/W multiple sector transfer: Max = 16	Current = 16
	Advanced power management level: 254
	DMA: mdma0 mdma1 mdma2 udma0 udma1 udma2 udma3 udma4 udma5 *udma6 
	     Cycle time: min=120ns recommended=120ns
	PIO: pio0 pio1 pio2 pio3 pio4 
	     Cycle time: no flow control=120ns  IORDY flow control=120ns
Commands/features:
	Enabled	Supported:
	   *	SMART feature set
	    	Security Mode feature set
	   *	Power Management feature set
	   *	Write cache
	   *	Look-ahead
	   *	Host Protected Area feature set
	   *	WRITE_BUFFER command
	   *	READ_BUFFER command
	   *	NOP cmd
	   *	DOWNLOAD_MICROCODE
	   *	Advanced Power Management feature set
	   *	48-bit Address feature set
	   *	Mandatory FLUSH_CACHE
	   *	FLUSH_CACHE_EXT
	   *	SMART error logging
	   *	SMART self-test
	   *	General Purpose Logging feature set
	   *	WRITE_{DMA|MULTIPLE}_FUA_EXT
	   *	64-bit World wide name
	   *	IDLE_IMMEDIATE with UNLOAD
	   *	WRITE_UNCORRECTABLE_EXT command
	   *	{READ,WRITE}_DMA_EXT_GPL commands
	   *	Segmented DOWNLOAD_MICROCODE
	   *	Gen1 signaling speed (1.5Gb/s)
	   *	Gen2 signaling speed (3.0Gb/s)
	   *	Gen3 signaling speed (6.0Gb/s)
	   *	Native Command Queueing (NCQ)
	   *	Host-initiated interface power management
	   *	Phy event counters
	   *	DMA Setup Auto-Activate optimization
	    	Device-initiated interface power management
	   *	Software settings preservation
	    	Device Sleep (DEVSLP)
	   *	SMART Command Transport (SCT) feature set
	   *	SCT Error Recovery Control (AC3)
	   *	SCT Features Control (AC4)
	   *	SCT Data Tables (AC5)
	   *	SANITIZE feature set
	   *	CRYPTO_SCRAMBLE_EXT command
	   *	BLOCK_ERASE_EXT command
	   *	reserved 69[4]
	   *	DOWNLOAD MICROCODE DMA command
	   *	WRITE BUFFER DMA command
	   *	READ BUFFER DMA command
	   *	Data Set Management TRIM supported (limit 8 blocks)
	   *	Deterministic read data after TRIM
Security: 
	Master password revision code = 65534
		supported
	not	enabled
	not	locked
		frozen
	not	expired: security count
		supported: enhanced erase
	4min for SECURITY ERASE UNIT. 2min for ENHANCED SECURITY ERASE UNIT.
Logical Unit WWN Device Identifier: 55cd2e414d07e84e
	NAA		: 5
	IEEE OUI	: 5cd2e4
	Unique ID	: 14d07e84e
Device Sleep:
	DEVSLP Exit Timeout (DETO): 20 ms (drive)
	Minimum DEVSLP Assertion Time (MDAT): 31 ms (drive)
Checksum: correct

/dev/sdc:

ATA device, with non-removable media
	Model Number:       ST1000DM003-1ER162                      
	Serial Number:      Z4Y5FJF6
	Firmware Revision:  CC45    
	Transport:          Serial, SATA 1.0a, SATA II Extensions, SATA Rev 2.5, SATA Rev 2.6, SATA Rev 3.0
Standards:
	Used: unknown (minor revision code 0x001f) 
	Supported: 9 8 7 6 5 
	Likely used: 9
Configuration:
	Logical		max	current
	cylinders	16383	16383
	heads		16	16
	sectors/track	63	63
	--
	CHS current addressable sectors:    16514064
	LBA    user addressable sectors:   268435455
	LBA48  user addressable sectors:  1953525168
	Logical  Sector size:                   512 bytes
	Physical Sector size:                  4096 bytes
	Logical Sector-0 offset:                  0 bytes
	device size with M = 1024*1024:      953869 MBytes
	device size with M = 1000*1000:     1000204 MBytes (1000 GB)
	cache/buffer size  = unknown
	Form Factor: 3.5 inch
	Nominal Media Rotation Rate: 7200
Capabilities:
	LBA, IORDY(can be disabled)
	Queue depth: 32
	Standby timer values: spec'd by Standard, no device specific minimum
	R/W multiple sector transfer: Max = 16	Current = 16
	Advanced power management level: 254
	Recommended acoustic management value: 208, current value: 208
	DMA: mdma0 mdma1 mdma2 udma0 udma1 udma2 udma3 udma4 udma5 *udma6 
	     Cycle time: min=120ns recommended=120ns
	PIO: pio0 pio1 pio2 pio3 pio4 
	     Cycle time: no flow control=120ns  IORDY flow control=120ns
Commands/features:
	Enabled	Supported:
	   *	SMART feature set
	    	Security Mode feature set
	   *	Power Management feature set
	   *	Write cache
	   *	Look-ahead
	   *	Host Protected Area feature set
	   *	WRITE_BUFFER command
	   *	READ_BUFFER command
	   *	DOWNLOAD_MICROCODE
	   *	Advanced Power Management feature set
	    	Power-Up In Standby feature set
	   *	SET_FEATURES required to spinup after power up
	    	SET_MAX security extension
	   *	48-bit Address feature set
	   *	Device Configuration Overlay feature set
	   *	Mandatory FLUSH_CACHE
	   *	FLUSH_CACHE_EXT
	   *	SMART error logging
	   *	SMART self-test
	   *	General Purpose Logging feature set
	   *	WRITE_{DMA|MULTIPLE}_FUA_EXT
	   *	64-bit World wide name
	    	Write-Read-Verify feature set
	   *	WRITE_UNCORRECTABLE_EXT command
	   *	{READ,WRITE}_DMA_EXT_GPL commands
	   *	Segmented DOWNLOAD_MICROCODE
	   *	unknown 119[6]
	   *	Gen1 signaling speed (1.5Gb/s)
	   *	Gen2 signaling speed (3.0Gb/s)
	   *	Gen3 signaling speed (6.0Gb/s)
	   *	Native Command Queueing (NCQ)
	   *	Phy event counters
	   *	READ_LOG_DMA_EXT equivalent to READ_LOG_EXT
	   *	DMA Setup Auto-Activate optimization
	    	Device-initiated interface power management
	   *	Software settings preservation
	    	unknown 78[7]
	   *	SMART Command Transport (SCT) feature set
	   *	SCT Write Same (AC2)
	    	unknown 206[7]
	    	unknown 206[12] (vendor specific)
	   *	SANITIZE feature set
	   *	OVERWRITE_EXT command
Security: 
	Master password revision code = 65534
		supported
	not	enabled
	not	locked
		frozen
	not	expired: security count
		supported: enhanced erase
	100min for SECURITY ERASE UNIT. 100min for ENHANCED SECURITY ERASE UNIT.
Logical Unit WWN Device Identifier: 5000c5007aab9de1
	NAA		: 5
	IEEE OUI	: 000c50
	Unique ID	: 07aab9de1
Checksum: correct

/dev/sdd:

ATA device, with non-removable media
	Model Number:       ST1000DM003-1ER162                      
	Serial Number:      Z4Y1SAVG
	Firmware Revision:  CC43    
	Transport:          Serial, SATA 1.0a, SATA II Extensions, SATA Rev 2.5, SATA Rev 2.6, SATA Rev 3.0
Standards:
	Used: unknown (minor revision code 0x001f) 
	Supported: 9 8 7 6 5 
	Likely used: 9
Configuration:
	Logical		max	current
	cylinders	16383	16383
	heads		16	16
	sectors/track	63	63
	--
	CHS current addressable sectors:    16514064
	LBA    user addressable sectors:   268435455
	LBA48  user addressable sectors:  1953525168
	Logical  Sector size:                   512 bytes
	Physical Sector size:                  4096 bytes
	Logical Sector-0 offset:                  0 bytes
	device size with M = 1024*1024:      953869 MBytes
	device size with M = 1000*1000:     1000204 MBytes (1000 GB)
	cache/buffer size  = unknown
	Form Factor: 3.5 inch
	Nominal Media Rotation Rate: 7200
Capabilities:
	LBA, IORDY(can be disabled)
	Queue depth: 32
	Standby timer values: spec'd by Standard, no device specific minimum
	R/W multiple sector transfer: Max = 16	Current = 16
	Advanced power management level: 254
	Recommended acoustic management value: 208, current value: 208
	DMA: mdma0 mdma1 mdma2 udma0 udma1 udma2 udma3 udma4 udma5 *udma6 
	     Cycle time: min=120ns recommended=120ns
	PIO: pio0 pio1 pio2 pio3 pio4 
	     Cycle time: no flow control=120ns  IORDY flow control=120ns
Commands/features:
	Enabled	Supported:
	   *	SMART feature set
	    	Security Mode feature set
	   *	Power Management feature set
	   *	Write cache
	   *	Look-ahead
	   *	Host Protected Area feature set
	   *	WRITE_BUFFER command
	   *	READ_BUFFER command
	   *	DOWNLOAD_MICROCODE
	   *	Advanced Power Management feature set
	    	Power-Up In Standby feature set
	   *	SET_FEATURES required to spinup after power up
	    	SET_MAX security extension
	   *	48-bit Address feature set
	   *	Device Configuration Overlay feature set
	   *	Mandatory FLUSH_CACHE
	   *	FLUSH_CACHE_EXT
	   *	SMART error logging
	   *	SMART self-test
	   *	General Purpose Logging feature set
	   *	WRITE_{DMA|MULTIPLE}_FUA_EXT
	   *	64-bit World wide name
	    	Write-Read-Verify feature set
	   *	WRITE_UNCORRECTABLE_EXT command
	   *	{READ,WRITE}_DMA_EXT_GPL commands
	   *	Segmented DOWNLOAD_MICROCODE
	   *	unknown 119[6]
	   *	Gen1 signaling speed (1.5Gb/s)
	   *	Gen2 signaling speed (3.0Gb/s)
	   *	Gen3 signaling speed (6.0Gb/s)
	   *	Native Command Queueing (NCQ)
	   *	Phy event counters
	   *	READ_LOG_DMA_EXT equivalent to READ_LOG_EXT
	   *	DMA Setup Auto-Activate optimization
	    	Device-initiated interface power management
	   *	Software settings preservation
	    	unknown 78[7]
	   *	SMART Command Transport (SCT) feature set
	   *	SCT Write Same (AC2)
	    	unknown 206[7]
	    	unknown 206[12] (vendor specific)
	   *	SANITIZE feature set
	   *	OVERWRITE_EXT command
	   *	reserved 69[7]
Security: 
	Master password revision code = 65534
		supported
	not	enabled
	not	locked
		frozen
	not	expired: security count
		supported: enhanced erase
	98min for SECURITY ERASE UNIT. 98min for ENHANCED SECURITY ERASE UNIT.
Logical Unit WWN Device Identifier: 5000c500793959c3
	NAA		: 5
	IEEE OUI	: 000c50
	Unique ID	: 0793959c3
Checksum: correct

/dev/sde:

ATA device, with non-removable media
	Model Number:       ST1000DM003-1ER162                      
	Serial Number:      Z4Y9C367
	Firmware Revision:  CC45    
	Transport:          Serial, SATA 1.0a, SATA II Extensions, SATA Rev 2.5, SATA Rev 2.6, SATA Rev 3.0
Standards:
	Used: unknown (minor revision code 0x001f) 
	Supported: 9 8 7 6 5 
	Likely used: 9
Configuration:
	Logical		max	current
	cylinders	16383	16383
	heads		16	16
	sectors/track	63	63
	--
	CHS current addressable sectors:    16514064
	LBA    user addressable sectors:   268435455
	LBA48  user addressable sectors:  1953525168
	Logical  Sector size:                   512 bytes
	Physical Sector size:                  4096 bytes
	Logical Sector-0 offset:                  0 bytes
	device size with M = 1024*1024:      953869 MBytes
	device size with M = 1000*1000:     1000204 MBytes (1000 GB)
	cache/buffer size  = unknown
	Form Factor: 3.5 inch
	Nominal Media Rotation Rate: 7200
Capabilities:
	LBA, IORDY(can be disabled)
	Queue depth: 32
	Standby timer values: spec'd by Standard, no device specific minimum
	R/W multiple sector transfer: Max = 16	Current = 16
	Advanced power management level: 254
	Recommended acoustic management value: 208, current value: 208
	DMA: mdma0 mdma1 mdma2 udma0 udma1 udma2 udma3 udma4 udma5 *udma6 
	     Cycle time: min=120ns recommended=120ns
	PIO: pio0 pio1 pio2 pio3 pio4 
	     Cycle time: no flow control=120ns  IORDY flow control=120ns
Commands/features:
	Enabled	Supported:
	   *	SMART feature set
	    	Security Mode feature set
	   *	Power Management feature set
	   *	Write cache
	   *	Look-ahead
	   *	Host Protected Area feature set
	   *	WRITE_BUFFER command
	   *	READ_BUFFER command
	   *	DOWNLOAD_MICROCODE
	   *	Advanced Power Management feature set
	    	Power-Up In Standby feature set
	   *	SET_FEATURES required to spinup after power up
	    	SET_MAX security extension
	   *	48-bit Address feature set
	   *	Device Configuration Overlay feature set
	   *	Mandatory FLUSH_CACHE
	   *	FLUSH_CACHE_EXT
	   *	SMART error logging
	   *	SMART self-test
	   *	General Purpose Logging feature set
	   *	WRITE_{DMA|MULTIPLE}_FUA_EXT
	   *	64-bit World wide name
	    	Write-Read-Verify feature set
	   *	WRITE_UNCORRECTABLE_EXT command
	   *	{READ,WRITE}_DMA_EXT_GPL commands
	   *	Segmented DOWNLOAD_MICROCODE
	   *	unknown 119[6]
	   *	Gen1 signaling speed (1.5Gb/s)
	   *	Gen2 signaling speed (3.0Gb/s)
	   *	Gen3 signaling speed (6.0Gb/s)
	   *	Native Command Queueing (NCQ)
	   *	Phy event counters
	   *	READ_LOG_DMA_EXT equivalent to READ_LOG_EXT
	   *	DMA Setup Auto-Activate optimization
	    	Device-initiated interface power management
	   *	Software settings preservation
	    	unknown 78[7]
	   *	SMART Command Transport (SCT) feature set
	   *	SCT Write Same (AC2)
	    	unknown 206[7]
	    	unknown 206[12] (vendor specific)
	   *	SANITIZE feature set
	   *	OVERWRITE_EXT command
Security: 
	Master password revision code = 65534
		supported
	not	enabled
	not	locked
		frozen
	not	expired: security count
		supported: enhanced erase
	104min for SECURITY ERASE UNIT. 104min for ENHANCED SECURITY ERASE UNIT.
Logical Unit WWN Device Identifier: 5000c50086e4bcd4
	NAA		: 5
	IEEE OUI	: 000c50
	Unique ID	: 086e4bcd4
Checksum: correct

 xfs_info /dev/sdc1
xfs_info: /dev/sdc1 contains a mounted filesystem

fatal error -- couldn't initialize XFS library

hmm ?

root@trooper:~# umount /mnt/d0/
root@trooper:~# umount /mnt/d1/
root@trooper:~# umount /mnt/d2/
root@trooper:~# xfs_info /dev/sdc1
meta-data=/dev/sdc1              isize=512    agcount=4, agsize=61047598 blks
         =                       sectsz=4096  attr=2, projid32bit=1
         =                       crc=1        finobt=1, sparse=1, rmapbt=0
         =                       reflink=0
data     =                       bsize=4096   blocks=244190390, imaxpct=25
         =                       sunit=0      swidth=0 blks
naming   =version 2              bsize=4096   ascii-ci=0, ftype=1
log      =internal log           bsize=4096   blocks=119233, version=2
         =                       sectsz=4096  sunit=1 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0

xfs_info /dev/sdd1
meta-data=/dev/sdd1              isize=512    agcount=4, agsize=61047598 blks
         =                       sectsz=4096  attr=2, projid32bit=1
         =                       crc=1        finobt=1, sparse=1, rmapbt=0
         =                       reflink=0
data     =                       bsize=4096   blocks=244190390, imaxpct=25
         =                       sunit=0      swidth=0 blks
naming   =version 2              bsize=4096   ascii-ci=0, ftype=1
log      =internal log           bsize=4096   blocks=119233, version=2
         =                       sectsz=4096  sunit=1 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0

root@trooper:~# xfs_info /dev/sde1 
meta-data=/dev/sde1              isize=512    agcount=4, agsize=61047598 blks
         =                       sectsz=4096  attr=2, projid32bit=1
         =                       crc=1        finobt=1, sparse=1, rmapbt=0
         =                       reflink=0
data     =                       bsize=4096   blocks=244190390, imaxpct=25
         =                       sunit=0      swidth=0 blks
naming   =version 2              bsize=4096   ascii-ci=0, ftype=1
log      =internal log           bsize=4096   blocks=119233, version=2
         =                       sectsz=4096  sunit=1 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0

/home and / (on ssd's) are made with the older version of mkfs.xfs so they 
don't have the sparse inode feature enabled. And I have tested both versions of mkfs.xfs with the exact same result unfortunately. Otherwise all systems are made with default options (i.e. no options).

I knew about that vfs_cache_pressure=0 "drawback", it's not a fix :(

While testing I have never seen any tendency to swap. I have tested with swappiness=100 and different swap sizes and areas and even a swap file now (thanks for the recent fallocate addition, much appreciated :) ).

I'll do a quick run and give you some dmesg
Comment 3 Dave Chinner 2019-01-29 00:29:38 UTC
On Mon, Jan 28, 2019 at 11:26:32PM +0000, bugzilla-daemon@bugzilla.kernel.org wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=202441
> 
> --- Comment #2 from Roger (rogan6710@gmail.com) ---
> 
> Hello Dave !
> Thanks for the really fast reply :)
> Here is most of the (rather lengthy) system information:
> 
> Single "eight" core processor:
> 
> rogan@trooper:~$ uname -a
> Linux trooper.morgoth.org 4.19.18 #2 SMP Sat Jan 26 13:43:16 CST 2019 x86_64
> AMD FX(tm)-9590 Eight-Core Processor AuthenticAMD GNU/Linux
> 
> root@trooper:~# xfs_repair -V
> xfs_repair version 4.19.0
> 
> root@trooper:~# cat /proc/meminfo 
> MemTotal:       24645396 kB
> MemFree:          358452 kB
> MemAvailable:   22044292 kB
> Buffers:            3152 kB
> Cached:         22005216 kB
> SwapCached:            0 kB
> Active:          1713092 kB
> Inactive:       21824100 kB
> Active(anon):    1157816 kB
> Inactive(anon):   555736 kB
> Active(file):     555276 kB
> Inactive(file): 21268364 kB
....
> Slab:             565012 kB
> SReclaimable:     502684 kB

Ok, so memory is completely used by the page cache, and there is
some inode/dentry cache overhead in the slab caches.

Nothing unusual in the rest of the output , either.

>  xfs_info /dev/sdc1
> xfs_info: /dev/sdc1 contains a mounted filesystem
> 
> fatal error -- couldn't initialize XFS library
> 
> hmm ?

$ man xfs_info
...
	xfs_info [ -t mtab ] mount-point
...
	[...] The mount-point argument is the pathname of the
	directory where the filesystem is mounted. [...]

$ sudo mount /dev/vdc /mnt/scratch
$ sudo xfs_info /dev/vdc
xfs_info: /dev/vdc contains a mounted filesystem

fatal error -- couldn't initialize XFS library
$ sudo xfs_info /mnt/scratch
meta-data=/dev/vdc               isize=512    agcount=500, agsize=268435455 blks
         =                       sectsz=512   attr=2, projid32bit=1
         =                       crc=1        finobt=1, sparse=1, rmapbt=0
         =                       reflink=0
data     =                       bsize=4096   blocks=134217727500, imaxpct=1
         =                       sunit=0      swidth=0 blks
naming   =version 2              bsize=4096   ascii-ci=0, ftype=1
log      =internal log           bsize=4096   blocks=521728, version=2
         =                       sectsz=512   sunit=0 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0
$

> I'll do a quick run and give you some dmesg

OK, that'll be interesting :)

Cheers,

Dave.
Comment 4 Roger 2019-01-29 00:43:39 UTC
"If all else fails, read the man page" ;)
The complete dmesg output is a litte bit too big for the 
system here. they only allow 65535 characters
Last Output:
[ 1831.904739] sysrq: SysRq : Show Blocked State
[ 1831.904745]   task                        PC stack   pid father
[ 1831.904752] kswapd0         D    0    85      2 0x80000000
[ 1831.904753] Call Trace:
[ 1831.904758]  ? __schedule+0x21d/0x840
[ 1831.904760]  schedule+0x28/0x80
[ 1831.904761]  schedule_preempt_disabled+0xa/0x10
[ 1831.904762]  __mutex_lock.isra.6+0x2c3/0x4b0
[ 1831.904806]  ? xfs_perag_get_tag+0x3d/0xe0 [xfs]
[ 1831.904830]  xfs_reclaim_inodes_ag+0x299/0x300 [xfs]
[ 1831.904854]  ? xfs_perag_get+0x27/0xb0 [xfs]
[ 1831.904876]  ? xfs_inode_set_reclaim_tag+0x67/0x140 [xfs]
[ 1831.904899]  xfs_reclaim_inodes_nr+0x31/0x40 [xfs]
[ 1831.904901]  super_cache_scan+0x155/0x1a0
[ 1831.904903]  do_shrink_slab+0x128/0x290
[ 1831.904905]  shrink_slab+0x233/0x2b0
[ 1831.904907]  shrink_node+0xe6/0x460
[ 1831.904908]  kswapd+0x408/0x720
[ 1831.904909]  ? mem_cgroup_shrink_node+0x180/0x180
[ 1831.904911]  kthread+0x112/0x130
[ 1831.904912]  ? kthread_create_worker_on_cpu+0x70/0x70
[ 1831.904913]  ret_from_fork+0x22/0x40
[ 1831.904930] xfsaild/sdc1    D    0  1446      2 0x80000000
[ 1831.904931] Call Trace:
[ 1831.904932]  ? __schedule+0x21d/0x840
[ 1831.904933]  schedule+0x28/0x80
[ 1831.904956]  xfs_log_force+0x166/0x2e0 [xfs]
[ 1831.904957]  ? wake_up_q+0x70/0x70
[ 1831.904981]  xfsaild+0x1b2/0x830 [xfs]
[ 1831.905005]  ? xfs_trans_ail_cursor_first+0x80/0x80 [xfs]
[ 1831.905006]  kthread+0x112/0x130
[ 1831.905007]  ? kthread_create_worker_on_cpu+0x70/0x70
[ 1831.905008]  ret_from_fork+0x22/0x40
[ 1831.905012] Xorg            D    0  1496   1495 0x00000000
[ 1831.905013] Call Trace:
[ 1831.905014]  ? __schedule+0x21d/0x840
[ 1831.905015]  schedule+0x28/0x80
[ 1831.905016]  schedule_preempt_disabled+0xa/0x10
[ 1831.905017]  __mutex_lock.isra.6+0x2c3/0x4b0
[ 1831.905039]  ? xfs_perag_get_tag+0x3d/0xe0 [xfs]
[ 1831.905061]  xfs_reclaim_inodes_ag+0x299/0x300 [xfs]
[ 1831.905084]  ? xfs_perag_get+0x27/0xb0 [xfs]
[ 1831.905106]  ? xfs_inode_set_reclaim_tag+0x67/0x140 [xfs]
[ 1831.905128]  xfs_reclaim_inodes_nr+0x31/0x40 [xfs]
[ 1831.905130]  super_cache_scan+0x155/0x1a0
[ 1831.905131]  do_shrink_slab+0x128/0x290
[ 1831.905132]  shrink_slab+0x233/0x2b0
[ 1831.905133]  shrink_node+0xe6/0x460
[ 1831.905135]  do_try_to_free_pages+0xc6/0x370
[ 1831.905136]  try_to_free_pages+0xf5/0x1c0
[ 1831.905137]  __alloc_pages_slowpath+0x3aa/0xdc0
[ 1831.905139]  ? enqueue_entity+0x36d/0x7e0
[ 1831.905140]  __alloc_pages_nodemask+0x297/0x2c0
[ 1831.905142]  kmalloc_order+0x14/0x40
[ 1831.905143]  kmalloc_order_trace+0x1e/0xa0
[ 1831.905198]  dc_create_state+0x19/0x30 [amdgpu]
[ 1831.905234]  amdgpu_dm_atomic_check+0xc6/0x3b0 [amdgpu]
[ 1831.905248]  drm_atomic_check_only+0x460/0x660 [drm]
[ 1831.905258]  ? drm_atomic_set_fb_for_plane+0x53/0x80 [drm]
[ 1831.905267]  drm_atomic_nonblocking_commit+0x13/0x50 [drm]
[ 1831.905276]  drm_atomic_helper_page_flip+0x5b/0x90 [drm_kms_helper]
[ 1831.905285]  drm_mode_page_flip_ioctl+0x553/0x5b0 [drm]
[ 1831.905294]  ? drm_mode_cursor2_ioctl+0x10/0x10 [drm]
[ 1831.905301]  drm_ioctl_kernel+0xa1/0xf0 [drm]
[ 1831.905310]  drm_ioctl+0x206/0x3a0 [drm]
[ 1831.905319]  ? drm_mode_cursor2_ioctl+0x10/0x10 [drm]
[ 1831.905347]  amdgpu_drm_ioctl+0x49/0x80 [amdgpu]
[ 1831.905349]  do_vfs_ioctl+0xa4/0x630
[ 1831.905351]  ? __x64_sys_futex+0x143/0x180
[ 1831.905352]  ksys_ioctl+0x60/0x90
[ 1831.905354]  __x64_sys_ioctl+0x16/0x20
[ 1831.905355]  do_syscall_64+0x55/0x100
[ 1831.905356]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1831.905358] RIP: 0033:0x7f87fd574d37
[ 1831.905361] Code: Bad RIP value.
[ 1831.905362] RSP: 002b:00007fff347ff238 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 1831.905363] RAX: ffffffffffffffda RBX: 0000000000bd9f10 RCX: 00007f87fd574d37
[ 1831.905364] RDX: 00007fff347ff270 RSI: 00000000c01864b0 RDI: 000000000000000e
[ 1831.905364] RBP: 00007fff347ff270 R08: 00000000000041ce R09: 0000000000000000
[ 1831.905365] R10: 00000000014cbb60 R11: 0000000000000246 R12: 00000000c01864b0
[ 1831.905366] R13: 000000000000000e R14: 0000000000000000 R15: 0000000000bd58e0
[ 1831.905380] mc              D    0  1866   1740 0x00000000
[ 1831.905381] Call Trace:
[ 1831.905382]  ? __schedule+0x21d/0x840
[ 1831.905383]  schedule+0x28/0x80
[ 1831.905384]  schedule_preempt_disabled+0xa/0x10
[ 1831.905385]  __mutex_lock.isra.6+0x2c3/0x4b0
[ 1831.905407]  ? xfs_perag_get_tag+0x3d/0xe0 [xfs]
[ 1831.905429]  xfs_reclaim_inodes_ag+0x299/0x300 [xfs]
[ 1831.905431]  ? inode_lru_list_add+0x20/0x40
[ 1831.905432]  ? iput+0x16d/0x200
[ 1831.905455]  ? xfs_iunlock+0x61/0x110 [xfs]
[ 1831.905477]  ? xfs_perag_get+0x27/0xb0 [xfs]
[ 1831.905499]  ? xfs_inode_set_reclaim_tag+0x67/0x140 [xfs]
[ 1831.905522]  xfs_reclaim_inodes_nr+0x31/0x40 [xfs]
[ 1831.905523]  super_cache_scan+0x155/0x1a0
[ 1831.905524]  do_shrink_slab+0x128/0x290
[ 1831.905526]  shrink_slab+0x233/0x2b0
[ 1831.905527]  shrink_node+0xe6/0x460
[ 1831.905528]  do_try_to_free_pages+0xc6/0x370
[ 1831.905529]  try_to_free_pages+0xf5/0x1c0
[ 1831.905530]  __alloc_pages_slowpath+0x3aa/0xdc0
[ 1831.905531]  ? __switch_to_asm+0x34/0x70
[ 1831.905532]  ? __switch_to_asm+0x40/0x70
[ 1831.905533]  ? __switch_to_asm+0x34/0x70
[ 1831.905534]  ? __switch_to_asm+0x40/0x70
[ 1831.905535]  ? __switch_to_asm+0x34/0x70
[ 1831.905536]  ? __switch_to_asm+0x40/0x70
[ 1831.905537]  __alloc_pages_nodemask+0x297/0x2c0
[ 1831.905538]  __do_page_cache_readahead+0xb1/0x1b0
[ 1831.905539]  ondemand_readahead+0x1f9/0x2c0
[ 1831.905541]  generic_file_read_iter+0x738/0xc10
[ 1831.905542]  ? page_cache_tree_insert+0xe0/0xe0
[ 1831.905543]  nfs_file_read+0x5d/0x80
[ 1831.905546]  __vfs_read+0x133/0x190
[ 1831.905547]  vfs_read+0x8a/0x140
[ 1831.905548]  ksys_read+0x4f/0xb0
[ 1831.905549]  do_syscall_64+0x55/0x100
[ 1831.905551]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1831.905551] RIP: 0033:0x7fad0ffd9aae
[ 1831.905553] Code: Bad RIP value.
[ 1831.905553] RSP: 002b:00007ffc380b1bb8 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
[ 1831.905554] RAX: ffffffffffffffda RBX: 00000000008ef9e0 RCX: 00007fad0ffd9aae
[ 1831.905555] RDX: 0000000000020000 RSI: 00000000008f7ec0 RDI: 000000000000000a
[ 1831.905555] RBP: 0000000000020000 R08: 0000000000000000 R09: 0000000000000000
[ 1831.905556] R10: 0000000000000008 R11: 0000000000000246 R12: 00000000008f7ec0
[ 1831.905556] R13: 0000000000000000 R14: 0000000199000000 R15: 00000000008d5b70
[ 1831.905574] kworker/u16:4   D    0 14955      2 0x80000000
[ 1831.905577] Workqueue: writeback wb_workfn (flush-8:32)
[ 1831.905578] Call Trace:
[ 1831.905579]  ? __schedule+0x21d/0x840
[ 1831.905580]  schedule+0x28/0x80
[ 1831.905581]  schedule_timeout+0x1d8/0x370
[ 1831.905603]  ? xfs_buf_read_map+0xc1/0x180 [xfs]
[ 1831.905604]  ? schedule+0x28/0x80
[ 1831.905606]  ? down_trylock+0x25/0x30
[ 1831.905607]  __down+0x7f/0xd0
[ 1831.905629]  ? xfs_buf_find.isra.30+0x3b4/0x5e0 [xfs]
[ 1831.905630]  down+0x3b/0x50
[ 1831.905652]  xfs_buf_lock+0x32/0xf0 [xfs]
[ 1831.905675]  xfs_buf_find.isra.30+0x3b4/0x5e0 [xfs]
[ 1831.905698]  xfs_buf_get_map+0x40/0x2c0 [xfs]
[ 1831.905720]  xfs_buf_read_map+0x28/0x180 [xfs]
[ 1831.905743]  xfs_trans_read_buf_map+0xb4/0x2f0 [xfs]
[ 1831.905764]  xfs_read_agf+0x94/0x120 [xfs]
[ 1831.905785]  xfs_alloc_read_agf+0x47/0x1b0 [xfs]
[ 1831.905805]  xfs_alloc_fix_freelist+0x377/0x430 [xfs]
[ 1831.905807]  ? __update_load_avg_cfs_rq+0x1b5/0x230
[ 1831.905808]  ? __alloc_pages_nodemask+0x13a/0x2c0
[ 1831.905809]  ? update_curr+0xba/0x1a0
[ 1831.905831]  ? xfs_perag_get+0x27/0xb0 [xfs]
[ 1831.905851]  xfs_alloc_vextent+0x121/0x580 [xfs]
[ 1831.905871]  xfs_bmap_btalloc+0x420/0x890 [xfs]
[ 1831.905893]  xfs_bmapi_write+0x5f5/0xb80 [xfs]
[ 1831.905916]  xfs_iomap_write_allocate+0x176/0x380 [xfs]
[ 1831.905939]  xfs_map_blocks+0x186/0x450 [xfs]
[ 1831.905962]  xfs_do_writepage+0x123/0x440 [xfs]
[ 1831.905963]  write_cache_pages+0x1dd/0x470
[ 1831.905985]  ? xfs_vm_releasepage+0x80/0x80 [xfs]
[ 1831.905987]  ? genl_register_family+0xfa/0x610
[ 1831.905989]  ? __tcp_transmit_skb+0x58d/0xad0
[ 1831.906011]  xfs_vm_writepages+0x59/0x90 [xfs]
[ 1831.906012]  do_writepages+0x41/0xd0
[ 1831.906013]  ? __tcp_push_pending_frames+0x2d/0xa0
[ 1831.906014]  ? tcp_sendmsg_locked+0x509/0xd80
[ 1831.906015]  __writeback_single_inode+0x4a/0x380
[ 1831.906017]  writeback_sb_inodes+0x1d0/0x460
[ 1831.906018]  __writeback_inodes_wb+0x5d/0xb0
[ 1831.906019]  wb_writeback+0x263/0x310
[ 1831.906020]  ? get_nr_inodes+0x35/0x50
[ 1831.906021]  ? cpumask_next+0x16/0x20
[ 1831.906022]  wb_workfn+0x340/0x3f0
[ 1831.906024]  ? __switch_to_asm+0x40/0x70
[ 1831.906025]  process_one_work+0x1eb/0x420
[ 1831.906026]  worker_thread+0x2d/0x3d0
[ 1831.906027]  ? pwq_unbound_release_workfn+0xc0/0xc0
[ 1831.906028]  kthread+0x112/0x130
[ 1831.906029]  ? kthread_create_worker_on_cpu+0x70/0x70
[ 1831.906030]  ret_from_fork+0x22/0x40
[ 1831.906033] make            D    0 25592  24315 0x00000000
[ 1831.906034] Call Trace:
[ 1831.906036]  ? __schedule+0x21d/0x840
[ 1831.906037]  schedule+0x28/0x80
[ 1831.906037]  rwsem_down_read_failed+0xe1/0x140
[ 1831.906039]  ? update_curr+0xba/0x1a0
[ 1831.906040]  call_rwsem_down_read_failed+0x14/0x30
[ 1831.906041]  down_read+0x1c/0x30
[ 1831.906042]  lookup_slow+0x27/0x50
[ 1831.906043]  walk_component+0x1bf/0x4a0
[ 1831.906045]  ? __switch_to_asm+0x40/0x70
[ 1831.906046]  ? __switch_to_asm+0x34/0x70
[ 1831.906047]  ? __switch_to_asm+0x40/0x70
[ 1831.906048]  ? __switch_to_asm+0x34/0x70
[ 1831.906048]  path_lookupat.isra.55+0x6d/0x220
[ 1831.906050]  ? __switch_to_asm+0x40/0x70
[ 1831.906051]  ? __switch_to_asm+0x34/0x70
[ 1831.906051]  ? __switch_to_asm+0x40/0x70
[ 1831.906052]  ? __switch_to_asm+0x34/0x70
[ 1831.906053]  ? __switch_to_asm+0x40/0x70
[ 1831.906054]  filename_lookup.part.69+0xa0/0x170
[ 1831.906055]  ? __switch_to_asm+0x34/0x70
[ 1831.906056]  ? __check_object_size+0x158/0x184
[ 1831.906058]  ? strncpy_from_user+0x4a/0x170
[ 1831.906059]  vfs_statx+0x73/0xe0
[ 1831.906061]  __do_sys_newstat+0x39/0x70
[ 1831.906063]  ? recalc_sigpending+0x17/0x50
[ 1831.906064]  ? __set_task_blocked+0x6d/0x90
[ 1831.906064]  ? __set_current_blocked+0x3d/0x60
[ 1831.906065]  ? sigprocmask+0x72/0xa0
[ 1831.906066]  ? __x64_sys_rt_sigprocmask+0x76/0xd0
[ 1831.906067]  do_syscall_64+0x55/0x100
[ 1831.906068]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1831.906069] RIP: 0033:0x7efe49566325
[ 1831.906070] Code: Bad RIP value.
[ 1831.906071] RSP: 002b:00007ffd677f3518 EFLAGS: 00000246 ORIG_RAX: 0000000000000004
[ 1831.906072] RAX: ffffffffffffffda RBX: 00007ffd677f3660 RCX: 00007efe49566325
[ 1831.906072] RDX: 00007ffd677f3590 RSI: 00007ffd677f3590 RDI: 00007ffd677f3520
[ 1831.906073] RBP: 00007ffd677f3650 R08: 000000000000000a R09: 00007efe495c1950
[ 1831.906073] R10: 7974697275636573 R11: 0000000000000246 R12: 00007ffd677f3870
[ 1831.906074] R13: 00007ffd677f3520 R14: 0000000000000000 R15: 0000000000000009
[ 1831.906076] cc1             D    0 26405  26404 0x00000000
[ 1831.906077] Call Trace:
[ 1831.906078]  ? __schedule+0x21d/0x840
[ 1831.906101]  ? xfs_bwrite+0x25/0x60 [xfs]
[ 1831.906101]  schedule+0x28/0x80
[ 1831.906102]  schedule_timeout+0x1d8/0x370
[ 1831.906104]  ? blk_finish_plug+0x21/0x2e
[ 1831.906127]  ? xfs_bwrite+0x25/0x60 [xfs]
[ 1831.906128]  wait_for_completion+0xad/0x130
[ 1831.906129]  ? wake_up_q+0x70/0x70
[ 1831.906151]  ? __xfs_buf_submit+0xd7/0x230 [xfs]
[ 1831.906173]  xfs_buf_iowait+0x27/0xd0 [xfs]
[ 1831.906195]  __xfs_buf_submit+0xd7/0x230 [xfs]
[ 1831.906218]  xfs_bwrite+0x25/0x60 [xfs]
[ 1831.906240]  xfs_reclaim_inode+0x309/0x330 [xfs]
[ 1831.906263]  xfs_reclaim_inodes_ag+0x1b1/0x300 [xfs]
[ 1831.906285]  ? xfs_perag_get+0x27/0xb0 [xfs]
[ 1831.906308]  ? xfs_inode_set_reclaim_tag+0x67/0x140 [xfs]
[ 1831.906331]  xfs_reclaim_inodes_nr+0x31/0x40 [xfs]
[ 1831.906332]  super_cache_scan+0x155/0x1a0
[ 1831.906333]  do_shrink_slab+0x128/0x290
[ 1831.906335]  shrink_slab+0x233/0x2b0
[ 1831.906336]  shrink_node+0xe6/0x460
[ 1831.906337]  do_try_to_free_pages+0xc6/0x370
[ 1831.906338]  try_to_free_pages+0xf5/0x1c0
[ 1831.906339]  __alloc_pages_slowpath+0x3aa/0xdc0
[ 1831.906340]  __alloc_pages_nodemask+0x297/0x2c0
[ 1831.906342]  alloc_pages_vma+0x7c/0x1f0
[ 1831.906343]  __handle_mm_fault+0x8b5/0xf80
[ 1831.906345]  handle_mm_fault+0x155/0x1d0
[ 1831.906346]  __do_page_fault+0x1e6/0x460
[ 1831.906348]  ? page_fault+0x8/0x30
[ 1831.906349]  page_fault+0x1e/0x30
[ 1831.906350] RIP: 0033:0x7f49d7b4ba38
[ 1831.906351] Code: Bad RIP value.
[ 1831.906351] RSP: 002b:00007ffc9d5e4bd8 EFLAGS: 00010206
[ 1831.906352] RAX: 00007f49d67ec000 RBX: 0000000000000170 RCX: 00007f49d67ec040
[ 1831.906353] RDX: 0000000000000170 RSI: 0000000000000000 RDI: 00007f49d67ec000
[ 1831.906353] RBP: 00007f49d783d100 R08: 00000000031ee1f0 R09: 0000000000000000
[ 1831.906354] R10: 0000000000000000 R11: 00000000031ee1f0 R12: 00007f49d67eac00
[ 1831.906354] R13: 00007f49d67eac00 R14: 0000000000000000 R15: 00007f49d78472d0
[ 1831.906355] cc1             D    0 26411  26410 0x00000000
[ 1831.906356] Call Trace:
[ 1831.906357]  ? __schedule+0x21d/0x840
[ 1831.906358]  schedule+0x28/0x80
[ 1831.906359]  schedule_preempt_disabled+0xa/0x10
[ 1831.906360]  __mutex_lock.isra.6+0x2c3/0x4b0
[ 1831.906383]  xfs_reclaim_inodes_ag+0x299/0x300 [xfs]
[ 1831.906384]  ? inode_lru_list_add+0x20/0x40
[ 1831.906385]  ? iput+0x16d/0x200
[ 1831.906408]  ? xfs_iunlock+0x61/0x110 [xfs]
[ 1831.906429]  ? xfs_perag_get+0x27/0xb0 [xfs]
[ 1831.906452]  ? xfs_inode_set_reclaim_tag+0x67/0x140 [xfs]
[ 1831.906474]  xfs_reclaim_inodes_nr+0x31/0x40 [xfs]
[ 1831.906476]  super_cache_scan+0x155/0x1a0
[ 1831.906477]  do_shrink_slab+0x128/0x290
[ 1831.906478]  shrink_slab+0x233/0x2b0
[ 1831.906479]  shrink_node+0xe6/0x460
[ 1831.906481]  do_try_to_free_pages+0xc6/0x370
[ 1831.906481]  try_to_free_pages+0xf5/0x1c0
[ 1831.906483]  __alloc_pages_slowpath+0x3aa/0xdc0
[ 1831.906484]  ? __alloc_pages_slowpath+0x173/0xdc0
[ 1831.906485]  __alloc_pages_nodemask+0x297/0x2c0
[ 1831.906486]  alloc_pages_vma+0x7c/0x1f0
[ 1831.906487]  wp_page_copy+0x4f0/0x740
[ 1831.906488]  do_wp_page+0x8a/0x5f0
[ 1831.906489]  __handle_mm_fault+0xafc/0xf80
[ 1831.906491]  handle_mm_fault+0x155/0x1d0
[ 1831.906492]  __do_page_fault+0x1e6/0x460
[ 1831.906493]  ? page_fault+0x8/0x30
[ 1831.906494]  page_fault+0x1e/0x30
[ 1831.906495] RIP: 0033:0x5b126b
[ 1831.906496] Code: Bad RIP value.
[ 1831.906496] RSP: 002b:00007ffcb1940470 EFLAGS: 00010256
[ 1831.906497] RAX: 0000000000000000 RBX: 00007fdf9a729000 RCX: 0000000000000001
[ 1831.906498] RDX: 0000000010000002 RSI: 0000000000000001 RDI: 0000000000000054
[ 1831.906498] RBP: 00007fdf9a715000 R08: 0000000000000000 R09: 000000008000833a
[ 1831.906499] R10: 0000000000000000 R11: 0000000002d22010 R12: 00007fdf9c68ddb0
[ 1831.906499] R13: 00007fdf9a725900 R14: 0000000000000000 R15: 00007fdf9a725900
[ 1831.906500] cc1             D    0 26415  26414 0x00000000
[ 1831.906501] Call Trace:
[ 1831.906502]  ? __schedule+0x21d/0x840
[ 1831.906503]  schedule+0x28/0x80
[ 1831.906504]  schedule_preempt_disabled+0xa/0x10
[ 1831.906505]  __mutex_lock.isra.6+0x2c3/0x4b0
[ 1831.906528]  xfs_reclaim_inodes_ag+0x299/0x300 [xfs]
[ 1831.906551]  ? xfs_iunlock+0x61/0x110 [xfs]
[ 1831.906573]  ? xfs_perag_get+0x27/0xb0 [xfs]
[ 1831.906595]  ? xfs_inode_set_reclaim_tag+0x67/0x140 [xfs]
[ 1831.906618]  xfs_reclaim_inodes_nr+0x31/0x40 [xfs]
[ 1831.906619]  super_cache_scan+0x155/0x1a0
[ 1831.906620]  do_shrink_slab+0x128/0x290
[ 1831.906622]  shrink_slab+0x233/0x2b0
[ 1831.906623]  shrink_node+0xe6/0x460
[ 1831.906624]  do_try_to_free_pages+0xc6/0x370
[ 1831.906625]  try_to_free_pages+0xf5/0x1c0
[ 1831.906626]  __alloc_pages_slowpath+0x3aa/0xdc0
[ 1831.906627]  __alloc_pages_nodemask+0x297/0x2c0
[ 1831.906628]  alloc_pages_vma+0x7c/0x1f0
[ 1831.906629]  __handle_mm_fault+0x8b5/0xf80
[ 1831.906631]  handle_mm_fault+0x155/0x1d0
[ 1831.906631]  __do_page_fault+0x1e6/0x460
[ 1831.906633]  ? page_fault+0x8/0x30
[ 1831.906634]  page_fault+0x1e/0x30
[ 1831.906634] RIP: 0033:0x7f25af773a38
[ 1831.906636] Code: Bad RIP value.
[ 1831.906636] RSP: 002b:00007ffdf763bac8 EFLAGS: 00010202
[ 1831.906637] RAX: 00007f25ad1ee000 RBX: 0000000000000080 RCX: 00007f25ad1ee040
[ 1831.906638] RDX: 0000000000000080 RSI: 0000000000000000 RDI: 00007f25ad1ee000
[ 1831.906638] RBP: 000000007ff9f6ef R08: 00000000039dc8d0 R09: 0000000000000000
[ 1831.906639] R10: 0000000000000000 R11: 00000000039daf80 R12: 0000000000000003
[ 1831.906639] R13: 0000000000000022 R14: 00007f25af47f3d8 R15: 000000007ff9f6ef
[ 1831.906641] cc1             D    0 26430  26428 0x00000000
[ 1831.906641] Call Trace:
[ 1831.906643]  ? __schedule+0x21d/0x840
[ 1831.906643]  schedule+0x28/0x80
[ 1831.906644]  schedule_preempt_disabled+0xa/0x10
[ 1831.906645]  __mutex_lock.isra.6+0x2c3/0x4b0
[ 1831.906668]  xfs_reclaim_inodes_ag+0x299/0x300 [xfs]
[ 1831.906669]  ? inode_lru_list_add+0x20/0x40
[ 1831.906670]  ? iput+0x16d/0x200
[ 1831.906693]  ? xfs_iunlock+0x61/0x110 [xfs]
[ 1831.906714]  ? xfs_perag_get+0x27/0xb0 [xfs]
[ 1831.906737]  ? xfs_inode_set_reclaim_tag+0xd2/0x140 [xfs]
[ 1831.906759]  xfs_reclaim_inodes_nr+0x31/0x40 [xfs]
[ 1831.906760]  super_cache_scan+0x155/0x1a0
[ 1831.906762]  do_shrink_slab+0x128/0x290
[ 1831.906763]  shrink_slab+0x233/0x2b0
[ 1831.906764]  shrink_node+0xe6/0x460
[ 1831.906765]  do_try_to_free_pages+0xc6/0x370
[ 1831.906766]  try_to_free_pages+0xf5/0x1c0
[ 1831.906767]  __alloc_pages_slowpath+0x3aa/0xdc0
[ 1831.906768]  ? ttwu_do_wakeup+0x19/0x150
[ 1831.906770]  __alloc_pages_nodemask+0x297/0x2c0
[ 1831.906771]  alloc_pages_vma+0x7c/0x1f0
[ 1831.906772]  __handle_mm_fault+0x8b5/0xf80
[ 1831.906773]  handle_mm_fault+0x155/0x1d0
[ 1831.906774]  __do_page_fault+0x1e6/0x460
[ 1831.906775]  ? page_fault+0x8/0x30
[ 1831.906776]  page_fault+0x1e/0x30
[ 1831.906777] RIP: 0033:0x7f3c73bba484
[ 1831.906778] Code: Bad RIP value.
[ 1831.906779] RSP: 002b:00007ffffaa9d5c8 EFLAGS: 00010202
[ 1831.906780] RAX: 00007f3c71ade000 RBX: 00007f3c72827000 RCX: 0000000000080000
[ 1831.906780] RDX: 00000000000d4f70 RSI: 00007f3c728fbff0 RDI: 00007f3c71bb3070
[ 1831.906781] RBP: 0000000000180000 R08: 00007f3c71bddff0 R09: 00007f3c72927000
[ 1831.906781] R10: 0000000000000007 R11: 00007f3c73c08680 R12: 00007f3c71ade000
[ 1831.906782] R13: 0000000000100000 R14: 00007ffffaa9db20 R15: 00007ffffaa9db20
[ 1831.906783] fixdep          D    0 26436  26319 0x00000000
[ 1831.906784] Call Trace:
[ 1831.906785]  ? __schedule+0x21d/0x840
[ 1831.906786]  schedule+0x28/0x80
[ 1831.906787]  rwsem_down_read_failed+0xe1/0x140
[ 1831.906788]  call_rwsem_down_read_failed+0x14/0x30
[ 1831.906789]  down_read+0x1c/0x30
[ 1831.906790]  path_openat+0xb9b/0x1650
[ 1831.906792]  ? generic_file_read_iter+0x853/0xc10
[ 1831.906812]  ? xfs_bmapi_read+0x129/0x340 [xfs]
[ 1831.906813]  do_filp_open+0x93/0x100
[ 1831.906815]  ? __check_object_size+0x158/0x184
[ 1831.906816]  do_sys_open+0x186/0x210
[ 1831.906817]  do_syscall_64+0x55/0x100
[ 1831.906818]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1831.906819] RIP: 0033:0x7fc96d8769c0
[ 1831.906820] Code: Bad RIP value.
[ 1831.906821] RSP: 002b:00007ffd1be5b150 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
[ 1831.906822] RAX: ffffffffffffffda RBX: 0000000000b9d071 RCX: 00007fc96d8769c0
[ 1831.906822] RDX: 0000000000000000 RSI: 0000000000b9d071 RDI: 00000000ffffff9c
[ 1831.906823] RBP: 0000000000b9d071 R08: 0000000000b9d071 R09: 00007fc96d8d1b40
[ 1831.906823] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
[ 1831.906824] R13: 0000000000bab372 R14: 0000000000000021 R15: 000000000000000b
[ 1831.906825] cc1             D    0 26450  26449 0x00000000
[ 1831.906826] Call Trace:
[ 1831.906827]  ? __schedule+0x21d/0x840
[ 1831.906849]  ? xfs_buf_read_map+0xc1/0x180 [xfs]
[ 1831.906850]  schedule+0x28/0x80
[ 1831.906851]  schedule_timeout+0x1d8/0x370
[ 1831.906852]  ? blk_finish_plug+0x21/0x2e
[ 1831.906874]  ? xfs_buf_read_map+0xc1/0x180 [xfs]
[ 1831.906875]  wait_for_completion+0xad/0x130
[ 1831.906876]  ? wake_up_q+0x70/0x70
[ 1831.906898]  ? __xfs_buf_submit+0xd7/0x230 [xfs]
[ 1831.906920]  xfs_buf_iowait+0x27/0xd0 [xfs]
[ 1831.906942]  __xfs_buf_submit+0xd7/0x230 [xfs]
[ 1831.906965]  xfs_buf_read_map+0xc1/0x180 [xfs]
[ 1831.906988]  xfs_trans_read_buf_map+0xb4/0x2f0 [xfs]
[ 1831.907010]  xfs_imap_to_bp+0x67/0xd0 [xfs]
[ 1831.907031]  xfs_iread+0x82/0x1f0 [xfs]
[ 1831.907033]  ? inode_init_always+0x120/0x1d0
[ 1831.907055]  xfs_iget+0x20f/0x990 [xfs]
[ 1831.907077]  ? xfs_dir_lookup+0x184/0x1d0 [xfs]
[ 1831.907099]  xfs_lookup+0xa4/0x120 [xfs]
[ 1831.907100]  ? unlazy_walk+0x3a/0xa0
[ 1831.907123]  xfs_vn_lookup+0x70/0xa0 [xfs]
[ 1831.907124]  path_openat+0xaff/0x1650
[ 1831.907125]  do_filp_open+0x93/0x100
[ 1831.907127]  ? __handle_mm_fault+0x9dc/0xf80
[ 1831.907128]  ? __check_object_size+0x158/0x184
[ 1831.907129]  do_sys_open+0x186/0x210
[ 1831.907130]  do_syscall_64+0x55/0x100
[ 1831.907131]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1831.907132] RIP: 0033:0x7f3884a4e9c0
[ 1831.907133] Code: Bad RIP value.
[ 1831.907134] RSP: 002b:00007ffcfa97a360 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
[ 1831.907134] RAX: ffffffffffffffda RBX: 0000000002407db0 RCX: 00007f3884a4e9c0
[ 1831.907135] RDX: 0000000000000100 RSI: 00000000023b14f0 RDI: 00000000ffffff9c
[ 1831.907135] RBP: 0000000002215ae0 R08: 00000000023b2b20 R09: 0000000099568b0e
[ 1831.907136] R10: 0000000000000000 R11: 0000000000000246 R12: 00000000023b14f0
[ 1831.907136] R13: 0000000099568de8 R14: 00000000021cf190 R15: 00000000021b73b0
[ 1831.907138] cc1             D    0 26454  26453 0x00000000
[ 1831.907139] Call Trace:
[ 1831.907140]  ? __schedule+0x21d/0x840
[ 1831.907141]  schedule+0x28/0x80
[ 1831.907142]  schedule_timeout+0x1d8/0x370
[ 1831.907143]  __down+0x7f/0xd0
[ 1831.907144]  ? syscall_return_via_sysret+0x13/0x83
[ 1831.907145]  ? __switch_to_asm+0x40/0x70
[ 1831.907146]  ? __switch_to_asm+0x40/0x70
[ 1831.907168]  ? xfs_buf_find.isra.30+0x3b4/0x5e0 [xfs]
[ 1831.907169]  down+0x3b/0x50
[ 1831.907191]  xfs_buf_lock+0x32/0xf0 [xfs]
[ 1831.907213]  xfs_buf_find.isra.30+0x3b4/0x5e0 [xfs]
[ 1831.907235]  xfs_buf_get_map+0x40/0x2c0 [xfs]
[ 1831.907258]  xfs_buf_read_map+0x28/0x180 [xfs]
[ 1831.907280]  ? xfs_buf_trylock+0x19/0xd0 [xfs]
[ 1831.907303]  xfs_trans_read_buf_map+0xb4/0x2f0 [xfs]
[ 1831.907325]  xfs_read_agi+0x9e/0x140 [xfs]
[ 1831.907347]  xfs_ialloc_read_agi+0x34/0xd0 [xfs]
[ 1831.907368]  xfs_dialloc+0xe7/0x2b0 [xfs]
[ 1831.907391]  xfs_ialloc+0x6b/0x5a0 [xfs]
[ 1831.907414]  ? kmem_zone_alloc+0x61/0xe0 [xfs]
[ 1831.907437]  xfs_dir_ialloc+0x6c/0x220 [xfs]
[ 1831.907460]  xfs_create+0x224/0x620 [xfs]
[ 1831.907483]  xfs_generic_create+0x226/0x2c0 [xfs]
[ 1831.907484]  path_openat+0x1279/0x1650
[ 1831.907486]  ? current_time+0x4f/0x90
[ 1831.907487]  do_filp_open+0x93/0x100
[ 1831.907488]  ? __check_object_size+0x158/0x184
[ 1831.907489]  do_sys_open+0x186/0x210
[ 1831.907490]  do_syscall_64+0x55/0x100
[ 1831.907491]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1831.907492] RIP: 0033:0x7f4afda6e9c0
[ 1831.907493] Code: Bad RIP value.
[ 1831.907494] RSP: 002b:00007ffef4762170 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
[ 1831.907495] RAX: ffffffffffffffda RBX: 0000000003523800 RCX: 00007f4afda6e9c0
[ 1831.907495] RDX: 0000000000000241 RSI: 00007ffef4763faa RDI: 00000000ffffff9c
[ 1831.907496] RBP: 000000000128aafd R08: 0000000000000001 R09: 000000000310e660
[ 1831.907496] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000004
[ 1831.907497] R13: 000000000128aafd R14: 0000000000000000 R15: 0000000000000000
[ 1831.907498] rm              D    0 26462  26356 0x00000000
[ 1831.907498] Call Trace:
[ 1831.907500]  ? __schedule+0x21d/0x840
[ 1831.907501]  schedule+0x28/0x80
[ 1831.907501]  schedule_timeout+0x1d8/0x370
[ 1831.907503]  __down+0x7f/0xd0
[ 1831.907524]  ? xfs_buf_find.isra.30+0x3b4/0x5e0 [xfs]
[ 1831.907525]  down+0x3b/0x50
[ 1831.907547]  xfs_buf_lock+0x32/0xf0 [xfs]
[ 1831.907570]  xfs_buf_find.isra.30+0x3b4/0x5e0 [xfs]
[ 1831.907592]  xfs_buf_get_map+0x40/0x2c0 [xfs]
[ 1831.907614]  xfs_buf_read_map+0x28/0x180 [xfs]
[ 1831.907637]  xfs_trans_read_buf_map+0xb4/0x2f0 [xfs]
[ 1831.907659]  xfs_read_agi+0x9e/0x140 [xfs]
[ 1831.907682]  xfs_iunlink+0x4d/0x140 [xfs]
[ 1831.907705]  xfs_remove+0x1ec/0x2e0 [xfs]
[ 1831.907728]  xfs_vn_unlink+0x55/0xa0 [xfs]
[ 1831.907729]  ? may_delete+0x7f/0x190
[ 1831.907730]  vfs_unlink+0x109/0x1a0
[ 1831.907731]  do_unlinkat+0x225/0x310
[ 1831.907732]  do_syscall_64+0x55/0x100
[ 1831.907733]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1831.907734] RIP: 0033:0x7f05978905b7
[ 1831.907735] Code: Bad RIP value.
[ 1831.907736] RSP: 002b:00007fff97cd1258 EFLAGS: 00000202 ORIG_RAX: 0000000000000107
[ 1831.907737] RAX: ffffffffffffffda RBX: 00000000011d68c0 RCX: 00007f05978905b7
[ 1831.907737] RDX: 0000000000000000 RSI: 00000000011d5690 RDI: 00000000ffffff9c
[ 1831.907738] RBP: 00000000011d5600 R08: 0000000000000003 R09: 0000000000000000
[ 1831.907738] R10: 0000000000000003 R11: 0000000000000202 R12: 00007fff97cd1410
[ 1831.907739] R13: 0000000000000000 R14: 0000000000000000 R15: 00000000011d68c0
[ 1831.907739] rm              D    0 26472  26300 0x00000000
[ 1831.907740] Call Trace:
[ 1831.907742]  ? __schedule+0x21d/0x840
[ 1831.907742]  schedule+0x28/0x80
[ 1831.907743]  schedule_timeout+0x1d8/0x370
[ 1831.907744]  __down+0x7f/0xd0
[ 1831.907766]  ? xfs_buf_find.isra.30+0x3b4/0x5e0 [xfs]
[ 1831.907767]  down+0x3b/0x50
[ 1831.907789]  xfs_buf_lock+0x32/0xf0 [xfs]
[ 1831.907811]  xfs_buf_find.isra.30+0x3b4/0x5e0 [xfs]
[ 1831.907834]  xfs_buf_get_map+0x40/0x2c0 [xfs]
[ 1831.907856]  xfs_buf_read_map+0x28/0x180 [xfs]
[ 1831.907879]  xfs_trans_read_buf_map+0xb4/0x2f0 [xfs]
[ 1831.907901]  xfs_read_agi+0x9e/0x140 [xfs]
[ 1831.907924]  xfs_iunlink+0x4d/0x140 [xfs]
[ 1831.907947]  xfs_remove+0x1ec/0x2e0 [xfs]
[ 1831.907969]  xfs_vn_unlink+0x55/0xa0 [xfs]
[ 1831.907970]  ? may_delete+0x7f/0x190
[ 1831.907971]  vfs_unlink+0x109/0x1a0
[ 1831.907972]  do_unlinkat+0x225/0x310
[ 1831.907974]  do_syscall_64+0x55/0x100
[ 1831.907975]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1831.907975] RIP: 0033:0x7f26250485b7
[ 1831.907977] Code: Bad RIP value.
[ 1831.907977] RSP: 002b:00007fffce6faab8 EFLAGS: 00000206 ORIG_RAX: 0000000000000107
[ 1831.907978] RAX: ffffffffffffffda RBX: 00000000016728c0 RCX: 00007f26250485b7
[ 1831.907979] RDX: 0000000000000000 RSI: 0000000001671690 RDI: 00000000ffffff9c
[ 1831.907979] RBP: 0000000001671600 R08: 0000000000000003 R09: 0000000000000000
[ 1831.907980] R10: 0000000000000003 R11: 0000000000000206 R12: 00007fffce6fac70
[ 1831.907980] R13: 0000000000000000 R14: 0000000000000000 R15: 00000000016728c0
[ 1831.907981] gcc             D    0 26474  26473 0x00000000
[ 1831.907982] Call Trace:
[ 1831.907983]  ? __schedule+0x21d/0x840
[ 1831.907984]  schedule+0x28/0x80
[ 1831.907985]  rwsem_down_read_failed+0xe1/0x140
[ 1831.907987]  call_rwsem_down_read_failed+0x14/0x30
[ 1831.907988]  down_read+0x1c/0x30
[ 1831.907988]  lookup_slow+0x27/0x50
[ 1831.907989]  walk_component+0x1bf/0x4a0
[ 1831.907990]  path_lookupat.isra.55+0x6d/0x220
[ 1831.907992]  filename_lookup.part.69+0xa0/0x170
[ 1831.907993]  ? __check_object_size+0x158/0x184
[ 1831.907994]  ? strncpy_from_user+0x4a/0x170
[ 1831.907995]  ? getname_flags+0x6a/0x1e0
[ 1831.907996]  do_faccessat+0xa2/0x240
[ 1831.907997]  do_syscall_64+0x55/0x100
[ 1831.907998]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1831.907999] RIP: 0033:0x7f4af479ed87
[ 1831.908000] Code: Bad RIP value.
[ 1831.908000] RSP: 002b:00007fff3f11af58 EFLAGS: 00000246 ORIG_RAX: 0000000000000015
[ 1831.908001] RAX: ffffffffffffffda RBX: 000000000000005c RCX: 00007f4af479ed87
[ 1831.908002] RDX: 0000000000632e65 RSI: 0000000000000000 RDI: 000000000227b460
[ 1831.908002] RBP: 00007fff3f11b000 R08: 0000000000000000 R09: 00007f4af47f9af0
[ 1831.908003] R10: 7974697275636573 R11: 0000000000000246 R12: 0000000000498875
[ 1831.908003] R13: 00007fff3f11dd8d R14: 000000000227b460 R15: 0000000000000000
[ 1831.908004] cc1             D    0 26477  26476 0x00000000
[ 1831.908005] Call Trace:
[ 1831.908006]  ? __schedule+0x21d/0x840
[ 1831.908007]  schedule+0x28/0x80
[ 1831.908008]  schedule_preempt_disabled+0xa/0x10
[ 1831.908009]  __mutex_lock.isra.6+0x2c3/0x4b0
[ 1831.908032]  xfs_reclaim_inodes_ag+0x299/0x300 [xfs]
[ 1831.908052]  ? xfs_bmapi_read+0x129/0x340 [xfs]
[ 1831.908054]  ? inode_lru_list_add+0x20/0x40
[ 1831.908054]  ? iput+0x16d/0x200
[ 1831.908077]  ? xfs_iunlock+0x61/0x110 [xfs]
[ 1831.908099]  ? xfs_perag_get+0x27/0xb0 [xfs]
[ 1831.908121]  ? xfs_inode_set_reclaim_tag+0x67/0x140 [xfs]
[ 1831.908144]  xfs_reclaim_inodes_nr+0x31/0x40 [xfs]
[ 1831.908145]  super_cache_scan+0x155/0x1a0
[ 1831.908146]  do_shrink_slab+0x128/0x290
[ 1831.908148]  shrink_slab+0x233/0x2b0
[ 1831.908149]  shrink_node+0xe6/0x460
[ 1831.908150]  do_try_to_free_pages+0xc6/0x370
[ 1831.908151]  try_to_free_pages+0xf5/0x1c0
[ 1831.908152]  __alloc_pages_slowpath+0x3aa/0xdc0
[ 1831.908153]  __alloc_pages_nodemask+0x297/0x2c0
[ 1831.908154]  alloc_pages_vma+0x7c/0x1f0
[ 1831.908155]  __handle_mm_fault+0x8b5/0xf80
[ 1831.908157]  handle_mm_fault+0x155/0x1d0
[ 1831.908158]  __do_page_fault+0x1e6/0x460
[ 1831.908159]  ? page_fault+0x8/0x30
[ 1831.908160]  page_fault+0x1e/0x30
[ 1831.908161] RIP: 0033:0x7ff3864ab988
[ 1831.908162] Code: Bad RIP value.
[ 1831.908162] RSP: 002b:00007ffe12e37508 EFLAGS: 00010283
[ 1831.908163] RAX: 00007ff38634e000 RBX: 00007ff3870bb198 RCX: 0000000000000001
[ 1831.908164] RDX: 0000000000000014 RSI: 0000000000000000 RDI: 00007ff38634e000
[ 1831.908164] RBP: 0000000000000005 R08: 000000000239e9f0 R09: 0000000000000000
[ 1831.908165] R10: 0000000000000000 R11: 000000000239e9f0 R12: 0000000000a2c800
[ 1831.908165] R13: 00007ff3863269c8 R14: 000000007ffff9d8 R15: 00007ff38711c000
[ 1831.908166] fixdep          D    0 26479  26425 0x00000000
[ 1831.908167] Call Trace:
[ 1831.908168]  ? __schedule+0x21d/0x840
[ 1831.908169]  schedule+0x28/0x80
[ 1831.908170]  io_schedule+0x12/0x40
[ 1831.908171]  generic_file_read_iter+0x3a4/0xc10
[ 1831.908172]  ? page_cache_tree_insert+0xe0/0xe0
[ 1831.908195]  xfs_file_buffered_aio_read+0x4b/0xd0 [xfs]
[ 1831.908217]  xfs_file_read_iter+0x6e/0xd0 [xfs]
[ 1831.908219]  __vfs_read+0x133/0x190
[ 1831.908220]  vfs_read+0x8a/0x140
[ 1831.908221]  ksys_read+0x4f/0xb0
[ 1831.908222]  do_syscall_64+0x55/0x100
[ 1831.908224]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1831.908224] RIP: 0033:0x7fa104b76c21
[ 1831.908225] Code: fe ff ff 48 8d 3d 6f 68 0a 00 48 83 ec 08 e8 56 3d 02 00 66 0f 1f 44 00 00 48 8d 05 d9 fa 0d 00 8b 00 85 c0 75 13 31 c0 0f 05 <48> 3d 00 f0 ff ff 77 57 f3 c3 0f 1f 44 00 00 41 54 55 49 89 d4 53
[ 1831.908226] RSP: 002b:00007ffea7b75238 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
[ 1831.908227] RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007fa104b76c21
[ 1831.908227] RDX: 00000000000002a6 RSI: 00000000014f5910 RDI: 0000000000000003
[ 1831.908228] RBP: 00000000014f5910 R08: 00000000014efa55 R09: 00007fa104bd1b40
[ 1831.908228] R10: 0000000000000000 R11: 0000000000000246 R12: 00000000000002a6
[ 1831.908229] R13: 00000000014fab76 R14: 0000000000000019 R15: 0000000000000007
[ 1831.908229] rm              D    0 26480  26371 0x00000000
[ 1831.908230] Call Trace:
[ 1831.908232]  ? __schedule+0x21d/0x840
[ 1831.908233]  ? __switch_to_asm+0x34/0x70
[ 1831.908233]  schedule+0x28/0x80
[ 1831.908234]  schedule_timeout+0x1d8/0x370
[ 1831.908235]  ? __switch_to_asm+0x40/0x70
[ 1831.908236]  ? __switch_to_asm+0x34/0x70
[ 1831.908237]  ? __switch_to_asm+0x40/0x70
[ 1831.908239]  ? __switch_to+0x159/0x4c0
[ 1831.908240]  ? __switch_to_asm+0x34/0x70
[ 1831.908241]  ? __switch_to_asm+0x40/0x70
[ 1831.908242]  __down+0x7f/0xd0
[ 1831.908264]  ? xfs_buf_find.isra.30+0x3b4/0x5e0 [xfs]
[ 1831.908265]  down+0x3b/0x50
[ 1831.908287]  xfs_buf_lock+0x32/0xf0 [xfs]
[ 1831.908309]  xfs_buf_find.isra.30+0x3b4/0x5e0 [xfs]
[ 1831.908331]  xfs_buf_get_map+0x40/0x2c0 [xfs]
[ 1831.908354]  xfs_buf_read_map+0x28/0x180 [xfs]
[ 1831.908377]  xfs_trans_read_buf_map+0xb4/0x2f0 [xfs]
[ 1831.908399]  xfs_imap_to_bp+0x67/0xd0 [xfs]
[ 1831.908421]  xfs_iunlink_remove+0x2b6/0x430 [xfs]
[ 1831.908445]  xfs_ifree+0x42/0x140 [xfs]
[ 1831.908475]  xfs_inactive_ifree+0x9e/0x1c0 [xfs]
[ 1831.908499]  xfs_inactive+0x9e/0x140 [xfs]
[ 1831.908522]  xfs_fs_destroy_inode+0xb1/0x1c0 [xfs]
[ 1831.908523]  do_unlinkat+0x256/0x310
[ 1831.908524]  do_syscall_64+0x55/0x100
[ 1831.908526]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1831.908526] RIP: 0033:0x7fce9b3a05b7
[ 1831.908528] Code: Bad RIP value.
[ 1831.908528] RSP: 002b:00007ffc5b1d3528 EFLAGS: 00000206 ORIG_RAX: 0000000000000107
[ 1831.908529] RAX: ffffffffffffffda RBX: 00000000020248c0 RCX: 00007fce9b3a05b7
[ 1831.908530] RDX: 0000000000000000 RSI: 0000000002023690 RDI: 00000000ffffff9c
[ 1831.908530] RBP: 0000000002023600 R08: 0000000000000003 R09: 0000000000000000
[ 1831.908531] R10: 0000000000000003 R11: 0000000000000206 R12: 00007ffc5b1d36e0
[ 1831.908531] R13: 0000000000000000 R14: 0000000000000000 R15: 00000000020248c0
[ 1831.908532] cc1             D    0 26483  26482 0x00000000
[ 1831.908533] Call Trace:
[ 1831.908535]  ? __schedule+0x21d/0x840
[ 1831.908535]  schedule+0x28/0x80
[ 1831.908536]  rwsem_down_read_failed+0xe1/0x140
[ 1831.908538]  call_rwsem_down_read_failed+0x14/0x30
[ 1831.908539]  down_read+0x1c/0x30
[ 1831.908540]  path_openat+0xb9b/0x1650
[ 1831.908541]  ? mem_cgroup_commit_charge+0x7f/0x550
[ 1831.908542]  do_filp_open+0x93/0x100
[ 1831.908543]  ? __handle_mm_fault+0x9dc/0xf80
[ 1831.908544]  ? __check_object_size+0x158/0x184
[ 1831.908546]  do_sys_open+0x186/0x210
[ 1831.908547]  do_syscall_64+0x55/0x100
[ 1831.908548]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1831.908549] RIP: 0033:0x7f3e426469c0
[ 1831.908550] Code: Bad RIP value.
[ 1831.908550] RSP: 002b:00007ffe6e0c7070 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
[ 1831.908551] RAX: ffffffffffffffda RBX: 00000000027634a0 RCX: 00007f3e426469c0
[ 1831.908552] RDX: 0000000000000100 RSI: 0000000002762300 RDI: 00000000ffffff9c
[ 1831.908552] RBP: 00000000027adae0 R08: 00000000027b5f40 R09: 00000000f43cde6b
[ 1831.908553] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000002762300
[ 1831.908553] R13: 00000000f43cde6b R14: 0000000002760fc0 R15: 0000000002760fc0
[ 1831.908554] as              D    0 26484  26482 0x00000000
[ 1831.908555] Call Trace:
[ 1831.908556]  ? __schedule+0x21d/0x840
[ 1831.908557]  schedule+0x28/0x80
[ 1831.908558]  schedule_timeout+0x17e/0x370
[ 1831.908559]  ? __next_timer_interrupt+0xc0/0xc0
[ 1831.908582]  xfs_iget+0x17f/0x990 [xfs]
[ 1831.908605]  xfs_ialloc+0xf5/0x5a0 [xfs]
[ 1831.908628]  ? kmem_zone_alloc+0x61/0xe0 [xfs]
[ 1831.908650]  xfs_dir_ialloc+0x6c/0x220 [xfs]
[ 1831.908673]  xfs_create+0x224/0x620 [xfs]
[ 1831.908696]  xfs_generic_create+0x226/0x2c0 [xfs]
[ 1831.908697]  path_openat+0x1279/0x1650
[ 1831.908699]  ? filemap_map_pages+0x139/0x3c0
[ 1831.908700]  do_filp_open+0x93/0x100
[ 1831.908701]  ? __handle_mm_fault+0xd6a/0xf80
[ 1831.908702]  ? __check_object_size+0x158/0x184
[ 1831.908703]  do_sys_open+0x186/0x210
[ 1831.908704]  do_syscall_64+0x55/0x100
[ 1831.908705]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1831.908706] RIP: 0033:0x7fb4160ce9c0
[ 1831.908707] Code: Bad RIP value.
[ 1831.908708] RSP: 002b:00007ffcbec13710 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
[ 1831.908709] RAX: ffffffffffffffda RBX: 0000000000a05280 RCX: 00007fb4160ce9c0
[ 1831.908709] RDX: 0000000000000242 RSI: 0000000000a29d50 RDI: 00000000ffffff9c
[ 1831.908710] RBP: 00007fb4162ac7ca R08: 0000000000000002 R09: 00007fb4162ac7cb
[ 1831.908710] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000000
[ 1831.908711] R13: 00007fb4162ac7c9 R14: 00000000ffffffff R15: 00007ffcbec13a20
[ 1831.908712] cc1             D    0 26487  26486 0x00000000
[ 1831.908713] Call Trace:
[ 1831.908714]  ? __schedule+0x21d/0x840
[ 1831.908715]  schedule+0x28/0x80
[ 1831.908716]  io_schedule+0x12/0x40
[ 1831.908717]  generic_file_read_iter+0x3a4/0xc10
[ 1831.908718]  ? page_cache_tree_insert+0xe0/0xe0
[ 1831.908740]  xfs_file_buffered_aio_read+0x4b/0xd0 [xfs]
[ 1831.908763]  xfs_file_read_iter+0x6e/0xd0 [xfs]
[ 1831.908764]  __vfs_read+0x133/0x190
[ 1831.908766]  vfs_read+0x8a/0x140
[ 1831.908767]  ksys_read+0x4f/0xb0
[ 1831.908768]  do_syscall_64+0x55/0x100
[ 1831.908769]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1831.908770] RIP: 0033:0x7fd0adf56c21
[ 1831.908771] Code: Bad RIP value.
[ 1831.908772] RSP: 002b:00007fff4be63908 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
[ 1831.908772] RAX: ffffffffffffffda RBX: 00000000000002a6 RCX: 00007fd0adf56c21
[ 1831.908773] RDX: 00000000000002a6 RSI: 0000000002e1a8f0 RDI: 0000000000000005
[ 1831.908773] RBP: 0000000002e39ae0 R08: 000000000120d1f6 R09: 000000006feaa6fe
[ 1831.908774] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000002e1a8f0
[ 1831.908774] R13: 0000000002ef6800 R14: 0000000000000000 R15: 0000000000000000
[ 1831.908775] as              D    0 26488  26486 0x00000000
[ 1831.908776] Call Trace:
[ 1831.908777]  ? __schedule+0x21d/0x840
[ 1831.908778]  schedule+0x28/0x80
[ 1831.908779]  schedule_timeout+0x1d8/0x370
[ 1831.908780]  __down+0x7f/0xd0
[ 1831.908802]  ? xfs_buf_find.isra.30+0x3b4/0x5e0 [xfs]
[ 1831.908803]  down+0x3b/0x50
[ 1831.908825]  xfs_buf_lock+0x32/0xf0 [xfs]
[ 1831.908847]  xfs_buf_find.isra.30+0x3b4/0x5e0 [xfs]
[ 1831.908870]  xfs_buf_get_map+0x40/0x2c0 [xfs]
[ 1831.908892]  xfs_buf_read_map+0x28/0x180 [xfs]
[ 1831.908915]  xfs_trans_read_buf_map+0xb4/0x2f0 [xfs]
[ 1831.908937]  xfs_read_agi+0x9e/0x140 [xfs]
[ 1831.908959]  xfs_ialloc_read_agi+0x34/0xd0 [xfs]
[ 1831.908980]  xfs_dialloc+0xe7/0x2b0 [xfs]
[ 1831.909003]  xfs_ialloc+0x6b/0x5a0 [xfs]
[ 1831.909026]  ? kmem_zone_alloc+0x61/0xe0 [xfs]
[ 1831.909049]  xfs_dir_ialloc+0x6c/0x220 [xfs]
[ 1831.909072]  xfs_create+0x224/0x620 [xfs]
[ 1831.909095]  xfs_generic_create+0x226/0x2c0 [xfs]
[ 1831.909096]  path_openat+0x1279/0x1650
[ 1831.909097]  ? filemap_map_pages+0x139/0x3c0
[ 1831.909098]  do_filp_open+0x93/0x100
[ 1831.909099]  ? __handle_mm_fault+0xd6a/0xf80
[ 1831.909100]  ? __check_object_size+0x158/0x184
[ 1831.909102]  do_sys_open+0x186/0x210
[ 1831.909103]  do_syscall_64+0x55/0x100
[ 1831.909104]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1831.909105] RIP: 0033:0x7f435fabe9c0
[ 1831.909106] Code: Bad RIP value.
[ 1831.909106] RSP: 002b:00007ffd8f4c1980 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
[ 1831.909107] RAX: ffffffffffffffda RBX: 0000000001df5280 RCX: 00007f435fabe9c0
[ 1831.909108] RDX: 0000000000000242 RSI: 0000000001e19a00 RDI: 00000000ffffff9c
[ 1831.909108] RBP: 00007f435fc9c7ca R08: 0000000000000002 R09: 00007f435fc9c7cb
[ 1831.909109] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000000
[ 1831.909109] R13: 00007f435fc9c7c9 R14: 00000000ffffffff R15: 00007ffd8f4c1c90
Comment 5 Roger 2019-01-29 00:47:23 UTC
Should have mentioned that this was done without turning off
inode reclaim and after a reboot.
Comment 6 Dave Chinner 2019-01-29 01:23:29 UTC
On Tue, Jan 29, 2019 at 12:43:39AM +0000, bugzilla-daemon@bugzilla.kernel.org wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=202441
> 
> --- Comment #4 from Roger (rogan6710@gmail.com) ---
> "If all else fails, read the man page" ;)
> The complete dmesg output is a litte bit too big for the 
> system here. they only allow 65535 characters

Attach it to the bug rather than pasting in line. Can be much bigger
that way.

> Last Output:
> [ 1831.904739] sysrq: SysRq : Show Blocked State
> [ 1831.904745]   task                        PC stack   pid father
> [ 1831.904752] kswapd0         D    0    85      2 0x80000000
> [ 1831.904753] Call Trace:
> [ 1831.904758]  ? __schedule+0x21d/0x840
> [ 1831.904760]  schedule+0x28/0x80
> [ 1831.904761]  schedule_preempt_disabled+0xa/0x10
> [ 1831.904762]  __mutex_lock.isra.6+0x2c3/0x4b0
> [ 1831.904806]  ? xfs_perag_get_tag+0x3d/0xe0 [xfs]
> [ 1831.904830]  xfs_reclaim_inodes_ag+0x299/0x300 [xfs]

Waiting on something else reclaiming inodes from that AG.

> [ 1831.904930] xfsaild/sdc1    D    0  1446      2 0x80000000
> [ 1831.904931] Call Trace:
> [ 1831.904932]  ? __schedule+0x21d/0x840
> [ 1831.904933]  schedule+0x28/0x80
> [ 1831.904956]  xfs_log_force+0x166/0x2e0 [xfs]

Waiting on a log force.

> [ 1831.905012] Xorg            D    0  1496   1495 0x00000000
> [ 1831.905013] Call Trace:
> [ 1831.905014]  ? __schedule+0x21d/0x840
> [ 1831.905015]  schedule+0x28/0x80
> [ 1831.905016]  schedule_preempt_disabled+0xa/0x10
> [ 1831.905017]  __mutex_lock.isra.6+0x2c3/0x4b0
> [ 1831.905039]  ? xfs_perag_get_tag+0x3d/0xe0 [xfs]
> [ 1831.905061]  xfs_reclaim_inodes_ag+0x299/0x300 [xfs]
> [ 1831.905084]  ? xfs_perag_get+0x27/0xb0 [xfs]
> [ 1831.905106]  ? xfs_inode_set_reclaim_tag+0x67/0x140 [xfs]
> [ 1831.905128]  xfs_reclaim_inodes_nr+0x31/0x40 [xfs]
> [ 1831.905130]  super_cache_scan+0x155/0x1a0
> [ 1831.905131]  do_shrink_slab+0x128/0x290
> [ 1831.905132]  shrink_slab+0x233/0x2b0
> [ 1831.905133]  shrink_node+0xe6/0x460
> [ 1831.905135]  do_try_to_free_pages+0xc6/0x370
> [ 1831.905136]  try_to_free_pages+0xf5/0x1c0
> [ 1831.905137]  __alloc_pages_slowpath+0x3aa/0xdc0
> [ 1831.905139]  ? enqueue_entity+0x36d/0x7e0
> [ 1831.905140]  __alloc_pages_nodemask+0x297/0x2c0
> [ 1831.905142]  kmalloc_order+0x14/0x40
> [ 1831.905143]  kmalloc_order_trace+0x1e/0xa0
> [ 1831.905198]  dc_create_state+0x19/0x30 [amdgpu]
> [ 1831.905234]  amdgpu_dm_atomic_check+0xc6/0x3b0 [amdgpu]
> [ 1831.905248]  drm_atomic_check_only+0x460/0x660 [drm]
> [ 1831.905258]  ? drm_atomic_set_fb_for_plane+0x53/0x80 [drm]
> [ 1831.905267]  drm_atomic_nonblocking_commit+0x13/0x50 [drm]
> [ 1831.905276]  drm_atomic_helper_page_flip+0x5b/0x90 [drm_kms_helper]
> [ 1831.905285]  drm_mode_page_flip_ioctl+0x553/0x5b0 [drm]
> [ 1831.905294]  ? drm_mode_cursor2_ioctl+0x10/0x10 [drm]
> [ 1831.905301]  drm_ioctl_kernel+0xa1/0xf0 [drm]
> [ 1831.905310]  drm_ioctl+0x206/0x3a0 [drm]

Ok, that looks familiar. GPU in a "nonblocking" code path,
doing a blocking memory allocation. Yeah, dc_create_state() is doing
a GFP_KERNEL allocation, which means the memory allocation is
allowed to block waiting for memory reclaim....

> [ 1831.905380] mc              D    0  1866   1740 0x00000000
> [ 1831.905381] Call Trace:
> [ 1831.905383]  schedule+0x28/0x80
> [ 1831.905384]  schedule_preempt_disabled+0xa/0x10
> [ 1831.905429]  xfs_reclaim_inodes_ag+0x299/0x300 [xfs]
> [ 1831.905522]  xfs_reclaim_inodes_nr+0x31/0x40 [xfs]
> [ 1831.905523]  super_cache_scan+0x155/0x1a0
> [ 1831.905524]  do_shrink_slab+0x128/0x290
> [ 1831.905526]  shrink_slab+0x233/0x2b0
> [ 1831.905527]  shrink_node+0xe6/0x460
> [ 1831.905528]  do_try_to_free_pages+0xc6/0x370
> [ 1831.905529]  try_to_free_pages+0xf5/0x1c0
> [ 1831.905530]  __alloc_pages_slowpath+0x3aa/0xdc0
> [ 1831.905537]  __alloc_pages_nodemask+0x297/0x2c0
> [ 1831.905538]  __do_page_cache_readahead+0xb1/0x1b0
> [ 1831.905539]  ondemand_readahead+0x1f9/0x2c0
> [ 1831.905541]  generic_file_read_iter+0x738/0xc10
> [ 1831.905542]  ? page_cache_tree_insert+0xe0/0xe0
> [ 1831.905543]  nfs_file_read+0x5d/0x80

Oh, NFS read. XFS clears GFP_FS from it's mapping mask so page cache
demand doesn't end up blocked on filesystem reclaim.

> [ 1831.905574] kworker/u16:4   D    0 14955      2 0x80000000
> [ 1831.905577] Workqueue: writeback wb_workfn (flush-8:32)
> [ 1831.905578] Call Trace:
> [ 1831.905580]  schedule+0x28/0x80
> [ 1831.905581]  schedule_timeout+0x1d8/0x370
> [ 1831.905607]  __down+0x7f/0xd0
> [ 1831.905630]  down+0x3b/0x50
> [ 1831.905652]  xfs_buf_lock+0x32/0xf0 [xfs]
> [ 1831.905675]  xfs_buf_find.isra.30+0x3b4/0x5e0 [xfs]
> [ 1831.905698]  xfs_buf_get_map+0x40/0x2c0 [xfs]
> [ 1831.905720]  xfs_buf_read_map+0x28/0x180 [xfs]
> [ 1831.905743]  xfs_trans_read_buf_map+0xb4/0x2f0 [xfs]
> [ 1831.905764]  xfs_read_agf+0x94/0x120 [xfs]
> [ 1831.905785]  xfs_alloc_read_agf+0x47/0x1b0 [xfs]
> [ 1831.905805]  xfs_alloc_fix_freelist+0x377/0x430 [xfs]
> [ 1831.905851]  xfs_alloc_vextent+0x121/0x580 [xfs]
> [ 1831.905871]  xfs_bmap_btalloc+0x420/0x890 [xfs]
> [ 1831.905893]  xfs_bmapi_write+0x5f5/0xb80 [xfs]
> [ 1831.905916]  xfs_iomap_write_allocate+0x176/0x380 [xfs]
> [ 1831.905939]  xfs_map_blocks+0x186/0x450 [xfs]
> [ 1831.905962]  xfs_do_writepage+0x123/0x440 [xfs]
> [ 1831.905963]  write_cache_pages+0x1dd/0x470

Writeback blocked waiting for the AGF to be unlocked so it can do
allocation.

> [ 1831.906033] make            D    0 25592  24315 0x00000000
> [ 1831.906034] Call Trace:
> [ 1831.906037]  schedule+0x28/0x80
> [ 1831.906037]  rwsem_down_read_failed+0xe1/0x140
> [ 1831.906040]  call_rwsem_down_read_failed+0x14/0x30
> [ 1831.906041]  down_read+0x1c/0x30
> [ 1831.906042]  lookup_slow+0x27/0x50
> [ 1831.906043]  walk_component+0x1bf/0x4a0
> [ 1831.906048]  path_lookupat.isra.55+0x6d/0x220
> [ 1831.906054]  filename_lookup.part.69+0xa0/0x170
> [ 1831.906059]  vfs_statx+0x73/0xe0

Blocked in VFS pathname walk.

> [ 1831.906076] cc1             D    0 26405  26404 0x00000000
> [ 1831.906077] Call Trace:
> [ 1831.906101]  schedule+0x28/0x80
> [ 1831.906102]  schedule_timeout+0x1d8/0x370
> [ 1831.906128]  wait_for_completion+0xad/0x130
> [ 1831.906173]  xfs_buf_iowait+0x27/0xd0 [xfs]
> [ 1831.906195]  __xfs_buf_submit+0xd7/0x230 [xfs]
> [ 1831.906218]  xfs_bwrite+0x25/0x60 [xfs]
> [ 1831.906240]  xfs_reclaim_inode+0x309/0x330 [xfs]
> [ 1831.906263]  xfs_reclaim_inodes_ag+0x1b1/0x300 [xfs]
> [ 1831.906331]  xfs_reclaim_inodes_nr+0x31/0x40 [xfs]
> [ 1831.906332]  super_cache_scan+0x155/0x1a0
> [ 1831.906333]  do_shrink_slab+0x128/0x290
> [ 1831.906335]  shrink_slab+0x233/0x2b0
> [ 1831.906336]  shrink_node+0xe6/0x460
> [ 1831.906337]  do_try_to_free_pages+0xc6/0x370
> [ 1831.906338]  try_to_free_pages+0xf5/0x1c0
> [ 1831.906339]  __alloc_pages_slowpath+0x3aa/0xdc0
> [ 1831.906340]  __alloc_pages_nodemask+0x297/0x2c0
> [ 1831.906342]  alloc_pages_vma+0x7c/0x1f0
> [ 1831.906343]  __handle_mm_fault+0x8b5/0xf80
> [ 1831.906345]  handle_mm_fault+0x155/0x1d0
> [ 1831.906346]  __do_page_fault+0x1e6/0x460
> [ 1831.906349]  page_fault+0x1e/0x30

And there's our reclaimer that is doing IO. Page fault on an
executable page.

> [ 1831.906355] cc1             D    0 26411  26410 0x00000000
> [ 1831.906356] Call Trace:
> [ 1831.906358]  schedule+0x28/0x80
> [ 1831.906359]  schedule_preempt_disabled+0xa/0x10
> [ 1831.906360]  __mutex_lock.isra.6+0x2c3/0x4b0
> [ 1831.906383]  xfs_reclaim_inodes_ag+0x299/0x300 [xfs]
> [ 1831.906474]  xfs_reclaim_inodes_nr+0x31/0x40 [xfs]
> [ 1831.906476]  super_cache_scan+0x155/0x1a0
> [ 1831.906477]  do_shrink_slab+0x128/0x290
> [ 1831.906478]  shrink_slab+0x233/0x2b0
> [ 1831.906479]  shrink_node+0xe6/0x460
> [ 1831.906481]  do_try_to_free_pages+0xc6/0x370
> [ 1831.906481]  try_to_free_pages+0xf5/0x1c0
> [ 1831.906483]  __alloc_pages_slowpath+0x3aa/0xdc0
> [ 1831.906485]  __alloc_pages_nodemask+0x297/0x2c0
> [ 1831.906486]  alloc_pages_vma+0x7c/0x1f0
> [ 1831.906487]  wp_page_copy+0x4f0/0x740
> [ 1831.906488]  do_wp_page+0x8a/0x5f0
> [ 1831.906489]  __handle_mm_fault+0xafc/0xf80
> [ 1831.906491]  handle_mm_fault+0x155/0x1d0
> [ 1831.906492]  __do_page_fault+0x1e6/0x460

same thing, but blocked on the per-ag reclaim lock.

> [ 1831.906500] cc1             D    0 26415  26414 0x00000000
> [ 1831.906501] Call Trace:
> [ 1831.906503]  schedule+0x28/0x80
> [ 1831.906504]  schedule_preempt_disabled+0xa/0x10
> [ 1831.906505]  __mutex_lock.isra.6+0x2c3/0x4b0
> [ 1831.906528]  xfs_reclaim_inodes_ag+0x299/0x300 [xfs]

same thing.

> [ 1831.906641] cc1             D    0 26430  26428 0x00000000

same thing.

> [ 1831.906783] fixdep          D    0 26436  26319 0x00000000
> [ 1831.906784] Call Trace:
> [ 1831.906786]  schedule+0x28/0x80
> [ 1831.906787]  rwsem_down_read_failed+0xe1/0x140
> [ 1831.906788]  call_rwsem_down_read_failed+0x14/0x30
> [ 1831.906789]  down_read+0x1c/0x30
> [ 1831.906790]  path_openat+0xb9b/0x1650
> [ 1831.906813]  do_filp_open+0x93/0x100
> [ 1831.906816]  do_sys_open+0x186/0x210

Blocked in pathwalk.

> [ 1831.906825] cc1             D    0 26450  26449 0x00000000
> [ 1831.906826] Call Trace:
> [ 1831.906850]  schedule+0x28/0x80
> [ 1831.906851]  schedule_timeout+0x1d8/0x370
> [ 1831.906875]  wait_for_completion+0xad/0x130
> [ 1831.906920]  xfs_buf_iowait+0x27/0xd0 [xfs]
> [ 1831.906942]  __xfs_buf_submit+0xd7/0x230 [xfs]
> [ 1831.906965]  xfs_buf_read_map+0xc1/0x180 [xfs]
> [ 1831.906988]  xfs_trans_read_buf_map+0xb4/0x2f0 [xfs]
> [ 1831.907010]  xfs_imap_to_bp+0x67/0xd0 [xfs]
> [ 1831.907031]  xfs_iread+0x82/0x1f0 [xfs]
> [ 1831.907055]  xfs_iget+0x20f/0x990 [xfs]
> [ 1831.907099]  xfs_lookup+0xa4/0x120 [xfs]
> [ 1831.907123]  xfs_vn_lookup+0x70/0xa0 [xfs]
> [ 1831.907124]  path_openat+0xaff/0x1650
> [ 1831.907125]  do_filp_open+0x93/0x100

Blocked in open(), waiting for inode buffer read.

> [ 1831.907138] cc1             D    0 26454  26453 0x00000000
> [ 1831.907139] Call Trace:
> [ 1831.907141]  schedule+0x28/0x80
> [ 1831.907142]  schedule_timeout+0x1d8/0x370
> [ 1831.907143]  __down+0x7f/0xd0
> [ 1831.907169]  down+0x3b/0x50
> [ 1831.907191]  xfs_buf_lock+0x32/0xf0 [xfs]
> [ 1831.907213]  xfs_buf_find.isra.30+0x3b4/0x5e0 [xfs]
> [ 1831.907235]  xfs_buf_get_map+0x40/0x2c0 [xfs]
> [ 1831.907258]  xfs_buf_read_map+0x28/0x180 [xfs]
> [ 1831.907303]  xfs_trans_read_buf_map+0xb4/0x2f0 [xfs]
> [ 1831.907325]  xfs_read_agi+0x9e/0x140 [xfs]
> [ 1831.907347]  xfs_ialloc_read_agi+0x34/0xd0 [xfs]
> [ 1831.907368]  xfs_dialloc+0xe7/0x2b0 [xfs]
> [ 1831.907391]  xfs_ialloc+0x6b/0x5a0 [xfs]

INode allocation in open call, blocked waiting on AGI buffer lock.

> [ 1831.907498] rm              D    0 26462  26356 0x00000000
> [ 1831.907498] Call Trace:
> [ 1831.907501]  schedule+0x28/0x80
> [ 1831.907501]  schedule_timeout+0x1d8/0x370
> [ 1831.907503]  __down+0x7f/0xd0
> [ 1831.907525]  down+0x3b/0x50
> [ 1831.907547]  xfs_buf_lock+0x32/0xf0 [xfs]
> [ 1831.907570]  xfs_buf_find.isra.30+0x3b4/0x5e0 [xfs]
> [ 1831.907592]  xfs_buf_get_map+0x40/0x2c0 [xfs]
> [ 1831.907614]  xfs_buf_read_map+0x28/0x180 [xfs]
> [ 1831.907637]  xfs_trans_read_buf_map+0xb4/0x2f0 [xfs]
> [ 1831.907659]  xfs_read_agi+0x9e/0x140 [xfs]
> [ 1831.907682]  xfs_iunlink+0x4d/0x140 [xfs]
> [ 1831.907705]  xfs_remove+0x1ec/0x2e0 [xfs]
> [ 1831.907728]  xfs_vn_unlink+0x55/0xa0 [xfs]

Unlink, blocked on AGI buffer lock.

> [ 1831.907739] rm              D    0 26472  26300 0x00000000

Ditto.

> [ 1831.907981] gcc             D    0 26474  26473 0x00000000
> [ 1831.907982] Call Trace:
> [ 1831.907984]  schedule+0x28/0x80
> [ 1831.907985]  rwsem_down_read_failed+0xe1/0x140
> [ 1831.907987]  call_rwsem_down_read_failed+0x14/0x30
> [ 1831.907988]  down_read+0x1c/0x30
> [ 1831.907988]  lookup_slow+0x27/0x50
> [ 1831.907989]  walk_component+0x1bf/0x4a0
> [ 1831.907990]  path_lookupat.isra.55+0x6d/0x220
> [ 1831.907992]  filename_lookup.part.69+0xa0/0x170
> [ 1831.907996]  do_faccessat+0xa2/0x240

Blocked in pathname walk.

> [ 1831.908004] cc1             D    0 26477  26476 0x00000000

Pagefault -> per ag shrinker lock again.

> [ 1831.908166] fixdep          D    0 26479  26425 0x00000000
> [ 1831.908167] Call Trace:
> [ 1831.908169]  schedule+0x28/0x80
> [ 1831.908170]  io_schedule+0x12/0x40
> [ 1831.908171]  generic_file_read_iter+0x3a4/0xc10
> [ 1831.908195]  xfs_file_buffered_aio_read+0x4b/0xd0 [xfs]
> [ 1831.908217]  xfs_file_read_iter+0x6e/0xd0 [xfs]
> [ 1831.908219]  __vfs_read+0x133/0x190
> [ 1831.908220]  vfs_read+0x8a/0x140

waiting on read IO. Disk is busy.

> [ 1831.908229] rm              D    0 26480  26371 0x00000000
> [ 1831.908230] Call Trace:
> [ 1831.908233]  schedule+0x28/0x80
> [ 1831.908234]  schedule_timeout+0x1d8/0x370
> [ 1831.908242]  __down+0x7f/0xd0
> [ 1831.908265]  down+0x3b/0x50
> [ 1831.908287]  xfs_buf_lock+0x32/0xf0 [xfs]
> [ 1831.908309]  xfs_buf_find.isra.30+0x3b4/0x5e0 [xfs]
> [ 1831.908331]  xfs_buf_get_map+0x40/0x2c0 [xfs]
> [ 1831.908354]  xfs_buf_read_map+0x28/0x180 [xfs]
> [ 1831.908377]  xfs_trans_read_buf_map+0xb4/0x2f0 [xfs]
> [ 1831.908399]  xfs_imap_to_bp+0x67/0xd0 [xfs]
> [ 1831.908421]  xfs_iunlink_remove+0x2b6/0x430 [xfs]
> [ 1831.908445]  xfs_ifree+0x42/0x140 [xfs]
> [ 1831.908475]  xfs_inactive_ifree+0x9e/0x1c0 [xfs]
> [ 1831.908499]  xfs_inactive+0x9e/0x140 [xfs]
> [ 1831.908522]  xfs_fs_destroy_inode+0xb1/0x1c0 [xfs]

Unlink, holds AGI buffer lock, blocked on inode buffer lock.
 
> [ 1831.908532] cc1             D    0 26483  26482 0x00000000

Blocked in path walk.

> [ 1831.908554] as              D    0 26484  26482 0x00000000
> [ 1831.908555] Call Trace:
> [ 1831.908557]  schedule+0x28/0x80
> [ 1831.908558]  schedule_timeout+0x17e/0x370
> [ 1831.908582]  xfs_iget+0x17f/0x990 [xfs]
> [ 1831.908605]  xfs_ialloc+0xf5/0x5a0 [xfs]
> [ 1831.908650]  xfs_dir_ialloc+0x6c/0x220 [xfs]
> [ 1831.908673]  xfs_create+0x224/0x620 [xfs]
> [ 1831.908696]  xfs_generic_create+0x226/0x2c0 [xfs]
> [ 1831.908697]  path_openat+0x1279/0x1650
> [ 1831.908700]  do_filp_open+0x93/0x100

Blocked in inode allocation, most likely waiting to for a recently
freed inode to be reclaimed fully

> [ 1831.908712] cc1             D    0 26487  26486 0x00000000

Waiting on read.

> [ 1831.908775] as              D    0 26488  26486 0x00000000

waiting on AGI buffer lock for allocation.

OK, so your disks are busy and it would appear that the problem is
memory reclaim driving the inode cache hard into reclaiming dirty
inodes and having to wait for IO to complete before it can make
progress. That's currently the only behaviour we have that stands
between "systems works" and "system can be driven into OOM kill
death by direct reclaim". i.e. it prevents memory reclaim from
skipping and making insufficient progress and winding the reclaim
priority up until it triggers the OOM killer because it takes a lot
of time to write back dirty inodes...

It looks like 4.18->4.19 has put a lot more pressure on the inode
caches and is driving them to block on dirty inodes much, much more
often. It would be instructive to know if this behaviour appeared in
4.19-rc1 or not, because the memory reclaim shrinker algorithms were
significantly changed in the 4.19 merge window....

Cheers,

Dave.
Comment 7 Roger 2019-01-29 03:36:40 UTC
I'll do a test on 4.19-rc1 asap, and use the "Add an attachment" 
for dmesg from that test. Have to get some sleep first.
Comment 8 Roger 2019-01-29 09:09:11 UTC
Created attachment 280837 [details]
meminfo and xfs_info 4.19.0-rc1
Comment 9 Roger 2019-01-29 09:11:28 UTC
Created attachment 280839 [details]
dmesg with sysrq show blocked state for a run on 4.19.0-rc1
Comment 10 Roger 2019-01-29 09:27:46 UTC
I did not experience these problems with 4.19.0-rc1.
The compile completed in 3min 38s which is about as good as the 
best tests on pre 4.19 that I've done on any file system.
I had to do the test "nomodeset" in console mode because the 
vega10 drivers for my vega64 stopped working in this version.
Comment 11 Roger 2019-01-29 09:29:28 UTC
Now onto testing rc2...
Comment 12 Roger 2019-01-29 17:55:00 UTC
Now I have tested all rc versions as well. None of them have the problem.
I'm watching "top" as the compile executes and seeing a _large_ difference
in how the problem free kernel versions handles buff/cache versus the others.

Beginnig from rc5, might have been earlier also, cache get's released, sometimes almost all of it, and begins to fill up slowly again, while for instance on 4.19.18 it get's almost completely filled (23.5 of 24 G) and is not released unless the copying is manually halted.
Comment 13 Roger 2019-01-29 21:19:52 UTC
Considering that rc8 which I believe was released as 4.19.0 did not show any problems on my 24G machine I must have managed to get a false positive on 4.19.0. The machine I tested that on has less ram (8G) but I don't know if that matters.

Anyhow, after a filthy amount of copying and compiling I can say that
something probably went wrong between 4.19.2, which is ok, and 4.19.3
which is not, at least on this 9590. 

I downloaded, compiled, and tested all rc versions, 4.19.{2,3,5,9} and verified that 4.19.{3,5,9,18} all have the problems described above on the 9590.
All tests were done in console (nomodeset) directly after boot.
Comment 14 Dave Chinner 2019-01-29 21:41:21 UTC
On Tue, Jan 29, 2019 at 05:55:00PM +0000, bugzilla-daemon@bugzilla.kernel.org wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=202441
> 
> --- Comment #12 from Roger (rogan6710@gmail.com) ---
> Now I have tested all rc versions as well. None of them have the problem.
> I'm watching "top" as the compile executes and seeing a _large_ difference
> in how the problem free kernel versions handles buff/cache versus the others.

You've been busy! And your results are very interesting.

> Beginnig from rc5, might have been earlier also, cache get's released,
> sometimes almost all of it, and begins to fill up slowly again,

Which I'd consider bad behaviour - trashing the entire working set
because memory pressure is occurring is pathological behaviour.

Can you confirm which -rcX that behaviour starts in? e.g. between
-rc4 and -rc5 there is this commit:

172b06c32b94 mm: slowly shrink slabs with a relatively small number of objects

Which does change the way that the inode caches are reclaimed by
forcably triggering reclaim for caches that would have previously
been ignored. That's one of the "red flag" commits I noticed when
first looking at the history between 4.18 and 4.19....

> while for
> instance on 4.19.18 it get's almost completely filled (23.5 of 24 G) and is
> not
> released unless the copying is manually halted.

Which is how I'd expect memory reclaim to work - only free enough
for the current demand. What seems to be the issue is that it's not
freeing enough page cache, and so dumping more reclaim load on the
shrinkers and that's driving XFS inode reclaim into IO and
blocking...

Looking at the sysrq-w info from 4.19-rc1, it's all just waiting on
IO as the disk is busy, as I'd expect to see. Given that this
doesn't appear to be a problem in the early 4.19-rcX kernels, that
means it's either a problem in the released 4.19.0 or it's something
backported from a 4.20 kernel into the stable kernels.

SO, three questions:
	- did you test a 4.19.0 kernel?
	- if not, can you test it?
	- if 4.19.0 doesn't have the problem, can you sample a
	  couple of 4.19.x stable kernels (say .5, .10 and .15,
	  but definitely not .11 or .12 as they contain memory
	  corrupting bugs from an auto-backport of a buggy, untested
	  4.20-rc commit)

Basically, we're now at the point where this needs to be isolated
to the stable kernel series, and then we have a much smaller bunch
of commits that might be causing it.

Cheers,

Dave.
Comment 15 Dave Chinner 2019-01-29 21:44:10 UTC
On Tue, Jan 29, 2019 at 09:19:52PM +0000, bugzilla-daemon@bugzilla.kernel.org wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=202441
> 
> --- Comment #13 from Roger (rogan6710@gmail.com) ---
> Considering that rc8 which I believe was released as 4.19.0 did not show any
> problems on my 24G machine I must have managed to get a false positive on
> 4.19.0. The machine I tested that on has less ram (8G) but I don't know if
> that
> matters.
> 
> Anyhow, after a filthy amount of copying and compiling I can say that
> something probably went wrong between 4.19.2, which is ok, and 4.19.3
> which is not, at least on this 9590. 

Thank you!

We crossed streams - I was writing the email suggesting this when,
in fact, your were way ahead of me.

> I downloaded, compiled, and tested all rc versions, 4.19.{2,3,5,9} and
> verified
> that 4.19.{3,5,9,18} all have the problems described above on the 9590.
> All tests were done in console (nomodeset) directly after boot.

Ok, I'll have a look at the 4.19.2 -> 4.19.3 history now and see
what pops out.

Cheers,

Dave.
Comment 16 Dave Chinner 2019-01-29 21:53:16 UTC
On Tue, Jan 29, 2019 at 09:41:21PM +0000, bugzilla-daemon@bugzilla.kernel.org wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=202441
> --- Comment #14 from Dave Chinner (david@fromorbit.com) ---
> > --- Comment #12 from Roger (rogan6710@gmail.com) ---
> > Beginnig from rc5, might have been earlier also, cache get's released,
> > sometimes almost all of it, and begins to fill up slowly again,
> 
> Which I'd consider bad behaviour - trashing the entire working set
> because memory pressure is occurring is pathological behaviour.
> 
> Can you confirm which -rcX that behaviour starts in? e.g. between
> -rc4 and -rc5 there is this commit:
> 
> 172b06c32b94 mm: slowly shrink slabs with a relatively small number of
> objects
> 
> Which does change the way that the inode caches are reclaimed by
> forcably triggering reclaim for caches that would have previously
> been ignored. That's one of the "red flag" commits I noticed when
> first looking at the history between 4.18 and 4.19....

And now, added in 4.19.3:

 $ gl -n 1 5ebac3b957a9 -p
commit 5ebac3b957a91c921d2f1a7953caafca18aa6260
Author: Roman Gushchin <guro@fb.com>
Date:   Fri Nov 16 15:08:18 2018 -0800

    mm: don't reclaim inodes with many attached pages
    
    commit a76cf1a474d7dbcd9336b5f5afb0162baa142cf0 upstream.
    
    Spock reported that commit 172b06c32b94 ("mm: slowly shrink slabs with a
    relatively small number of objects") leads to a regression on his setup:
    periodically the majority of the pagecache is evicted without an obvious
    reason, while before the change the amount of free memory was balancing
    around the watermark.
    
    The reason behind is that the mentioned above change created some
    minimal background pressure on the inode cache.  The problem is that if
    an inode is considered to be reclaimed, all belonging pagecache page are
    stripped, no matter how many of them are there.  So, if a huge
    multi-gigabyte file is cached in the memory, and the goal is to reclaim
    only few slab objects (unused inodes), we still can eventually evict all
    gigabytes of the pagecache at once.
    
    The workload described by Spock has few large non-mapped files in the
    pagecache, so it's especially noticeable.
    
    To solve the problem let's postpone the reclaim of inodes, which have
    more than 1 attached page.  Let's wait until the pagecache pages will be
    evicted naturally by scanning the corresponding LRU lists, and only then
    reclaim the inode structure.
    
    Link: http://lkml.kernel.org/r/20181023164302.20436-1-guro@fb.com
    Signed-off-by: Roman Gushchin <guro@fb.com>
    Reported-by: Spock <dairinin@gmail.com>
    Tested-by: Spock <dairinin@gmail.com>
    Reviewed-by: Andrew Morton <akpm@linux-foundation.org>
    Cc: Michal Hocko <mhocko@kernel.org>
    Cc: Rik van Riel <riel@surriel.com>
    Cc: Randy Dunlap <rdunlap@infradead.org>
    Cc: <stable@vger.kernel.org>    [4.19.x]
    Signed-off-by: Andrew Morton <akpm@linux-foundation.org>
    Signed-off-by: Linus Torvalds <torvalds@linux-foundation.org>
    Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>

SO, basically, I was right - the slab shrinking change in 4.18-rc5
caused the page cache to saw tooth like you reported, and there is a
"fix" for it in 4.19.3.

What does that "fix" do? It stops inode reclaim from inodes with
cached pages attached.

diff --git a/fs/inode.c b/fs/inode.c
index 42f6d25f32a5..65ae154df760 100644
--- a/fs/inode.c
+++ b/fs/inode.c
@@ -730,8 +730,11 @@ static enum lru_status inode_lru_isolate(struct list_head *item,
                return LRU_REMOVED;
        }
 
-       /* recently referenced inodes get one more pass */
-       if (inode->i_state & I_REFERENCED) {
+       /*
+        * Recently referenced inodes and inodes with many attached pages
+        * get one more pass.
+        */
+       if (inode->i_state & I_REFERENCED || inode->i_data.nrpages > 1) {
                inode->i_state &= ~I_REFERENCED;
                spin_unlock(&inode->i_lock);
                return LRU_ROTATE;

Basically, what happened before this patch was that when an inode
was aged out of the cache due to the shrinker cycling over it, it's
page cache was reclaimed and then the inode reclaimed.

Now, the inode does not get reclaimed and the page cache is not
reclaimed. When you have lots of large files in your workload, that
means the inode cache turning over can no longer reclaim those
inodes, and so the inode can only be reclaimed after memory reclaim
has reclaimed the entire page cache for an inode.

That's a /massive/ change in behaviour, and it means that clean
inodes with cached pages attached can no longer be reclaimed by the
inode cache shrinker. Which will drive the inode cache shrinker into
trying to reclaim dirty inodes.....

Can you revert the above patch and see if the problem goes away?

Cheers,

Dave.
Comment 17 Roger 2019-01-29 22:07:09 UTC
I suspected that commit as well...
I would love to try that revert. I have never done one so I'm not sure how to go about it. I'll have to read up a little.
Do I revert in 4.19.3 or the latest ?
Comment 18 Dave Chinner 2019-01-29 22:19:22 UTC
(In reply to Roger from comment #17)
> I suspected that commit as well...
> I would love to try that revert. I have never done one so I'm not sure how
> to go about it. I'll have to read up a little.
> Do I revert in 4.19.3 or the latest ?

Reverting in 4.19.3 and testing that would be ideal, though it would 
probably revert just fine in the lastest tree. If yuive been         
building from a git tree, then:                                      
                                                                     
$ git revert 5ebac3b957a9                                            

and rebuild is all you need to do (assuming it cleanly reverts).                 
                                                                     
If you've been building from a downloaded tarball, then you'll need to apply the revert yourself. I'll attach a revert patch, which you can apply via:

$ patch -p1 < revert.patch

and rebuild the kernel (assuming it applies cleanly - use --dry-run to test).

Or you can just manually change the code in an editor to set the code back to the original. i.e:

        /* recently referenced inodes get one more pass */
        if (inode->i_state & I_REFERENCED) {

-Dave.
Comment 19 Dave Chinner 2019-01-29 22:23:03 UTC
Created attachment 280859 [details]
revert patch
Comment 20 Roger 2019-01-29 22:39:21 UTC
I used my trusty old emacs and remove the second conditional in the if statement.
I'll have to use the console with 4.19.3 so it'll take approximately 16 + 10 min
before I'm back...
Comment 21 Roger 2019-01-29 23:03:21 UTC
Worked very well :) (compile took 3min 31s) 
I saw the same behaviour as I first noticed on rc5, sawtoothing buff/cache.
Comment 22 Dave Chinner 2019-01-29 23:28:36 UTC
On Tue, Jan 29, 2019 at 11:03:21PM +0000, bugzilla-daemon@bugzilla.kernel.org wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=202441
> 
> --- Comment #21 from Roger (rogan6710@gmail.com) ---
> Worked very well :) (compile took 3min 31s) 
> I saw the same behaviour as I first noticed on rc5, sawtoothing buff/cache.

Ok, thanks for confirming. I doubt there's going to be a fast fix
for this, though, but we'll see how it goes.

Cheers,

Dave.
Comment 23 Roger 2019-01-29 23:35:49 UTC
Me and my kernel compiling workhorse says thank you very much :)
Let me know if any ideas pop up and if I should try them.
Comment 24 Roger 2019-01-30 10:50:12 UTC
A few moments ago, a piece of the puzzle fell into place.

The problem persists. All this revert did, was to make the issue granularity dependent from what I gather. While redoing the test with all those source trees I used to compile the kernels, the same exact problem came back.

The earlier tests were done using mostly multi GB files.

After some more testing I found out that rc4 is completely problem free in this regard, but rc5 is definately not, so the real culprit was probably introduced in rc5. 

After applying our inode.c revert on 4.19.18, it shows the same behaviour as rc5. I can test on intermediate versions as well if necessary, as I still have them all compiled and ready.
Comment 25 Roger 2019-01-30 12:00:15 UTC
If I had been less strict in my testing I probably would have discovered that the problem was present earlier than 4.19.3. Mr Gushins commit made it more visible.

I'm going back to work after two days off, so I might not be able to respond inside your working hours, but I'll keep checking in on this as I get a chance.
Comment 26 Roger 2019-02-01 21:59:59 UTC
I have tried both your suggested reverts on a customized non-modular server oriented 5.0.0-rc3, and subjected the poor machine to a brutal test: 8 "simultaneous" defonfig compiles, a sort of load balancing test I do to evaluate io and cpu, on a xfs formatted hdd, while copying GB sized files to a btrfs formatted hdd ditto and my, by now, significant collection of kernel source trees to yet another ext4 formatted hdd. All this while watching a (very boring) youtube HD video and writing this. All working perfectly with a very responsive ui, while buff/cache is kept at 20-23 Gb, and almost no cpu idle.

I have also done the earlier tests with very good results :)
5.5.0-rc3 locked up completely, and I had do do a "Norwegian reboot", when I tried loading it like that, earlier, without the reverts.

From my point of view, they entirely solve this particular problem.
I'll continue testing the reverts on other versions as well.

All kernel compile processes finished with a delta t < 5o seconds, good :)
(now try that on jfs ;))
Comment 27 Roger 2019-02-03 08:12:13 UTC
I've done testing on distribution standard 4.19.19 "generic" kernel with the reverts applied, all seems ok again :)

Note You need to log in before you can comment on or make changes to this bug.