2015-11-18 06:57:24

by kernel test robot

[permalink] [raw]
Subject: [lkp] [xfs] a45086e27d: -100.0% xfstests.xfs.033.seconds

FYI, we noticed the below changes on

https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master
commit a45086e27dfa21a4b39134f7505c8f60a3ecdec4 ("xfs: validate metadata LSNs against log on v5 superblocks")

2015-11-17 05:11:29 export TEST_DIR=/fs/sdd1
2015-11-17 05:11:29 export TEST_DEV=/dev/sdd1
2015-11-17 05:11:29 export FSTYP=xfs
2015-11-17 05:11:29 export SCRATCH_MNT=/fs/scratch
2015-11-17 05:11:29 mkdir /fs/scratch -p
2015-11-17 05:11:29 export SCRATCH_DEV=/dev/sdg1
2015-11-17 05:11:29 export SCRATCH_LOGDEV=/dev/sdh1
2015-11-17 05:11:29 ./check xfs/004 xfs/010 xfs/011 xfs/013 xfs/017 xfs/020 xfs/026 xfs/027 xfs/028 xfs/031 xfs/032 xfs/033 xfs/041 xfs/042 xfs/046 xfs/047 xfs/049 xfs/050 xfs/054 xfs/056 xfs/059 xfs/060 xfs/061 xfs/063 xfs/064 xfs/065 xfs/066 xfs/068 xfs/073 xfs/076
FSTYP -- xfs (non-debug)
PLATFORM -- Linux/x86_64 lkp-ws02 4.3.0-rc2-00002-ga45086e
MKFS_OPTIONS -- -f -bsize=4096 /dev/sdg1
MOUNT_OPTIONS -- /dev/sdg1 /fs/scratch

