Ubuntu
linux package

ubuntu_vfat_stress failed again with P8/P9 Bionic

Bug #1805778 reported by Po-Hsu Lin on 2018-11-29

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	ubuntu-kernel-tests	Fix Released	High	Colin Ian King
	linux (Ubuntu)	Won't Fix	Undecided	Unassigned

Bug Description

This issue just like bug 1801907, but this time it's passed with P8 "modoc", failed with P8 "entei" and P9 "baltar"

I haven't run them directly, this is the result when testing with the whole test suite.

06:21:04 INFO | START ubuntu_vfat_stress.vfat-stress ubuntu_vfat_stress.vfat-stress timestamp=1543472464 timeout=18000 localtime=Nov 29 06:21:04
06:21:04 DEBUG| Persistent state client._record_indent now set to 2
06:21:04 DEBUG| Persistent state client.unexpected_reboot now set to ('ubuntu_vfat_stress.vfat-stress', 'ubuntu_vfat_stress.vfat-stress')
06:21:04 DEBUG| Waiting for pid 56149 for 18000 seconds
06:21:04 DEBUG| Running 'LOG=/tmp/vfat-falure.log STRESS_NG=/home/ubuntu/autotest/client/tmp/ubuntu_vfat_stress/src/stress-ng/stress-ng DURATION=10s bash -c /home/ubuntu/autotest/client/tests/ubuntu_vfat_stress/ubuntu_vfat_stress.sh /home/ubuntu/autotest/client/tmp/ubuntu_vfat_stress/src 2>&1'
06:21:04 DEBUG| [stdout] Testing: --verify --times --metrics-brief --syslog --keep-name -t 10s --hdd 2 --hdd-opts sync,wr-rnd,rd-rnd,fadv-willneed,fadv-rnd --lockf 2 --seek 2 --aio 2 --aio-requests 32 --dentry 2 --dir 2 --dentry-order stride --fallocate 2 --fstat 2 --dentries 100 --lease 2 --open 2 --rename 2 --hdd-bytes 4M --fallocate-bytes 4M --chdir 2 --rename 2 --hdd-write-size 512
06:21:04 DEBUG| [stdout] Mounting tmpfs /mnt/vfat-test-56154
06:21:05 DEBUG| [stdout] Created loop image /mnt/vfat-test-56154/vfat-loop-data
06:21:05 DEBUG| [stdout] mkfs.fat 4.1 (2017-01-24)
06:21:06 DEBUG| [stdout]
06:21:06 DEBUG| [stdout] --------------------------------------------------------------------------------
06:21:06 DEBUG| [stdout] VFAT options: allow_utime=20
06:21:06 DEBUG| [stdout] Stress test: /home/ubuntu/autotest/client/tmp/ubuntu_vfat_stress/src/stress-ng/stress-ng --verify --times --metrics-brief --syslog --keep-name -t 10s --hdd 2 --hdd-opts sync,wr-rnd,rd-rnd,fadv-willneed,fadv-rnd --lockf 2 --seek 2 --aio 2 --aio-requests 32 --dentry 2 --dir 2 --dentry-order stride --fallocate 2 --fstat 2 --dentries 100 --lease 2 --open 2 --rename 2 --hdd-bytes 4M --fallocate-bytes 4M --chdir 2 --rename 2 --hdd-write-size 512
06:21:06 DEBUG| [stdout] VFAT_IMAGE path: /mnt/vfat-test-56154
06:21:06 DEBUG| [stdout] Mount point: /mnt/vfat-test-56154
06:21:06 DEBUG| [stdout] Date: Thu Nov 29 06:21:06 UTC 2018
06:21:06 DEBUG| [stdout] Host: baltar
06:21:06 DEBUG| [stdout] Kernel: 4.15.0-42-generic #45-Ubuntu SMP Thu Nov 15 19:29:37 UTC 2018
06:21:06 DEBUG| [stdout] Machine: baltar ppc64le ppc64le
06:21:06 DEBUG| [stdout] CPUs online: 40
06:21:06 DEBUG| [stdout] CPUs total: 160
06:21:06 DEBUG| [stdout] Page size: 65536
06:21:06 DEBUG| [stdout] Pages avail: 1935143
06:21:06 DEBUG| [stdout] Pages total: 2089666
06:21:06 DEBUG| [stdout] --------------------------------------------------------------------------------
06:21:06 DEBUG| [stdout]
06:21:06 DEBUG| [stdout]
06:21:06 DEBUG| [stdout] Started, PID 56225
06:23:13 DEBUG| [stdout] Timed out waiting for stress-ng to finish
06:23:13 DEBUG| [stdout] Forcefully killing, PID 56225 (after 121 seconds)
06:23:23 DEBUG| [stdout] Found kernel warning and/or call trace:
06:23:23 DEBUG| [stdout]
06:23:23 DEBUG| [stdout] [ 4940.791800] Testing: --verify --times --metrics-brief --syslog --keep-name -t 10s --hdd 2 --hdd-opts sync,wr-rnd,rd-rnd,fadv-willneed,fadv-rnd --lockf 2 --seek 2 --aio 2 --aio-requests 32 --dentry 2 --dir 2 --dentry-order stride --fallocate 2 --fstat 2 --dentries 100 --lease 2 --open 2 --rename 2 --hdd-bytes 4M --fallocate-bytes 4M --chdir 2 --rename 2 --hdd-write-size 512
06:23:23 DEBUG| [stdout] [ 4941.855398] Created loop image /mnt/vfat-test-56154/vfat-loop-data
06:23:23 DEBUG| [stdout] [ 4942.232934] ubuntu_vfat_str (56154): drop_caches: 1
06:23:23 DEBUG| [stdout] [ 4942.593708] ubuntu_vfat_str (56154): drop_caches: 2
06:23:23 DEBUG| [stdout] [ 4942.597717] ubuntu_vfat_str (56154): drop_caches: 3
06:23:23 DEBUG| [stdout] [ 4943.125332] VFAT options: allow_utime=20
06:23:23 DEBUG| [stdout] [ 4943.125392] Stress test: /home/ubuntu/autotest/client/tmp/ubuntu_vfat_stress/src/stress-ng/stress-ng --verify --times --metrics-brief --syslog --keep-name -t 10s --hdd 2 --hdd-opts sync,wr-rnd,rd-rnd,fadv-willneed,fadv-rnd --lockf 2 --seek 2 --aio 2 --aio-requests 32 --dentry 2 --dir 2 --dentry-order stride --fallocate 2 --fstat 2 --dentries 100 --lease 2 --open 2 --rename 2 --hdd-bytes 4M --fallocate-bytes 4M --chdir 2 --rename 2 --hdd-write-size 512
06:23:23 DEBUG| [stdout] [ 4943.125420] Mount point: /mnt/vfat-test-56154
06:23:23 DEBUG| [stdout] [ 4943.125979] Started, PID 56225
06:23:23 DEBUG| [stdout] [ 5069.761998] Timed out waiting for stress-ng to finish
06:23:23 DEBUG| [stdout] [ 5069.762077] Forcefully killing, PID 56225 (after 121 seconds)
06:23:23 DEBUG| [stdout] [ 5078.885169] INFO: task kworker/u322:2:56189 blocked for more than 120 seconds.
06:23:23 DEBUG| [stdout] [ 5078.885238] Not tainted 4.15.0-42-generic #45-Ubuntu
06:23:23 DEBUG| [stdout] [ 5078.885274] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
06:23:23 DEBUG| [stdout] [ 5078.885327] kworker/u322:2 D 0 56189 2 0x00000800
06:23:23 DEBUG| [stdout] [ 5078.885338] Workqueue: writeback wb_workfn (flush-7:0)
06:23:23 DEBUG| [stdout] [ 5078.885340] Call Trace:
06:23:23 DEBUG| [stdout] [ 5078.885347] [c000200e38f7aaf0] [c000000000044c70] doorbell_exception+0xb0/0xe0 (unreliable)
06:23:23 DEBUG| [stdout] [ 5078.885352] [c000200e38f7acc0] [c00000000001c1d0] __switch_to+0x2a0/0x4d0
06:23:23 DEBUG| [stdout] [ 5078.885356] [c000200e38f7ad20] [c000000000cfdb84] __schedule+0x2a4/0xaf0
06:23:23 DEBUG| [stdout] [ 5078.885359] [c000200e38f7adf0] [c000000000cfe410] schedule+0x40/0xc0
06:23:23 DEBUG| [stdout] [ 5078.885362] [c000200e38f7ae10] [c000000000152e7c] io_schedule+0x2c/0x50
06:23:23 DEBUG| [stdout] [ 5078.885366] [c000200e38f7ae40] [c0000000006d20c4] wbt_wait+0x484/0x4e0
06:23:23 DEBUG| [stdout] [ 5078.885369] [c000200e38f7aee0] [c000000000699134] blk_mq_make_request+0x104/0x6e0
06:23:23 DEBUG| [stdout] [ 5078.885373] [c000200e38f7af80] [c000000000686cf4] generic_make_request+0x124/0x380
06:23:23 DEBUG| [stdout] [ 5078.885376] [c000200e38f7aff0] [c00000000068700c] submit_bio+0xbc/0x1d0
06:23:23 DEBUG| [stdout] [ 5078.885380] [c000200e38f7b0a0] [c00000000042de2c] submit_bh_wbc+0x1dc/0x240
06:23:23 DEBUG| [stdout] [ 5078.885383] [c000200e38f7b0f0] [c00000000042e108] __block_write_full_page+0x278/0x570
06:23:23 DEBUG| [stdout] [ 5078.885386] [c000200e38f7b190] [c00000000054af2c] fat_writepage+0x2c/0x40
06:23:23 DEBUG| [stdout] [ 5078.885389] [c000200e38f7b1b0] [c00000000043bdf0] __mpage_writepage+0x170/0x7b0
06:23:23 DEBUG| [stdout] [ 5078.885392] [c000200e38f7b6e0] [c0000000002f2d9c] write_cache_pages+0x25c/0x590
06:23:23 DEBUG| [stdout] [ 5078.885395] [c000200e38f7b820] [c00000000043bac8] mpage_writepages+0x78/0x150
06:23:23 DEBUG| [stdout] [ 5078.885397] [c000200e38f7b8b0] [c00000000054aea8] fat_writepages+0x28/0x40
06:23:23 DEBUG| [stdout] [ 5078.885400] [c000200e38f7b8d0] [c0000000002f5f1c] do_writepages+0x4c/0x130
06:23:23 DEBUG| [stdout] [ 5078.885403] [c000200e38f7b940] [c00000000041eff0] __writeback_single_inode+0x70/0x570
06:23:23 DEBUG| [stdout] [ 5078.885405] [c000200e38f7b9a0] [c00000000041fb8c] writeback_sb_inodes+0x26c/0x5d0
06:23:23 DEBUG| [stdout] [ 5078.885407] [c000200e38f7bab0] [c00000000042024c] wb_writeback+0x13c/0x460
06:23:23 DEBUG| [stdout] [ 5078.885410] [c000200e38f7bb80] [c000000000420f20] wb_workfn+0x100/0x5e0
06:23:23 DEBUG| [stdout] [ 5078.885414] [c000200e38f7bc90] [c000000000134bd8] process_one_work+0x298/0x5a0
06:23:23 DEBUG| [stdout] [ 5078.885416] [c000200e38f7bd20] [c000000000134f78] worker_thread+0x98/0x630
06:23:23 DEBUG| [stdout] [ 5078.885419] [c000200e38f7bdc0] [c00000000013db48] kthread+0x1a8/0x1b0
06:23:23 DEBUG| [stdout] [ 5078.885423] [c000200e38f7be30] [c00000000000b658] ret_from_kernel_thread+0x5c/0x84
06:23:23 DEBUG| [stdout] [ 5078.885426] INFO: task stress-ng:56241 blocked for more than 120 seconds.
06:23:23 DEBUG| [stdout] [ 5078.885470] Not tainted 4.15.0-42-generic #45-Ubuntu
06:23:23 DEBUG| [stdout] [ 5078.885505] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
06:23:23 DEBUG| [stdout] [ 5078.885558] stress-ng D 0 56241 1 0x00040002
06:23:23 DEBUG| [stdout] [ 5078.885560] Call Trace:
06:23:23 DEBUG| [stdout] [ 5078.885564] [c000000d4743f5b0] [c000000d4743f600] 0xc000000d4743f600 (unreliable)
06:23:23 DEBUG| [stdout] [ 5078.885568] [c000000d4743f780] [c00000000001c1d0] __switch_to+0x2a0/0x4d0
06:23:23 DEBUG| [stdout] [ 5078.885571] [c000000d4743f7e0] [c000000000cfdb84] __schedule+0x2a4/0xaf0
06:23:23 DEBUG| [stdout] [ 5078.885574] [c000000d4743f8b0] [c000000000cfe410] schedule+0x40/0xc0
06:23:23 DEBUG| [stdout] [ 5078.885577] [c000000d4743f8d0] [c000000000152e7c] io_schedule+0x2c/0x50
06:23:23 DEBUG| [stdout] [ 5078.885581] [c000000d4743f900] [c0000000002dc6ec] __lock_page+0x14c/0x1c0
06:23:23 DEBUG| [stdout] [ 5078.885584] [c000000d4743f9a0] [c0000000002de7bc] pagecache_get_page+0x2ac/0x450
06:23:23 DEBUG| [stdout] [ 5078.885587] [c000000d4743fa00] [c0000000002de994] grab_cache_page_write_begin+0x34/0x70
06:23:23 DEBUG| [stdout] [ 5078.885589] [c000000d4743fa30] [c00000000042f65c] block_write_begin+0x4c/0x170
06:23:23 DEBUG| [stdout] [ 5078.885592] [c000000d4743fa80] [c00000000042fa0c] cont_write_begin+0x28c/0x3a0
06:23:23 DEBUG| [stdout] [ 5078.885594] [c000000d4743fb40] [c00000000054adc8] fat_write_begin+0x58/0xc0
06:23:23 DEBUG| [stdout] [ 5078.885597] [c000000d4743fbd0] [c0000000002dde1c] generic_perform_write+0xec/0x270
06:23:23 DEBUG| [stdout] [ 5078.885601] [c000000d4743fc60] [c0000000002e2450] __generic_file_write_iter+0x250/0x2a0
06:23:23 DEBUG| [stdout] [ 5078.885604] [c000000d4743fcc0] [c0000000002e26ac] generic_file_write_iter+0x20c/0x2e0
06:23:23 DEBUG| [stdout] [ 5078.885608] [c000000d4743fd00] [c0000000003d2674] new_sync_write+0x104/0x160
06:23:23 DEBUG| [stdout] [ 5078.885610] [c000000d4743fd90] [c0000000003d5db8] vfs_write+0xd8/0x220
06:23:23 DEBUG| [stdout] [ 5078.885613] [c000000d4743fde0] [c0000000003d60d8] SyS_write+0x68/0x110
06:23:23 DEBUG| [stdout] [ 5078.885616] [c000000d4743fe30] [c00000000000b284] system_call+0x58/0x6c
06:23:23 DEBUG| [stdout] [ 5078.885618] INFO: task stress-ng:56243 blocked for more than 120 seconds.
06:23:23 DEBUG| [stdout] [ 5078.885677] Not tainted 4.15.0-42-generic #45-Ubuntu
06:23:23 DEBUG| [stdout] [ 5078.885713] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
06:23:23 DEBUG| [stdout] [ 5078.885765] stress-ng D 0 56243 1 0x00040002

