linux-kernel - [nfsd] ae3c57b5ca: last_state.soft

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [thread-next>] [day] [month] [year] [list]
Message-ID: <20201204082233.GC23474@xsang-OptiPlex-9020>
Date:   Fri, 4 Dec 2020 16:22:33 +0800
From:   kernel test robot <oliver.sang@...el.com>
To:     "J. Bruce Fields" <bfields@...hat.com>
Cc:     Chuck Lever <chuck.lever@...cle.com>,
        LKML <linux-kernel@...r.kernel.org>, lkp@...ts.01.org,
        lkp@...el.com
Subject: [nfsd]  ae3c57b5ca: last_state.soft_timeout


Greeting,

FYI, we noticed the following commit (built with gcc-9):

commit: ae3c57b5ca47665dc3416447a5534a9796096d86 ("nfsd: Cache R, RW, and W opens separately")
https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master


in testcase: fsmark
version: fsmark-x86_64-3.3-1_20201110
with following parameters:

	iterations: 1x
	nr_threads: 32t
	disk: 1HDD
	fs: f2fs
	fs2: nfsv4
	filesize: 16MB
	test_size: 60G
	sync_method: fsyncBeforeClose
	nr_directories: 16d
	nr_files_per_directory: 256fpd
	cpufreq_governor: performance
	ucode: 0x5002f01

test-description: The fsmark is a file system benchmark to test synchronous write workloads, for example, mail servers workload.
test-url: https://sourceforge.net/projects/fsmark/


on test machine: 96 threads Intel(R) Xeon(R) Gold 6252 CPU @ 2.10GHz with 512G memory

caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):




If you fix the issue, kindly add following tag
Reported-by: kernel test robot <oliver.sang@...el.com>

2020-12-01 07:16:05 fs_mark -d /nfs/sda1/1 -d /nfs/sda1/2 -d /nfs/sda1/3 -d /nfs/sda1/4 -d /nfs/sda1/5 -d /nfs/sda1/6 -d /nfs/sda1/7 -d /nfs/sda1/8 -d /nfs/sda1/9 -d /nfs/sda1/10 -d /nfs/sda1/11 -d /nfs/sda1/12 -d /nfs/sda1/13 -d /nfs/sda1/14 -d /nfs/sda1/15 -d /nfs/sda1/16 -d /nfs/sda1/17 -d /nfs/sda1/18 -d /nfs/sda1/19 -d /nfs/sda1/20 -d /nfs/sda1/21 -d /nfs/sda1/22 -d /nfs/sda1/23 -d /nfs/sda1/24 -d /nfs/sda1/25 -d /nfs/sda1/26 -d /nfs/sda1/27 -d /nfs/sda1/28 -d /nfs/sda1/29 -d /nfs/sda1/30 -d /nfs/sda1/31 -d /nfs/sda1/32 -D 16 -N 256 -n 120 -L 1 -S 1 -s 16777216

#  fs_mark  -d  /nfs/sda1/1  -d  /nfs/sda1/2  -d  /nfs/sda1/3  -d  /nfs/sda1/4  -d  /nfs/sda1/5  -d  /nfs/sda1/6  -d  /nfs/sda1/7  -d  /nfs/sda1/8  -d  /nfs/sda1/9  -d  /nfs/sda1/10  -d  /nfs/sda1/11  -d  /nfs/sda1/12  -d  /nfs/sda1/13  -d  /nfs/sda1/14  -d  /nfs/sda1/15  -d  /nfs/sda1/16  -d  /nfs/sda1/17  -d  /nfs/sda1/18  -d  /nfs/sda1/19  -d  /nfs/sda1/20  -d  /nfs/sda1/21  -d  /nfs/sda1/22  -d  /nfs/sda1/23  -d  /nfs/sda1/24  -d  /nfs/sda1/25  -d  /nfs/sda1/26  -d  /nfs/sda1/27  -d  /nfs/sda1/28  -d  /nfs/sda1/29  -d  /nfs/sda1/30  -d  /nfs/sda1/31  -d  /nfs/sda1/32  -D  16  -N  256  -n  120  -L  1  -S  1  -s  16777216 
#	Version 3.3, 32 thread(s) starting at Tue Dec  1 07:16:05 2020
#	Sync method: INBAND FSYNC: fsync() per file in write loop.
#	Directories:  Round Robin between directories across 16 subdirectories with 256 files per subdirectory.
#	File names: 40 bytes long, (16 initial bytes of time stamp with 24 random bytes at end of name)
#	Files info: size 16777216 bytes, written with an IO size of 16384 bytes per write
#	App overhead is time in microseconds spent in the test not doing file writing related system calls.

FSUse%        Count         Size    Files/sec     App Overhead


in attached dmesg
[ 2646.633157] nfs: server localhost not responding, still trying
[ 2646.633196] nfs: server localhost not responding, still trying
[ 2646.633199] nfs: server localhost not responding, still trying
[ 2646.633209] nfs: server localhost not responding, still trying
[ 2646.633212] nfs: server localhost not responding, still trying
[ 2646.633213] nfs: server localhost not responding, still trying
[ 2646.633229] nfs: server localhost not responding, still trying
[ 2646.633230] nfs: server localhost not responding, still trying
[ 2646.633231] nfs: server localhost not responding, still trying
[ 2646.633242] nfs: server localhost not responding, still trying
[ 2646.649307] nfs: server localhost OK
[ 2646.649497] nfs: server localhost OK
[ 2646.649507] nfs: server localhost OK
[ 2646.649571] nfs: server localhost OK
[ 2646.649590] nfs: server localhost OK
[ 2646.649652] nfs: server localhost OK
[ 2646.649663] nfs: server localhost OK
[ 2646.649673] nfs: server localhost OK
[ 2646.649734] nfs: server localhost OK
[ 2646.650546] nfs: server localhost OK
[ 3639.661587] Wed Dec  2 22:15:18 UTC 2020 detected soft_timeout
[ 3639.661590]
[ 3639.704756] Terminated
[ 3639.704758]
[ 3639.705909] kill 2538 /usr/bin/time -v -o /tmp/lkp/fsmark.time /lkp/lkp/src/tests/fsmark



To reproduce:

        git clone https://github.com/intel/lkp-tests.git
        cd lkp-tests
        bin/lkp install job.yaml  # job file is attached in this email
        bin/lkp run     job.yaml



Thanks,
Oliver Sang


View attachment "config-5.9.0-rc5-00017-gae3c57b5ca4766" of type "text/plain" (169129 bytes)

View attachment "job-script" of type "text/plain" (8490 bytes)

Download attachment "dmesg.xz" of type "application/x-xz" (32244 bytes)

View attachment "fsmark" of type "text/plain" (1787 bytes)

View attachment "job.yaml" of type "text/plain" (5946 bytes)

View attachment "reproduce" of type "text/plain" (1506 bytes)