xfs/004 3s
xfs/010 13s
xfs/011 19s
xfs/013 318s
xfs/017 15s
xfs/020 82s
xfs/026 14s
xfs/027 15s
xfs/028 25s
xfs/031 58s
xfs/032 14s
xfs/033 - output mismatch (see /lkp/benchmarks/xfstests/results//xfs/033.out.bad)
--- tests/xfs/033.out 2015-11-12 16:56:51.000000000 +0800
+++ /lkp/benchmarks/xfstests/results//xfs/033.out.bad 2015-11-17 05:21:38.091589526 +0800
@@ -38,7 +38,19 @@
Phase 7 - verify and correct link counts...
resetting inode INO nlinks from 1 to 2
done
+mount: wrong fs type, bad option, bad superblock on /dev/sdg1,
+ missing codepage or helper program, or other error
+
+ In some cases useful info is found in syslog - try
...
(Run 'diff -u tests/xfs/033.out /lkp/benchmarks/xfstests/results//xfs/033.out.bad' to see the entire diff)
xfs/041 18s
xfs/042 14s
xfs/046 15s
xfs/047 25s
xfs/049 48s
xfs/050 23s
xfs/054 15s
xfs/056 14s
xfs/059 18s
xfs/060 16s
xfs/061 14s
xfs/063 14s
xfs/064 228s
xfs/065 35s
xfs/066 28s
xfs/068 25s
xfs/073 16s
xfs/076 53s
Ran: xfs/004 xfs/010 xfs/011 xfs/013 xfs/017 xfs/020 xfs/026 xfs/027 xfs/028 xfs/031 xfs/032 xfs/033 xfs/041 xfs/042 xfs/046 xfs/047 xfs/049 xfs/050 xfs/054 xfs/056 xfs/059 xfs/060 xfs/061 xfs/063 xfs/064 xfs/065 xfs/066 xfs/068 xfs/073 xfs/076
Failures: xfs/033
Failed 1 of 30 tests


=========================================================================================
tbox_group/testcase/rootfs/kconfig/compiler/disk/fs/test:
lkp-ws02/xfstests/debian-x86_64-2015-02-07.cgz/x86_64-rhel/gcc-4.9/4HDD/xfs/xfs-mid1

commit:
b7cdc66be54b64daef593894d12ecc405f117829
a45086e27dfa21a4b39134f7505c8f60a3ecdec4

b7cdc66be54b64da a45086e27dfa21a4b39134f750
---------------- --------------------------
fail:runs %reproduction fail:runs
| | |
:4 100% 4:4 last_state.xfstests.exit_code.1
:4 100% 4:4 xfstests.nr_fail
:4 100% 4:4 xfstests.xfs.033.fail
:4 25% 1:4 kmsg.XFS(loop0):Filesystem_has_duplicate_UUID#-#-#f7b-b747-f26a6b2b589b-can't_mount
:4 25% 1:4 kmsg.XFS(loop0):Filesystem_has_duplicate_UUID#-#c55-#af8-a93b-#c6382174ba-can't_mount
1:4 -25% :4 kmsg.XFS(loop0):Filesystem_has_duplicate_UUID#-#d5c-#dd8-#c4c-#b9758dd7946-can't_mount
1:4 -25% :4 kmsg.XFS(loop0):Filesystem_has_duplicate_UUID#-#d8b-#bd0-bd22-be703a050d73-can't_mount
:4 25% 1:4 kmsg.XFS(loop0):Filesystem_has_duplicate_UUID#-#e49-#-#f14-c1f5b7a39914-can't_mount
:4 25% 1:4 kmsg.XFS(loop0):Filesystem_has_duplicate_UUID#-#f2c-#ba-#-#a8309204098-can't_mount
1:4 -25% :4 kmsg.XFS(loop0):Filesystem_has_duplicate_UUID#-#f88-#-a30c-f7972224a2c2-can't_mount
1:4 -25% :4 kmsg.XFS(loop0):Filesystem_has_duplicate_UUID#-a0f8-#-b678-a0e21fca1aea-can't_mount
:4 100% 4:4 kmsg.XFS(sdg1):log_mount/recovery_failed:error

lkp-ws02: Westmere-EP
Memory: 16G

To reproduce:

git clone git://git.kernel.org/pub/scm/linux/kernel/git/wfg/lkp-tests.git
cd lkp-tests
bin/lkp install job.yaml # job file is attached in this email
bin/lkp run job.yaml


Disclaimer:
Results have been estimated based on internal Intel analysis and are provided
for informational purposes only. Any difference in system hardware or software
design or configuration may affect actual performance.


Thanks,
Ying Huang


Attachments:
(No filename) (4.60 kB)
job.yaml (2.96 kB)
reproduce (729.00 B)
xfstests (2.07 kB)
Download all attachments

2015-11-18 14:32:10

by Brian Foster

[permalink] [raw]
Subject: Re: [lkp] [xfs] a45086e27d: -100.0% xfstests.xfs.033.seconds

cc linux-xfs

On Wed, Nov 18, 2015 at 02:57:21PM +0800, kernel test robot wrote:
> FYI, we noticed the below changes on
>
> https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master
> commit a45086e27dfa21a4b39134f7505c8f60a3ecdec4 ("xfs: validate metadata LSNs against log on v5 superblocks")
>
> 2015-11-17 05:11:29 export TEST_DIR=/fs/sdd1
> 2015-11-17 05:11:29 export TEST_DEV=/dev/sdd1
> 2015-11-17 05:11:29 export FSTYP=xfs
> 2015-11-17 05:11:29 export SCRATCH_MNT=/fs/scratch
> 2015-11-17 05:11:29 mkdir /fs/scratch -p
> 2015-11-17 05:11:29 export SCRATCH_DEV=/dev/sdg1
> 2015-11-17 05:11:29 export SCRATCH_LOGDEV=/dev/sdh1
> 2015-11-17 05:11:29 ./check xfs/004 xfs/010 xfs/011 xfs/013 xfs/017 xfs/020 xfs/026 xfs/027 xfs/028 xfs/031 xfs/032 xfs/033 xfs/041 xfs/042 xfs/046 xfs/047 xfs/049 xfs/050 xfs/054 xfs/056 xfs/059 xfs/060 xfs/061 xfs/063 xfs/064 xfs/065 xfs/066 xfs/068 xfs/073 xfs/076
> FSTYP -- xfs (non-debug)
> PLATFORM -- Linux/x86_64 lkp-ws02 4.3.0-rc2-00002-ga45086e
> MKFS_OPTIONS -- -f -bsize=4096 /dev/sdg1
> MOUNT_OPTIONS -- /dev/sdg1 /fs/scratch
>
> xfs/004 3s
> xfs/010 13s
> xfs/011 19s
> xfs/013 318s
> xfs/017 15s
> xfs/020 82s
> xfs/026 14s
> xfs/027 15s
> xfs/028 25s
> xfs/031 58s
> xfs/032 14s
> xfs/033 - output mismatch (see /lkp/benchmarks/xfstests/results//xfs/033.out.bad)
> --- tests/xfs/033.out 2015-11-12 16:56:51.000000000 +0800
> +++ /lkp/benchmarks/xfstests/results//xfs/033.out.bad 2015-11-17 05:21:38.091589526 +0800
> @@ -38,7 +38,19 @@
> Phase 7 - verify and correct link counts...
> resetting inode INO nlinks from 1 to 2
> done
> +mount: wrong fs type, bad option, bad superblock on /dev/sdg1,
> + missing codepage or helper program, or other error
> +
> + In some cases useful info is found in syslog - try
> ...
> (Run 'diff -u tests/xfs/033.out /lkp/benchmarks/xfstests/results//xfs/033.out.bad' to see the entire diff)

I reproduced this running xfs/033 directly on a 4.3.0-rc2+ kernel
(linux-xfs tree) and xfsprogs-3.2.2 from fedora. The problem here is
that the mount complains about an invalid metadata LSN. Via dmesg:

...
XFS (dm-3): Mounting V5 Filesystem
XFS (dm-3): Corruption warning: Metadata has LSN (1:16) ahead of current LSN (1:2). Please unmount and run xfs_repair (>= v4.3) to resolve.
XFS (dm-3): log mount/recovery failed: error -22
XFS (dm-3): log mount failed
...

This occurs because older versions of xfs_repair unconditionally zero
out the log, which can lead to corruption after a crash on v5 superblock
(-m crc=1) filesystems. Therefore, the invalid log state is detected in
the kernel as of the commit referenced above and ultimately fixed in
xfsprogs v4.3. In other words, XFS on a v4.4 kernel requires xfsprogs
v4.3 or newer.

I'm not sure what the xfsprogs release status is (tot looks like it's at
4.3.0-rc2), but the fix is ultimately to upgrade to a supported
userspace.

Brian

> xfs/041 18s
> xfs/042 14s
> xfs/046 15s
> xfs/047 25s
> xfs/049 48s
> xfs/050 23s
> xfs/054 15s
> xfs/056 14s
> xfs/059 18s
> xfs/060 16s
> xfs/061 14s
> xfs/063 14s
> xfs/064 228s
> xfs/065 35s
> xfs/066 28s
> xfs/068 25s
> xfs/073 16s
> xfs/076 53s
> Ran: xfs/004 xfs/010 xfs/011 xfs/013 xfs/017 xfs/020 xfs/026 xfs/027 xfs/028 xfs/031 xfs/032 xfs/033 xfs/041 xfs/042 xfs/046 xfs/047 xfs/049 xfs/050 xfs/054 xfs/056 xfs/059 xfs/060 xfs/061 xfs/063 xfs/064 xfs/065 xfs/066 xfs/068 xfs/073 xfs/076
> Failures: xfs/033
> Failed 1 of 30 tests
>
>
> =========================================================================================
> tbox_group/testcase/rootfs/kconfig/compiler/disk/fs/test:
> lkp-ws02/xfstests/debian-x86_64-2015-02-07.cgz/x86_64-rhel/gcc-4.9/4HDD/xfs/xfs-mid1
>
> commit:
> b7cdc66be54b64daef593894d12ecc405f117829
> a45086e27dfa21a4b39134f7505c8f60a3ecdec4
>
> b7cdc66be54b64da a45086e27dfa21a4b39134f750
> ---------------- --------------------------
> fail:runs %reproduction fail:runs
> | | |
> :4 100% 4:4 last_state.xfstests.exit_code.1
> :4 100% 4:4 xfstests.nr_fail
> :4 100% 4:4 xfstests.xfs.033.fail
> :4 25% 1:4 kmsg.XFS(loop0):Filesystem_has_duplicate_UUID#-#-#f7b-b747-f26a6b2b589b-can't_mount
> :4 25% 1:4 kmsg.XFS(loop0):Filesystem_has_duplicate_UUID#-#c55-#af8-a93b-#c6382174ba-can't_mount
> 1:4 -25% :4 kmsg.XFS(loop0):Filesystem_has_duplicate_UUID#-#d5c-#dd8-#c4c-#b9758dd7946-can't_mount
> 1:4 -25% :4 kmsg.XFS(loop0):Filesystem_has_duplicate_UUID#-#d8b-#bd0-bd22-be703a050d73-can't_mount
> :4 25% 1:4 kmsg.XFS(loop0):Filesystem_has_duplicate_UUID#-#e49-#-#f14-c1f5b7a39914-can't_mount
> :4 25% 1:4 kmsg.XFS(loop0):Filesystem_has_duplicate_UUID#-#f2c-#ba-#-#a8309204098-can't_mount
> 1:4 -25% :4 kmsg.XFS(loop0):Filesystem_has_duplicate_UUID#-#f88-#-a30c-f7972224a2c2-can't_mount
> 1:4 -25% :4 kmsg.XFS(loop0):Filesystem_has_duplicate_UUID#-a0f8-#-b678-a0e21fca1aea-can't_mount
> :4 100% 4:4 kmsg.XFS(sdg1):log_mount/recovery_failed:error
>
> lkp-ws02: Westmere-EP
> Memory: 16G
>
> To reproduce:
>
> git clone git://git.kernel.org/pub/scm/linux/kernel/git/wfg/lkp-tests.git
> cd lkp-tests
> bin/lkp install job.yaml # job file is attached in this email
> bin/lkp run job.yaml
>
>
> Disclaimer:
> Results have been estimated based on internal Intel analysis and are provided
> for informational purposes only. Any difference in system hardware or software
> design or configuration may affect actual performance.
>
>
> Thanks,
> Ying Huang

> ---
> LKP_SERVER: inn
> LKP_CGI_PORT: 80
> LKP_CIFS_PORT: 139
> testcase: xfstests
> default-monitors:
> wait: activate-monitor
> kmsg:
> vmstat:
> interval: 10
> default-watchdogs:
> oom-killer:
> watchdog:
> commit: 96a2f2162deb97760a44ad8558e374342260cee6
> model: Westmere-EP
> memory: 16G
> nr_hdd_partitions: 11
> hdd_partitions: "/dev/disk/by-id/scsi-35000c500*-part1"
> swap_partitions:
> rootfs_partition: "/dev/disk/by-id/ata-WDC_WD1002FAEX-00Z3A0_WD-WCATR5408564-part3"
> cpufreq_governor:
> category: functional
> disk: 4HDD
> fs: xfs
> xfstests:
> test: xfs-mid1
> queue: cyclic
> testbox: lkp-ws02
> tbox_group: lkp-ws02
> kconfig: x86_64-rhel
> enqueue_time: 2015-11-14 09:35:40.999257430 +08:00
> id: 37df3a54bced8a69c8daf7c99bfff44d990622e7
> user: lkp
> compiler: gcc-4.9
> head_commit: 96a2f2162deb97760a44ad8558e374342260cee6
> base_commit: 6a13feb9c82803e2b815eca72fa7a9f5561d7861
> branch: linux-devel/devel-hourly-2015111410
> kernel: "/pkg/linux/x86_64-rhel/gcc-4.9/96a2f2162deb97760a44ad8558e374342260cee6/vmlinuz-4.3.0-bochs-virtio-gpu-wl-ath-16719-g96a2f21"
> rootfs: debian-x86_64-2015-02-07.cgz
> result_root: "/result/xfstests/4HDD-xfs-xfs-mid1/lkp-ws02/debian-x86_64-2015-02-07.cgz/x86_64-rhel/gcc-4.9/96a2f2162deb97760a44ad8558e374342260cee6/0"
> job_file: "/lkp/scheduled/lkp-ws02/cyclic_xfstests-4HDD-xfs-xfs-mid1-x86_64-rhel-CYCLIC_HEAD-96a2f2162deb97760a44ad8558e374342260cee6-20151114-75902-1fjjdep-0.yaml"
> dequeue_time: 2015-11-14 12:49:18.590161421 +08:00
> nr_cpu: "$(nproc)"
> max_uptime: 3600
> initrd: "/osimage/debian/debian-x86_64-2015-02-07.cgz"
> bootloader_append:
> - root=/dev/ram0
> - user=lkp
> - job=/lkp/scheduled/lkp-ws02/cyclic_xfstests-4HDD-xfs-xfs-mid1-x86_64-rhel-CYCLIC_HEAD-96a2f2162deb97760a44ad8558e374342260cee6-20151114-75902-1fjjdep-0.yaml
> - ARCH=x86_64
> - kconfig=x86_64-rhel
> - branch=linux-devel/devel-hourly-2015111410
> - commit=96a2f2162deb97760a44ad8558e374342260cee6
> - BOOT_IMAGE=/pkg/linux/x86_64-rhel/gcc-4.9/96a2f2162deb97760a44ad8558e374342260cee6/vmlinuz-4.3.0-bochs-virtio-gpu-wl-ath-16719-g96a2f21
> - max_uptime=3600
> - RESULT_ROOT=/result/xfstests/4HDD-xfs-xfs-mid1/lkp-ws02/debian-x86_64-2015-02-07.cgz/x86_64-rhel/gcc-4.9/96a2f2162deb97760a44ad8558e374342260cee6/0
> - LKP_SERVER=inn
> - |-
> ipmi_watchdog.start_now=1
>
> earlyprintk=ttyS0,115200 systemd.log_level=err
> debug apic=debug sysrq_always_enabled rcupdate.rcu_cpu_stall_timeout=100
> panic=-1 softlockup_panic=1 nmi_watchdog=panic oops=panic load_ramdisk=2 prompt_ramdisk=0
> console=ttyS0,115200 console=tty0 vga=normal
>
> rw
> lkp_initrd: "/lkp/lkp/lkp-x86_64.cgz"
> modules_initrd: "/pkg/linux/x86_64-rhel/gcc-4.9/96a2f2162deb97760a44ad8558e374342260cee6/modules.cgz"
> bm_initrd: "/osimage/deps/debian-x86_64-2015-02-07.cgz/lkp.cgz,/osimage/deps/debian-x86_64-2015-02-07.cgz/run-ipconfig.cgz,/osimage/deps/debian-x86_64-2015-02-07.cgz/fs.cgz,/osimage/deps/debian-x86_64-2015-02-07.cgz/xfstests.cgz,/lkp/benchmarks/xfstests.cgz"
> job_state: finished
> loadavg: 0.66 0.72 0.56 1/350 26465
> start_time: '1447476647'
> end_time: '1447477486'
> version: "/lkp/lkp/.src-20151113-180526"

> mkfs -t xfs /dev/sdd1
> mkfs -t xfs /dev/sdk1
> mkfs -t xfs /dev/sdg1
> mkfs -t xfs /dev/sdh1
> mount -t xfs -o nobarrier,inode64 /dev/sdd1 /fs/sdd1
> mount -t xfs -o nobarrier,inode64 /dev/sdh1 /fs/sdh1
> mount -t xfs -o nobarrier,inode64 /dev/sdk1 /fs/sdk1
> mount -t xfs -o nobarrier,inode64 /dev/sdg1 /fs/sdg1
> export TEST_DIR=/fs/sdd1
> export TEST_DEV=/dev/sdd1
> export FSTYP=xfs
> export SCRATCH_MNT=/fs/scratch
> mkdir /fs/scratch -p
> export SCRATCH_DEV=/dev/sdg1
> export SCRATCH_LOGDEV=/dev/sdh1
> ./check xfs/004 xfs/010 xfs/011 xfs/013 xfs/017 xfs/020 xfs/026 xfs/027 xfs/028 xfs/031 xfs/032 xfs/033 xfs/041 xfs/042 xfs/046 xfs/047 xfs/049 xfs/050 xfs/054 xfs/056 xfs/059 xfs/060 xfs/061 xfs/063 xfs/064 xfs/065 xfs/066 xfs/068 xfs/073 xfs/076