ProblemType: Bug
DistroRelease: Ubuntu 18.04
Package: linux-image-4.15.0-42-generic 4.15.0-42.45
ProcVersionSignature: Ubuntu 4.15.0-42.45-generic 4.15.18
Uname: Linux 4.15.0-42-generic ppc64le
AlsaDevices:
total 0
crw-rw---- 1 root audio 116, 1 Nov 29 04:58 seq
crw-rw---- 1 root audio 116, 33 Nov 29 04:58 timer
AplayDevices: Error: [Errno 2] No such file or directory: 'aplay': 'aplay'
ApportVersion: 2.20.9-0ubuntu7.5
Architecture: ppc64el
ArecordDevices: Error: [Errno 2] No such file or directory: 'arecord': 'arecord'
AudioDevicesInUse: Error: command ['fuser', '-v', '/dev/snd/seq', '/dev/snd/timer'] failed with exit code 1:
Date: Thu Nov 29 05:05:38 2018
IwConfig: Error: [Errno 2] No such file or directory: 'iwconfig': 'iwconfig'
Lsusb:
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 003: ID 0451:80ff Texas Instruments, Inc.
Bus 001 Device 004: ID 0557:2419 ATEN International Co., Ltd
Bus 001 Device 002: ID 0557:7000 ATEN International Co., Ltd Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
PciMultimedia:

ProcFB: 0 astdrmfb
ProcKernelCmdLine: root=UUID=acd1a0d7-f6fc-4130-928c-c8b11ad6e4be ro console=hvc0
ProcLoadAvg: 2.45 1.59 0.69 3/1426 14448
ProcLocks:
1: FLOCK ADVISORY WRITE 4143 00:17:593 0 EOF
2: FLOCK ADVISORY WRITE 3627 00:17:525 0 EOF
3: POSIX ADVISORY WRITE 1799 00:17:368 0 EOF
4: POSIX ADVISORY WRITE 4090 00:17:592 0 EOF
5: POSIX ADVISORY WRITE 4089 00:17:582 0 EOF
ProcSwaps:
Filename Type Size Used Priority
/swap.img file 8388544 0 -2
ProcVersion: Linux version 4.15.0-42-generic (buildd@bos02-ppc64el-001) (gcc version 7.3.0 (Ubuntu 7.3.0-16ubuntu3)) #45-Ubuntu SMP Thu Nov 15 19:29:37 UTC 2018
RelatedPackageVersions:
linux-restricted-modules-4.15.0-42-generic N/A
linux-backports-modules-4.15.0-42-generic N/A
linux-firmware 1.173.2
RfKill: Error: [Errno 2] No such file or directory: 'rfkill': 'rfkill'
SourcePackage: linux
UpgradeStatus: No upgrade log present (probably fresh install)
VarLogDump_list: total 0
cpu_cores: Number of cores present = 40
cpu_coreson: Number of cores online = 40
cpu_dscr: DSCR is 16
cpu_freq:
min: 2.262 GHz (cpu 40)
max: 2.927 GHz (cpu 4)
avg: 2.896 GHz
cpu_runmode:
Could not retrieve current diagnostics mode,
No kernel interface to firmware
cpu_smt: SMT is off

