On Tue, 30 Aug 2011 14:02:37 -0400 Josef Bacik wrote: > On 08/30/2011 12:53 PM, Sergei Trofimovich wrote: > >> Running 'sync' program after the load does not finish and eats > >> 100%CPU busy-waiting for something in kernel. > >> > >> It's easy to reproduce hang with patch for me. I just run > >> liferea and sync after it. Without patch I haven't managed to > >> hang btrfs up. > > > > And I think it's another btrfs bug. I've managed to reproduce it > > _without_ your patch and _without_ autodefrag enabled by manually > > running the following commands: $ btrfs fi defrag > > file-with-20_000-extents $ sync > > > > I think your patch just shuffles things a bit and forces > > autodefrag races to pop-up sooner (which is good! :]) > > > > Sergei, can you do sysrq+w when this is happening, and maybe turn on > the softlockup detector so we can see where sync is getting stuck? > Thanks, Sure. As I keep telling about 2 cases in IRC I will state both here explicitely: ==The First Issue (aka "The Hung sync()" case) == - it's an unpatched linus's v3.1-rc4-80-g0f43dd5 - /dev/root on / type btrfs (rw,noatime,compress=lzo) - 50% full 30GB filesystem (usual nonmixed mode) How I hung it: $ /usr/sbin/filefrag ~/.bogofilter/wordlist.db /home/st/.bogofilter/wordlist.db: 19070 extents found the file is 138MB sqlite database for bayesian SPAM filter, it's being read and written every 20 minutes or so. Maybe, it was writtent even in defrag/sync time! $~/dev/git/btrfs-progs-unstable/btrfs fi defrag ~/.bogofilter/wordlist.db $ sync ^C I didn't try to reproduce it yet. As for lockdep I'll try but I'm afraid I will fail to reproduce, but I'll try tomorrow. I suspect I'll need to seriously fragment some file first down to such horrible state. With help of David I've some (hopefully relevant) info: #!/bin/sh -x for i in $(ps aux|grep " D[+ ]\?"|awk '{print $2}'); do ps $i sudo cat /proc/$i/stack done PID TTY STAT TIME COMMAND 1291 ? D 0:00 [btrfs-endio-wri] [] btrfs_tree_read_lock+0x6d/0x120 [] btrfs_search_slot+0x698/0x8b0 [] btrfs_lookup_csum+0x68/0x190 [] __btrfs_lookup_bio_sums+0x1cf/0x3e0 [] btrfs_lookup_bio_sums+0x11/0x20 [] btrfs_submit_bio_hook+0x140/0x170 [] submit_one_bio+0x64/0xa0 [] extent_readpages+0xe5/0x100 [] btrfs_readpages+0x1a/0x20 [] __do_page_cache_readahead+0x1d2/0x280 [] ra_submit+0x1c/0x20 [] ondemand_readahead+0x12d/0x270 [] page_cache_sync_readahead+0x2c/0x40 [] __load_free_space_cache+0x1a7/0x5b0 [] load_free_space_cache+0xd1/0x190 [] cache_block_group+0xab/0x290 [] find_free_extent.clone.71+0x39f/0xab0 [] btrfs_reserve_extent+0xe0/0x170 [] btrfs_alloc_free_block+0xcf/0x330 [] __btrfs_cow_block+0x11d/0x4a0 [] btrfs_cow_block+0xe8/0x1a0 [] btrfs_search_slot+0x175/0x8b0 [] btrfs_lookup_csum+0x68/0x190 [] btrfs_csum_file_blocks+0xbe/0x670 [] add_pending_csums.clone.39+0x41/0x60 [] btrfs_finish_ordered_io+0x218/0x310 [] btrfs_writepage_end_io_hook+0x15/0x20 [] end_compressed_bio_write+0x7a/0xe0 [] bio_endio+0x18/0x30 [] end_workqueue_fn+0xec/0x120 [] worker_loop+0xac/0x520 [] kthread+0x96/0xa0 [] kernel_thread_helper+0x4/0x10 [] 0xffffffffffffffff PID TTY STAT TIME COMMAND 1296 ? D 0:00 [btrfs-transacti] [] btrfs_commit_transaction+0x22e/0x870 [] transaction_kthread+0x26b/0x280 [] kthread+0x96/0xa0 [] kernel_thread_helper+0x4/0x10 [] 0xffffffffffffffff PID TTY STAT TIME COMMAND 2891 pts/0 D+ 0:00 sync [] sleep_on_page+0x9/0x10 [] wait_on_page_bit+0x6e/0x80 [] filemap_fdatawait_range+0xfa/0x190 [] filemap_fdatawait+0x22/0x30 [] sync_inodes_sb+0x17a/0x1e0 [] __sync_filesystem+0x78/0x80 [] sync_one_sb+0x17/0x20 [] iterate_supers+0x95/0xf0 [] sync_filesystems+0x1b/0x20 [] sys_sync+0x1c/0x40 [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff PID TTY STAT TIME COMMAND cat: /proc/4454/stack: Нет такого файла или каталога disassebbled btrfs_tree_read_lock: ffffffff813004f0 push %rbp ffffffff813004f1 mov %gs:0xb5c0,%rax ffffffff813004fa mov %rsp,%rbp ffffffff813004fd push %r15 ffffffff813004ff push %r14 ffffffff81300501 lea 0x6c(%rdi),%r14 ffffffff81300505 push %r13 ffffffff81300507 lea 0x70(%rdi),%r13 ffffffff8130050b push %r12 ffffffff8130050d lea -0x60(%rbp),%r12 ffffffff81300511 push %rbx ffffffff81300512 lea 0x18(%r12),%r15 ffffffff81300517 lea 0x5c(%rdi),%rbx ffffffff8130051b sub $0x58,%rsp ffffffff8130051f mov %rdi,-0x70(%rbp) ffffffff81300523 mov %rax,-0x68(%rbp) ffffffff81300527 mov %rax,-0x78(%rbp) ffffffff8130052b nopl 0x0(%rax,%rax,1) ffffffff81300530 mov (%rbx),%eax ffffffff81300532 test %eax,%eax ffffffff81300534 je ffffffff8130057e ffffffff81300536 mov -0x68(%rbp),%rax ffffffff8130053a movq $0x0,-0x60(%rbp) ffffffff81300542 movq $0xffffffff8105d950,-0x50(%rbp) ffffffff8130054a mov %r15,-0x48(%rbp) ffffffff8130054e mov %r15,-0x40(%rbp) ffffffff81300552 mov %rax,-0x58(%rbp) ffffffff81300556 jmp ffffffff8130055d ffffffff81300558 callq ffffffff815f4670 ffffffff8130055d mov $0x2,%edx ffffffff81300562 mov %r12,%rsi ffffffff81300565 mov %r13,%rdi ffffffff81300568 callq ffffffff8105db90 ffffffff8130056d mov (%rbx),%eax ffffffff8130056f test %eax,%eax ffffffff81300571 jne ffffffff81300558 ffffffff81300573 mov %r12,%rsi ffffffff81300576 mov %r13,%rdi ffffffff81300579 callq ffffffff8105da80 ffffffff8130057e mov %r14,%rdi ffffffff81300581 callq ffffffff815f76d0 <_raw_read_lock> ffffffff81300586 mov (%rbx),%eax ffffffff81300588 test %eax,%eax ffffffff8130058a je ffffffff813005eb ffffffff8130058c mov %r14,%rdi ffffffff8130058f callq ffffffff815f73f0 <_raw_read_unlock> ffffffff81300594 mov (%rbx),%eax ffffffff81300596 test %eax,%eax ffffffff81300598 je ffffffff81300530 ffffffff8130059a mov -0x78(%rbp),%rax ffffffff8130059e movq $0x0,-0x60(%rbp) ffffffff813005a6 movq $0xffffffff8105d950,-0x50(%rbp) ffffffff813005ae mov %r15,-0x48(%rbp) ffffffff813005b2 mov %r15,-0x40(%rbp) ffffffff813005b6 mov %rax,-0x58(%rbp) ffffffff813005ba jmp ffffffff813005c5 ffffffff813005bc nopl 0x0(%rax) ffffffff813005c0 callq ffffffff815f4670 ffffffff813005c5 mov $0x2,%edx ffffffff813005ca mov %r12,%rsi ffffffff813005cd mov %r13,%rdi ffffffff813005d0 callq ffffffff8105db90 ffffffff813005d5 mov (%rbx),%eax ffffffff813005d7 test %eax,%eax ffffffff813005d9 jne ffffffff813005c0 ffffffff813005db mov %r12,%rsi ffffffff813005de mov %r13,%rdi ffffffff813005e1 callq ffffffff8105da80 ffffffff813005e6 jmpq ffffffff81300530 ffffffff813005eb mov -0x70(%rbp),%rax ffffffff813005ef lock incl 0x58(%rax) ffffffff813005f3 lock incl 0x64(%rax) ffffffff813005f7 add $0x58,%rsp ffffffff813005fb pop %rbx ffffffff813005fc pop %r12 ffffffff813005fe pop %r13 ffffffff81300600 pop %r14 ffffffff81300602 pop %r15 ffffffff81300604 leaveq ffffffff81300605 retq ffffffff81300606 nopw %cs:0x0(%rax,%rax,1) ==The Second Issue (aka "The Busy Looping sync()" case) == The box is different from first, so conditions are a bit different. - it's a _patched_ linus's 3.1.0-rc3-00271-g3230739 (+patch from $SUBJ on top) - /dev/root on / type btrfs (rw,noatime,autodefrag) (note autodefrag!) - 15% full 594GB filesystem (usual nonmixed mode) How I hung it: $ liferea $ sync Got CPU is 100% loaded Perfectly reproducible. I don't remembed it it exits or hangs. Will send detailed followup today. -- Sergei