From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mail-by2nam03on0090.outbound.protection.outlook.com ([104.47.42.90]:64704 "EHLO NAM03-BY2-obe.outbound.protection.outlook.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S932177AbdALAfR (ORCPT ); Wed, 11 Jan 2017 19:35:17 -0500 From: Steve Kenton To: linux-fsdevel@vger.kernel.org Cc: jack@suse.cz, pali.rohar@gmail.com, Steve Kenton Subject: Sync took ~8 hours to complete on a UDF DVD+RW with very complex directory structure Date: Wed, 11 Jan 2017 18:35:02 -0600 Message-Id: <20170112003502.11233-1-skenton@ou.edu> MIME-Version: 1.0 Content-Type: text/plain; charset=sync-problem.txt Content-Transfer-Encoding: 8bit Sender: linux-fsdevel-owner@vger.kernel.org List-ID: I first noticed this with 4.10rc2+ while testing some changes I was making to the UDF driver but it's neither a new problem nor related to my changes. Below is a test run on a stock Ubuntu 14.04 system with kernel 3.19 and the results are the same. If I copy large video files to the DVD I can put 4+GiB on the disk, it syncs as expected and life is good. If I try to copy Linus' 2.7GiB repo to the DVD it is still going after running overnight and after killing the copy sync does not return for hours, which hangs a graceful reboot. I should note that while the sync has not completed the filesystem on the DVD seems usable for the light testing I did using df, ls, find etc and the verbose copy was still proceeding if slowly when I killed it. I can well believe a problem in the UDF or optical disc drivers or some interaction between them but in my naive opinion blocking sync this long looks like a potential local DOS attack. It's easy to reproduce (steps below) and if anyone want more information or specific tests I'm happy to try and help. The tainting is due to a Blackmagic Design driver and was not present when running the tests on a 4.10rc2+ kernel. Steve Kenton =============================== Desktop Intel i5 system with 8GiB RAM and SATA DVD drive hdi@hdi-H81H3-I:~$ uname -a Linux hdi-H81H3-I 3.19.0-77-generic #85~14.04.1-Ubuntu SMP Mon Dec 5 11:19:02 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux =============================== DVD+RW disc and most recent udftools from https://github.com/pali/udftools.git mkudffs --u8 --udfrev=0x0102 --blocksize=2048 --lvid="HDi-250 DVD" --strategy=4 --media-type=dvdrw --space=unallocbitmap --ad=inicb /dev/sr0 mounted on /dvd =============================== Linus' kernel repo as of 4.10rc2+ https://github.com/torvalds/linux.git hdi@hdi-H81H3-I:~/hdi$ du -s linux 2774444 linux =============================== hdi@hdi-H81H3-I:~/hdi$ find linux | wc -l 70209 =============================== hdi@hdi-H81H3-I:~/hdi/dvrepo/BCD/old_miscstuff$ cp -rpv linux /dvd =============================== After waiting overnight, file names were still scrolling in a bursty manner where scrolling coincides with changes in the free space and when not scrolling the free space does not change for longish times until scrolling resumes. ... ‘linux/arch/frv/include/asm/pgalloc.h’ -> ‘/dvd/linux/arch/frv/include/asm/pgalloc.h’ ‘linux/arch/frv/include/asm/mmu.h’ -> ‘/dvd/linux/arch/frv/include/asm/mmu.h’ ‘linux/arch/frv/include/asm/irq.h’ -> ‘/dvd/linux/arch/frv/include/asm/irq.h’ ‘linux/arch/frv/include/asm/linkage.h’ -> ‘/dvd/linux/arch/frv/include/asm/linkage.h’ ‘linux/arch/frv/include/asm/cpu-irqs.h’ -> ‘/dvd/linux/arch/frv/include/asm/cpu-irqs.h’ ‘linux/arch/frv/include/asm/emergency-restart.h’ -> ‘/dvd/linux/arch/frv/include/asm/emergency-restart.h’ ‘linux/arch/frv/include/asm/checksum.h’ -> ‘/dvd/linux/arch/frv/include/asm/checksum.h’ ‘linux/arch/frv/include/asm/serial-regs.h’ -> ‘/dvd/linux/arch/frv/include/asm/serial-regs.h’ ‘linux/arch/frv/include/asm/fb.h’ -> ‘/dvd/linux/arch/frv/include/asm/fb.h’ ‘linux/arch/frv/include/asm/xor.h’ -> ‘/dvd/linux/arch/frv/include/asm/xor.h’ ‘linux/arch/frv/include/asm/cache.h’ -> ‘/dvd/linux/arch/frv/include/asm/cache.h’ ‘linux/arch/frv/include/asm/unistd.h’ -> ‘/dvd/linux/arch/frv/include/asm/unistd.h’ ‘linux/arch/frv/include/asm/topology.h’ -> ‘/dvd/linux/arch/frv/include/asm/topology.h’ ‘linux/arch/frv/include/asm/div64.h’ -> ‘/dvd/linux/arch/frv/include/asm/div64.h’ ‘linux/arch/frv/include/asm/dma.h’ -> ‘/dvd/linux/arch/frv/include/asm/dma.h’ ‘linux/arch/frv/include/asm/ftrace.h’ -> ‘/dvd/linux/arch/frv/include/asm/ftrace.h’ ‘linux/arch/frv/include/asm/sections.h’ -> ‘/dvd/linux/arch/frv/include/asm/sections.h’ ^C hdi@hdi-H81H3-I:~/hdi$ sync =============================== hdi@hdi-H81H3-I:~/hdi$ df /dvd Filesystem 1K-blocks Used Available Use% Mounted on /dev/sr0 4589056 2664140 1924916 59% /dvd =============================== hdi@hdi-H81H3-I:~/hdi$ find /dvd | wc -l 57023 =============================== Start sync hdi@hdi-H81H3-I:~/hdi$ date Wed Jan 11 10:34:57 CST 2017 =============================== Finally sync has completed Wed Jan 11 18:21:19 CST 2017 hdi@hdi-H81H3-I:~$ =============================== hdi@hdi-H81H3-I:~$ sudo umount /dvd [sudo] password for hdi: Sucessful unmount =============================== Periodic syslog messages indicate the kernel noticed the problem Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777579] INFO: task sync:7426 blocked for more than 120 seconds. Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777589] Tainted: P OE 3.19.0-77-generic #85~14.04.1-Ubuntu Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777592] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777595] sync D ffff880106aafd48 0 7426 3039 0x00000000 Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777605] ffff880106aafd48 ffff8801f5ad3ae0 0000000000013e80 ffff880106aaffd8 Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777611] 0000000000013e80 ffff8802162589d0 ffff8801f5ad3ae0 ffff880106aafd58 Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777617] ffff880106aafe80 7fffffffffffffff ffff880106aafe78 ffff8801f5ad3ae0 Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777623] Call Trace: Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777640] [] ? vfs_fsync+0x40/0x40 Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777650] [] schedule+0x29/0x70 Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777657] [] schedule_timeout+0x244/0x2c0 Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777665] [] ? __queue_delayed_work+0xaa/0x1a0 Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777670] [] ? try_to_grab_pending+0x138/0x170 Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777677] [] wait_for_completion+0xa4/0x170 Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777684] [] ? wake_up_state+0x20/0x20 Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777690] [] sync_inodes_sb+0xa8/0x1c0 Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777697] [] ? vfs_fsync+0x40/0x40 Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777703] [] sync_inodes_one_sb+0x19/0x20 Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777710] [] iterate_supers+0xb2/0x110 Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777716] [] sys_sync+0x35/0x90 Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777724] [] system_call_fastpath+0x16/0x1b Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769223] INFO: task sync:7426 blocked for more than 120 seconds. Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769234] Tainted: P OE 3.19.0-77-generic #85~14.04.1-Ubuntu Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769237] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769241] sync D ffff880106aafd48 0 7426 3039 0x00000000 Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769250] ffff880106aafd48 ffff8801f5ad3ae0 0000000000013e80 ffff880106aaffd8 Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769257] 0000000000013e80 ffff8802162589d0 ffff8801f5ad3ae0 ffff880106aafd58 Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769263] ffff880106aafe80 7fffffffffffffff ffff880106aafe78 ffff8801f5ad3ae0 Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769269] Call Trace: Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769286] [] ? vfs_fsync+0x40/0x40 Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769296] [] schedule+0x29/0x70 Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769303] [] schedule_timeout+0x244/0x2c0 Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769311] [] ? __queue_delayed_work+0xaa/0x1a0 Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769316] [] ? try_to_grab_pending+0x138/0x170 Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769323] [] wait_for_completion+0xa4/0x170 Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769330] [] ? wake_up_state+0x20/0x20 Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769336] [] sync_inodes_sb+0xa8/0x1c0 Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769344] [] ? vfs_fsync+0x40/0x40 Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769350] [] sync_inodes_one_sb+0x19/0x20 Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769357] [] iterate_supers+0xb2/0x110 Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769363] [] sys_sync+0x35/0x90 Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769371] [] system_call_fastpath+0x16/0x1b Jan 11 11:09:01 hdi-H81H3-I CRON[7765]: (root) CMD ( [ -x /usr/lib/php5/maxlifetime ] && [ -x /usr/lib/php5/sessionclean ] && [ -d /var/lib/php5 ] && /usr/lib/php5/sessionclean /var/lib/php5 $(/usr/lib/php5/maxlifetime)) Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760862] INFO: task sync:7426 blocked for more than 120 seconds. Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760871] Tainted: P OE 3.19.0-77-generic #85~14.04.1-Ubuntu Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760874] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760878] sync D ffff880106aafd48 0 7426 3039 0x00000000 Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760887] ffff880106aafd48 ffff8801f5ad3ae0 0000000000013e80 ffff880106aaffd8 Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760894] 0000000000013e80 ffff8802162589d0 ffff8801f5ad3ae0 ffff880106aafd58 Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760900] ffff880106aafe80 7fffffffffffffff ffff880106aafe78 ffff8801f5ad3ae0 Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760906] Call Trace: Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760923] [] ? vfs_fsync+0x40/0x40 Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760932] [] schedule+0x29/0x70 Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760940] [] schedule_timeout+0x244/0x2c0 Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760948] [] ? __queue_delayed_work+0xaa/0x1a0 Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760953] [] ? try_to_grab_pending+0x138/0x170 Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760960] [] wait_for_completion+0xa4/0x170 Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760967] [] ? wake_up_state+0x20/0x20 Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760973] [] sync_inodes_sb+0xa8/0x1c0 Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760980] [] ? vfs_fsync+0x40/0x40 Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760987] [] sync_inodes_one_sb+0x19/0x20 Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760993] [] iterate_supers+0xb2/0x110 Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.761000] [] sys_sync+0x35/0x90 Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.761007] [] system_call_fastpath+0x16/0x1b Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752501] INFO: task sync:7426 blocked for more than 120 seconds. Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752511] Tainted: P OE 3.19.0-77-generic #85~14.04.1-Ubuntu Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752514] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752518] sync D ffff880106aafd48 0 7426 3039 0x00000000 Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752527] ffff880106aafd48 ffff8801f5ad3ae0 0000000000013e80 ffff880106aaffd8 Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752534] 0000000000013e80 ffff8802162589d0 ffff8801f5ad3ae0 ffff880106aafd58 Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752539] ffff880106aafe80 7fffffffffffffff ffff880106aafe78 ffff8801f5ad3ae0 Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752546] Call Trace: Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752563] [] ? vfs_fsync+0x40/0x40 Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752573] [] schedule+0x29/0x70 Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752581] [] schedule_timeout+0x244/0x2c0 Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752588] [] ? __queue_delayed_work+0xaa/0x1a0 Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752594] [] ? try_to_grab_pending+0x138/0x170 Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752601] [] wait_for_completion+0xa4/0x170 Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752607] [] ? wake_up_state+0x20/0x20 Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752614] [] sync_inodes_sb+0xa8/0x1c0 Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752621] [] ? vfs_fsync+0x40/0x40 Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752627] [] sync_inodes_one_sb+0x19/0x20 Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752634] [] iterate_supers+0xb2/0x110 Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752640] [] sys_sync+0x35/0x90 Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752648] [] system_call_fastpath+0x16/0x1b Jan 11 11:17:01 hdi-H81H3-I CRON[7803]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)