Tags:

Revision history for this message

Po-Hsu Lin (cypressyew) wrote on 2018-11-29:

.sys.firmware.opal.msglog.txt Edit (928.1 KiB, text/plain; charset="utf-8")
CRDA.txt Edit (454 bytes, text/plain; charset="utf-8")
CurrentDmesg.txt Edit (1.0 KiB, text/plain; charset="utf-8")
Dependencies.txt Edit (2.8 KiB, text/plain; charset="utf-8")
DeviceTree.tar.gz Edit (208.4 KiB, application/x-gzip)
Lspci.txt Edit (57.4 KiB, text/plain; charset="utf-8")
OpalElog.tar.gz Edit (58 bytes, application/x-gzip)
ProcCpuinfo.txt Edit (4.2 KiB, text/plain; charset="utf-8")
ProcCpuinfoMinimal.txt Edit (235 bytes, text/plain; charset="utf-8")
ProcEnviron.txt Edit (248 bytes, text/plain; charset="utf-8")
ProcInterrupts.txt Edit (157.6 KiB, text/plain; charset="utf-8")
ProcMisc.txt Edit (292 bytes, text/plain; charset="utf-8")
ProcModules.txt Edit (3.4 KiB, text/plain; charset="utf-8")
ProcPpc64.tar.gz Edit (497 bytes, application/x-gzip)
UdevDb.txt Edit (210.9 KiB, text/plain; charset="utf-8")
WifiSyslog.txt Edit (137.0 KiB, text/plain; charset="utf-8")
nvram.gz Edit (2.5 KiB, application/x-gzip)

