From: Steve Kenton <skenton@ou.edu>
To: linux-fsdevel@vger.kernel.org
Cc: jack@suse.cz, pali.rohar@gmail.com, Steve Kenton <skenton@ou.edu>
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 [thread overview]
Message-ID: <20170112003502.11233-1-skenton@ou.edu> (raw)
[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain; charset=sync-problem.txt, Size: 13657 bytes --]
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] [<ffffffff8121f350>] ? vfs_fsync+0x40/0x40
Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777650] [<ffffffff817b9949>] schedule+0x29/0x70
Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777657] [<ffffffff817bca54>] schedule_timeout+0x244/0x2c0
Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777665] [<ffffffff8108d14a>] ? __queue_delayed_work+0xaa/0x1a0
Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777670] [<ffffffff8108d538>] ? try_to_grab_pending+0x138/0x170
Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777677] [<ffffffff817ba6a4>] wait_for_completion+0xa4/0x170
Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777684] [<ffffffff810a2390>] ? wake_up_state+0x20/0x20
Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777690] [<ffffffff812181e8>] sync_inodes_sb+0xa8/0x1c0
Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777697] [<ffffffff8121f350>] ? vfs_fsync+0x40/0x40
Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777703] [<ffffffff8121f369>] sync_inodes_one_sb+0x19/0x20
Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777710] [<ffffffff811f20a2>] iterate_supers+0xb2/0x110
Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777716] [<ffffffff8121f5e5>] sys_sync+0x35/0x90
Jan 11 11:06:22 hdi-H81H3-I kernel: [62515.777724] [<ffffffff817bdd0d>] 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] [<ffffffff8121f350>] ? vfs_fsync+0x40/0x40
Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769296] [<ffffffff817b9949>] schedule+0x29/0x70
Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769303] [<ffffffff817bca54>] schedule_timeout+0x244/0x2c0
Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769311] [<ffffffff8108d14a>] ? __queue_delayed_work+0xaa/0x1a0
Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769316] [<ffffffff8108d538>] ? try_to_grab_pending+0x138/0x170
Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769323] [<ffffffff817ba6a4>] wait_for_completion+0xa4/0x170
Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769330] [<ffffffff810a2390>] ? wake_up_state+0x20/0x20
Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769336] [<ffffffff812181e8>] sync_inodes_sb+0xa8/0x1c0
Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769344] [<ffffffff8121f350>] ? vfs_fsync+0x40/0x40
Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769350] [<ffffffff8121f369>] sync_inodes_one_sb+0x19/0x20
Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769357] [<ffffffff811f20a2>] iterate_supers+0xb2/0x110
Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769363] [<ffffffff8121f5e5>] sys_sync+0x35/0x90
Jan 11 11:08:22 hdi-H81H3-I kernel: [62635.769371] [<ffffffff817bdd0d>] 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] [<ffffffff8121f350>] ? vfs_fsync+0x40/0x40
Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760932] [<ffffffff817b9949>] schedule+0x29/0x70
Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760940] [<ffffffff817bca54>] schedule_timeout+0x244/0x2c0
Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760948] [<ffffffff8108d14a>] ? __queue_delayed_work+0xaa/0x1a0
Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760953] [<ffffffff8108d538>] ? try_to_grab_pending+0x138/0x170
Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760960] [<ffffffff817ba6a4>] wait_for_completion+0xa4/0x170
Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760967] [<ffffffff810a2390>] ? wake_up_state+0x20/0x20
Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760973] [<ffffffff812181e8>] sync_inodes_sb+0xa8/0x1c0
Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760980] [<ffffffff8121f350>] ? vfs_fsync+0x40/0x40
Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760987] [<ffffffff8121f369>] sync_inodes_one_sb+0x19/0x20
Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.760993] [<ffffffff811f20a2>] iterate_supers+0xb2/0x110
Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.761000] [<ffffffff8121f5e5>] sys_sync+0x35/0x90
Jan 11 11:10:22 hdi-H81H3-I kernel: [62755.761007] [<ffffffff817bdd0d>] 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] [<ffffffff8121f350>] ? vfs_fsync+0x40/0x40
Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752573] [<ffffffff817b9949>] schedule+0x29/0x70
Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752581] [<ffffffff817bca54>] schedule_timeout+0x244/0x2c0
Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752588] [<ffffffff8108d14a>] ? __queue_delayed_work+0xaa/0x1a0
Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752594] [<ffffffff8108d538>] ? try_to_grab_pending+0x138/0x170
Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752601] [<ffffffff817ba6a4>] wait_for_completion+0xa4/0x170
Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752607] [<ffffffff810a2390>] ? wake_up_state+0x20/0x20
Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752614] [<ffffffff812181e8>] sync_inodes_sb+0xa8/0x1c0
Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752621] [<ffffffff8121f350>] ? vfs_fsync+0x40/0x40
Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752627] [<ffffffff8121f369>] sync_inodes_one_sb+0x19/0x20
Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752634] [<ffffffff811f20a2>] iterate_supers+0xb2/0x110
Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752640] [<ffffffff8121f5e5>] sys_sync+0x35/0x90
Jan 11 11:12:22 hdi-H81H3-I kernel: [62875.752648] [<ffffffff817bdd0d>] system_call_fastpath+0x16/0x1b
Jan 11 11:17:01 hdi-H81H3-I CRON[7803]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
next reply other threads:[~2017-01-12 0:35 UTC|newest]
Thread overview: 3+ messages / expand[flat|nested] mbox.gz Atom feed top
2017-01-12 0:35 Steve Kenton [this message]
2017-01-20 12:23 ` Sync took ~8 hours to complete on a UDF DVD+RW with very complex directory structure Jan Kara
2017-01-20 15:27 ` Steve Kenton
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20170112003502.11233-1-skenton@ou.edu \
--to=skenton@ou.edu \
--cc=jack@suse.cz \
--cc=linux-fsdevel@vger.kernel.org \
--cc=pali.rohar@gmail.com \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).