* Sync took ~8 hours to complete on a UDF DVD+RW with very complex directory structure
@ 2017-01-12 0:35 Steve Kenton
2017-01-20 12:23 ` Jan Kara
0 siblings, 1 reply; 3+ messages in thread
From: Steve Kenton @ 2017-01-12 0:35 UTC (permalink / raw)
To: linux-fsdevel; +Cc: jack, pali.rohar, Steve Kenton
[-- 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)
^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: Sync took ~8 hours to complete on a UDF DVD+RW with very complex directory structure
2017-01-12 0:35 Sync took ~8 hours to complete on a UDF DVD+RW with very complex directory structure Steve Kenton
@ 2017-01-20 12:23 ` Jan Kara
2017-01-20 15:27 ` Steve Kenton
0 siblings, 1 reply; 3+ messages in thread
From: Jan Kara @ 2017-01-20 12:23 UTC (permalink / raw)
To: Steve Kenton; +Cc: linux-fsdevel, jack, pali.rohar
On Wed 11-01-17 18:35:02, Steve Kenton wrote:
> 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.
Yeah, I think the problem is that seeking just kills the DVD drive and UDF
driver in Linux is not very good in avoiding them. So writing to a UDF
filesystem on DVD media directly simply does not work very well. Also if
you copy a directory tree, there are lots of inplace updates of directories
happening so that may contribute to slowness as well. So all in all I don't
think this was ever something we were trying to make work reasonably since
people don't tend to use DVD like this...
Honza
--
Jan Kara <jack@suse.com>
SUSE Labs, CR
^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: Sync took ~8 hours to complete on a UDF DVD+RW with very complex directory structure
2017-01-20 12:23 ` Jan Kara
@ 2017-01-20 15:27 ` Steve Kenton
0 siblings, 0 replies; 3+ messages in thread
From: Steve Kenton @ 2017-01-20 15:27 UTC (permalink / raw)
To: Jan Kara; +Cc: linux-fsdevel, pali.rohar
On 01/20/2017 07:23 AM, Jan Kara wrote:
> On Wed 11-01-17 18:35:02, Steve Kenton wrote:
>> 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.
>
> Yeah, I think the problem is that seeking just kills the DVD drive and UDF
> driver in Linux is not very good in avoiding them. So writing to a UDF
> filesystem on DVD media directly simply does not work very well. Also if
> you copy a directory tree, there are lots of inplace updates of directories
> happening so that may contribute to slowness as well. So all in all I don't
> think this was ever something we were trying to make work reasonably since
> people don't tend to use DVD like this...
>
> Honza
>
Granted it was a stress test, I was just surprised by the magnitude of
the slow down. Probably worth pursuing - later.
Steve Kenton
^ permalink raw reply [flat|nested] 3+ messages in thread
end of thread, other threads:[~2017-01-20 15:28 UTC | newest]
Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-01-12 0:35 Sync took ~8 hours to complete on a UDF DVD+RW with very complex directory structure Steve Kenton
2017-01-20 12:23 ` Jan Kara
2017-01-20 15:27 ` Steve Kenton
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).