Revision history for this message

Ubuntu Kernel Bot (ubuntu-kernel-bot) wrote on 2018-11-29: Status changed to Confirmed

This change was made by a bot.

Changed in linux (Ubuntu):
status:	New → Confirmed

Revision history for this message

Po-Hsu Lin (cypressyew) wrote on 2018-11-29:

For the P9 baltar, I can reproduce the stress-ng task blocking issue by just running the test directly (with Bionic in -released)

Revision history for this message

Colin Ian King (colin-king) wrote on 2018-11-29:

Seems like a process is still running at umount time and a re-mount fails. I think it snowballs after that.

[ 1209.031563] Mount point: /mnt/vfat-test-15951
[ 1209.032392] Started, PID 67047
[ 1224.249103] stress-ng now terminated
[ 1224.249203] Stopped, PID 67047 (after 14 seconds)
[ 1224.249312] umounting vfat
[ 1224.468077] umounting tmpfs
[ 1224.548526] Testing: --verify --times --metrics-brief --syslog --keep-name -t 10s --hdd 2 --hdd-opts sync,wr-rnd,rd-rnd,fadv-willneed,fadv-rnd --lockf 2 --seek 2 --aio 2 --aio-requests 32 --dentry 2 --dir 2 --dentry-order stride --fallocate 2 --fstat 2 --dentries 100 --lease 2 --open 2 --rename 2 --hdd-bytes 4M --fallocate-bytes 4M --chdir 2 --rename 2 --hdd-write-size 512
[ 1225.606221] Created loop image /mnt/vfat-test-15951/vfat-loop-data
[ 1225.684994] ubuntu_vfat_str (15951): drop_caches: 1
[ 1225.692320] ubuntu_vfat_str (15951): drop_caches: 2
[ 1225.695075] ubuntu_vfat_str (15951): drop_caches: 3
[ 1226.046191] VFAT options: fmask=777
[ 1226.046241] Stress test: /home/ubuntu/autotest/client/tmp/ubuntu_vfat_stress/src/stress-ng/stress-ng --verify --times --metrics-brief --syslog --keep-name -t 10s --hdd 2 --hdd-opts sync,wr-rnd,rd-rnd,fadv-willneed,fadv-rnd --lockf 2 --seek 2 --aio 2 --aio-requests 32 --dentry 2 --dir 2 --dentry-order stride --fallocate 2 --fstat 2 --dentries 100 --lease 2 --open 2 --rename 2 --hdd-bytes 4M --fallocate-bytes 4M --chdir 2 --rename 2 --hdd-write-size 512
[ 1226.046261] Mount point: /mnt/vfat-test-15951
[ 1226.046733] Started, PID 107847
[ 1230.696549] stress-ng now terminated
[ 1230.696689] Stopped, PID 107847 (after 4 seconds)
[ 1230.696870] umounting vfat
[ 1230.729214] umount vfat /mnt/vfat-test-15951 failed
[ 1230.729283] umounting tmpfs
[ 1230.730847] umount /mnt/vfat-test-15951 failed
[ 1230.746365] /mnt/vfat-test-15951 is already mounted!

Revision history for this message

Colin Ian King (colin-king) wrote on 2018-11-29:

  Started, PID 107847
  stress-ng now terminated
  Stopped, PID 107847 (after 4 seconds)
  umounting vfat
  umount: /mnt/vfat-test-15951: target is busy.
  umount vfat /mnt/vfat-test-15951 failed
  umounting tmpfs
  umount: /mnt/vfat-test-15951: target is busy.
  umount /mnt/vfat-test-15951 failed
  rmdir: failed to remove '/mnt/vfat-test-15951': Device or resource busy

Revision history for this message

Colin Ian King (colin-king) wrote on 2018-11-29:

Download full text (4.1 KiB)

OK, managed to reproduce this:

[ 3913.025219] VFAT options: check=s
[ 3913.025268] Stress test: /home/ubuntu/autotest/client/tmp/ubuntu_vfat_stress/src/stress-ng/stress-ng --verify --times --metrics-brief --syslog --keep-name -t 10s --hdd 2 --hdd-opts sync,wr-rnd,rd-rnd,fadv-willneed,fadv-rnd --lockf 2 --seek 2 --aio 2 --aio-requests 32 --dentry 2 --dir 2 --dentry-order stride --fallocate 2 --fstat 2 --dentries 100 --lease 2 --open 2 --rename 2 --hdd-bytes 4M --fallocate-bytes 4M --chdir 2 --rename 2 --hdd-write-size 512
[ 3913.025287] Mount point: /mnt/vfat-test-75202
[ 3913.025760] Started, PID 74908

Nov 29 12:53:00 baltar kernel: [ 4110.095234] INFO: task kworker/u321:3:80990 blocked for more than 120 seconds.
Nov 29 12:53:00 baltar kernel: [ 4110.095309] Not tainted 4.15.0-39-generic #42-Ubuntu
Nov 29 12:53:00 baltar kernel: [ 4110.095345] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 29 12:53:00 baltar kernel: [ 4110.095398] kworker/u321:3 D 0 80990 2 0x00000800
Nov 29 12:53:00 baltar kernel: [ 4110.095406] Workqueue: writeback wb_workfn (flush-7:0)
Nov 29 12:53:00 baltar kernel: [ 4110.095408] Call Trace:
Nov 29 12:53:00 baltar kernel: [ 4110.095411] [c000000feb7b6af0] [c000000feb7b6b60] 0xc000000feb7b6b60 (unreliable)
Nov 29 12:53:00 baltar kernel: [ 4110.095416] [c000000feb7b6cc0] [c00000000001c1d0] __switch_to+0x2a0/0x4d0
Nov 29 12:53:00 baltar kernel: [ 4110.095419] [c000000feb7b6d20] [c000000000cfd2e4] __schedule+0x2a4/0xaf0
Nov 29 12:53:00 baltar kernel: [ 4110.095423] [c000000feb7b6df0] [c000000000cfdb70] schedule+0x40/0xc0
Nov 29 12:53:00 baltar kernel: [ 4110.095426] [c000000feb7b6e10] [c000000000152e7c] io_schedule+0x2c/0x50
Nov 29 12:53:00 baltar kernel: [ 4110.095429] [c000000feb7b6e40] [c0000000006d1e04] wbt_wait+0x484/0x4e0
Nov 29 12:53:00 baltar kernel: [ 4110.095432] [c000000feb7b6ee0] [c000000000698e74] blk_mq_make_request+0x104/0x6e0
Nov 29 12:53:00 baltar kernel: [ 4110.095436] [c000000feb7b6f80] [c000000000686a34] generic_make_request+0x124/0x380
Nov 29 12:53:00 baltar kernel: [ 4110.095439] [c000000feb7b6ff0] [c000000000686d4c] submit_bio+0xbc/0x1d0
Nov 29 12:53:00 baltar kernel: [ 4110.095442] [c000000feb7b70a0] [c00000000042de2c] submit_bh_wbc+0x1dc/0x240
Nov 29 12:53:00 baltar kernel: [ 4110.095445] [c000000feb7b70f0] [c00000000042e108] __block_write_full_page+0x278/0x570
Nov 29 12:53:00 baltar kernel: [ 4110.095448] [c000000feb7b7190] [c00000000054ac6c] fat_writepage+0x2c/0x40
Nov 29 12:53:00 baltar kernel: [ 4110.095451] [c000000feb7b71b0] [c00000000043bdf0] __mpage_writepage+0x170/0x7b0
Nov 29 12:53:00 baltar kernel: [ 4110.095455] [c000000feb7b76e0] [c0000000002f2d9c] write_cache_pages+0x25c/0x590
Nov 29 12:53:00 baltar kernel: [ 4110.095457] [c000000feb7b7820] [c00000000043bac8] mpage_writepages+0x78/0x150
Nov 29 12:53:00 baltar kernel: [ 4110.095460] [c000000feb7b78b0] [c00000000054abe8] fat_writepages+0x28/0x40
Nov 29 12:53:00 baltar kernel: [ 4110.095463] [c000000feb7b78d0] [c0000000002f5f1c] do_writepages+0x4c/0x130
Nov 29 12:53:00 baltar kernel: [ 4110.095465] [c000000feb7b7940] [c00000000041eff0] __writeback_single_inode+0x70/0x570
Nov 29 12:53:00 b...

OK, managed to reproduce this:

[ 3913.025219] VFAT options:  check=s
[ 3913.025268] Stress test:   /home/ubuntu/autotest/client/tmp/ubuntu_vfat_stress/src/stress-ng/stress-ng --verify --times --metrics-brief --syslog --keep-name -t 10s --hdd 2 --hdd-opts sync,wr-rnd,rd-rnd,fadv-willneed,fadv-rnd --lockf 2 --seek 2 --aio 2 --aio-requests 32 --dentry 2 --dir 2 --dentry-order stride --fallocate 2 --fstat 2 --dentries 100 --lease 2 --open 2 --rename 2 --hdd-bytes 4M --fallocate-bytes 4M --chdir 2 --rename 2 --hdd-write-size 512
[ 3913.025287] Mount point:   /mnt/vfat-test-75202
[ 3913.025760] Started, PID 74908

Nov 29 12:53:00 baltar kernel: [ 4110.095234] INFO: task kworker/u321:3:80990 blocked for more than 120 seconds.
Nov 29 12:53:00 baltar kernel: [ 4110.095309]       Not tainted 4.15.0-39-generic #42-Ubuntu
Nov 29 12:53:00 baltar kernel: [ 4110.095345] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 29 12:53:00 baltar kernel: [ 4110.095398] kworker/u321:3  D    0 80990      2 0x00000800
Nov 29 12:53:00 baltar kernel: [ 4110.095406] Workqueue: writeback wb_workfn (flush-7:0)
Nov 29 12:53:00 baltar kernel: [ 4110.095408] Call Trace:
Nov 29 12:53:00 baltar kernel: [ 4110.095411] [c000000feb7b6af0] [c000000feb7b6b60] 0xc000000feb7b6b60 (unreliable)
Nov 29 12:53:00 baltar kernel: [ 4110.095416] [c000000feb7b6cc0] [c00000000001c1d0] __switch_to+0x2a0/0x4d0
Nov 29 12:53:00 baltar kernel: [ 4110.095419] [c000000feb7b6d20] [c000000000cfd2e4] __schedule+0x2a4/0xaf0
Nov 29 12:53:00 baltar kernel: [ 4110.095423] [c000000feb7b6df0] [c000000000cfdb70] schedule+0x40/0xc0
Nov 29 12:53:00 baltar kernel: [ 4110.095426] [c000000feb7b6e10] [c000000000152e7c] io_schedule+0x2c/0x50
Nov 29 12:53:00 baltar kernel: [ 4110.095429] [c000000feb7b6e40] [c0000000006d1e04] wbt_wait+0x484/0x4e0
Nov 29 12:53:00 baltar kernel: [ 4110.095432] [c000000feb7b6ee0] [c000000000698e74] blk_mq_make_request+0x104/0x6e0
Nov 29 12:53:00 baltar kernel: [ 4110.095436] [c000000feb7b6f80] [c000000000686a34] generic_make_request+0x124/0x380
Nov 29 12:53:00 baltar kernel: [ 4110.095439] [c000000feb7b6ff0] [c000000000686d4c] submit_bio+0xbc/0x1d0
Nov 29 12:53:00 baltar kernel: [ 4110.095442] [c000000feb7b70a0] [c00000000042de2c] submit_bh_wbc+0x1dc/0x240
Nov 29 12:53:00 baltar kernel: [ 4110.095445] [c000000feb7b70f0] [c00000000042e108] __block_write_full_page+0x278/0x570
Nov 29 12:53:00 baltar kernel: [ 4110.095448] [c000000feb7b7190] [c00000000054ac6c] fat_writepage+0x2c/0x40
Nov 29 12:53:00 baltar kernel: [ 4110.095451] [c000000feb7b71b0] [c00000000043bdf0] __mpage_writepage+0x170/0x7b0
Nov 29 12:53:00 baltar kernel: [ 4110.095455] [c000000feb7b76e0] [c0000000002f2d9c] write_cache_pages+0x25c/0x590
Nov 29 12:53:00 baltar kernel: [ 4110.095457] [c000000feb7b7820] [c00000000043bac8] mpage_writepages+0x78/0x150
Nov 29 12:53:00 baltar kernel: [ 4110.095460] [c000000feb7b78b0] [c00000000054abe8] fat_writepages+0x28/0x40
Nov 29 12:53:00 baltar kernel: [ 4110.095463] [c000000feb7b78d0] [c0000000002f5f1c] do_writepages+0x4c/0x130
Nov 29 12:53:00 baltar kernel: [ 4110.095465] [c000000feb7b7940] [c00000000041eff0] __writeback_single_inode+0x70/0x570
Nov 29 12:53:00 baltar kernel: [ 4110.095468] [c000000feb7b79a0] [c00000000041fb8c] writeback_sb_inodes+0x26c/0x5d0
Nov 29 12:53:00 baltar kernel: [ 4110.095470] [c000000feb7b7ab0] [c00000000042024c] wb_writeback+0x13c/0x460
Nov 29 12:53:00 baltar kernel: [ 4110.095472] [c000000feb7b7b80] [c000000000420f20] wb_workfn+0x100/0x5e0
Nov 29 12:53:00 baltar kernel: [ 4110.095475] [c000000feb7b7c90] [c000000000134bd8] process_one_work+0x298/0x5a0
Nov 29 12:53:00 baltar kernel: [ 4110.095478] [c000000feb7b7d20] [c000000000134f78] worker_thread+0x98/0x630
Nov 29 12:53:00 baltar kernel: [ 4110.095480] [c000000feb7b7dc0] [c00000000013db48] kthread+0x1a8/0x1b0
Nov 29 12:53:00 baltar kernel: [ 4110.095484] [c000000feb7b7e30] [c00000000000b658] ret_from_kernel_thread+0x5c/0x84
Nov 29 12:53:00 baltar kernel: [ 4110.095487] INFO: task stress-ng:74924 blocked for more than 120 seconds.
Nov 29 12:53:00 baltar kernel: [ 4110.095531]       Not tainted 4.15.0-39-generic #42-Ubuntu

Revision history for this message

Colin Ian King (colin-king) wrote on 2018-11-29:

Sam, can this be retested, I think we were getting into dirty page write amplification because of using vfat on a tmpfs backing store file. I've reworked the test now to use bog standard vfat on a loopbacked file.

Fix committed: http://kernel.ubuntu.com/git/ubuntu/autotest-client-tests.git/commit/?id=e39a7d03a6dbda3039514096737d72150877017b

no longer affects:	stress-ng
Changed in linux (Ubuntu):
assignee:	nobody → Colin Ian King (colin-king)
importance:	Undecided → High
status:	Confirmed → Fix Committed
status:	Fix Committed → Triaged
importance:	High → Undecided
assignee:	Colin Ian King (colin-king) → nobody
Changed in ubuntu-kernel-tests:
assignee:	nobody → Colin Ian King (colin-king)
importance:	Undecided → High
status:	New → Fix Committed

Revision history for this message

Po-Hsu Lin (cypressyew) wrote on 2018-11-30:

Retested on both entei and baltar,
passed on entei but still failing on balter (with the whole test suite)

Log for balter:
https://pastebin.ubuntu.com/p/82NXmVYS93/

I will give it another shot on balter.

Revision history for this message

Po-Hsu Lin (cypressyew) wrote on 2018-11-30:

BTW, the vfat stress failure in Bionic 4.18 has gone with retest as well. (node pepe)

Colin Ian King (colin-king) on 2018-11-30

Changed in ubuntu-kernel-tests:
status:	Fix Committed → Fix Released
Changed in linux (Ubuntu):
status:	Triaged → Won't Fix

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Bug attachments

Add attachment

Remote bug watches

Bug watches keep track of this bug in other bug trackers.

Ubuntulinux package

ubuntu_vfat_stress failed again with P8/P9 Bionic

Bug Description

Other bug subscribers

Bug attachments

Remote bug watches

Ubuntu
linux package