On Tue, Apr 10, 2012 at 5:16 PM, Josef Bacik <jo...@redhat.com> wrote: > On Mon, Apr 09, 2012 at 05:20:46PM -0400, Calvin Walton wrote: >> On Mon, 2012-04-09 at 16:54 -0400, Josef Bacik wrote: >> > On Mon, Apr 09, 2012 at 01:10:04PM -0400, Calvin Walton wrote: >> > > On Mon, 2012-04-09 at 11:53 -0400, Calvin Walton wrote: >> > > > Hi, >> > > > >> > > > I have a system that's using a dracut-generated initramfs to mount a >> > > > btrfs root. After upgrading to kernel 3.4.0-rc2 to test it out, I've >> > > > noticed that the process of mounting the root filesystem takes much >> > > > longer with 3.4.0-rc2 than it did with 3.3.1 - nearly 30 seconds >> > > > slower! >> >> > > And the bisect results are in: >> > > 285ff5af6ce358e73f53b55c9efadd4335f4c2ff is the first bad commit >> > > commit 285ff5af6ce358e73f53b55c9efadd4335f4c2ff >> > > Author: Josef Bacik <jo...@redhat.com> >> > > Date: Fri Jan 13 15:27:45 2012 -0500 >> > > >> > > Btrfs: remove the ideal caching code> >> > >> > Ok can you give this a whirl? You are going to have to boot/reboot a few >> > times >> > to let the cache get re-generated again to make sure it's taken effect, but >> > hopefully this will help out. Thanks, >> >> Unfortunately, it doesn't seem to help. Even after 3 or 4 reboots with >> this patch applied I'm still seeing the same delay. >> > > Ok drop that previous patch and give this one a whirl, it helped on my laptop. > This is only half of the problem AFAICS, but it's the easier half to fix, in > the meantime I need to lock down why we're not writing out cache for a bunch > of > block groups, but thats trickier since the messages I need are spit out while > I'm shutting down, so I need to get creative. Let me know if/how much this > helps. Thanks,
i have tried your patch and my system still needs several minutes to boot until it can be used. Also tried to reboot several times - it doesn't look like its getting better. The last thing the system does when its shutting down is a read-only remount of "/" so no umount. Booting was much faster before i pulled for-linus a few weeks ago but i couldn't find the time to bisect it yet .. please also look at the attached dmesg.txt. this is an core i3 system with 2x2TB BTRFS RAID1 and lots of home directories and snapshots. I'm going to test this patch on twenty more computers but with smaller HDDs and less files and see if it helps to speed up their boot times. Ahmet
[ 28.155134] btrfs: use lzo compression [ 239.698516] INFO: task btrfs-transacti:997 blocked for more than 120 seconds. [ 239.698520] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 239.698524] btrfs-transacti D ffff88023fcd0a00 0 997 2 0x00000000 [ 239.698530] ffff880233c1bce0 0000000000000046 ffff880234bcc9c0 0000000000010a00 [ 239.698535] ffff880233c1bfd8 ffff880233c1a000 0000000000010a00 0000000000004000 [ 239.698539] ffff880233c1bfd8 0000000000010a00 ffff880236d384c0 ffff880234bcc9c0 [ 239.698544] Call Trace: [ 239.698554] [<ffffffff8105d738>] ? idle_balance+0x108/0x130 [ 239.698580] [<ffffffffa001ec04>] ? do_chunk_alloc.clone.68+0x74/0x400 [btrfs] [ 239.698602] [<ffffffffa0077403>] ? btrfs_find_ref_cluster+0x33/0x170 [btrfs] [ 239.698618] [<ffffffffa001ea33>] ? btrfs_reduce_alloc_profile+0x53/0x120 [btrfs] [ 239.698624] [<ffffffff810caf8c>] ? cache_alloc_refill+0x7c/0x280 [ 239.698630] [<ffffffff8160beba>] schedule+0x3a/0x50 [ 239.698634] [<ffffffff8160a245>] schedule_timeout+0x1c5/0x220 [ 239.698638] [<ffffffff8160aaf9>] ? mutex_lock+0x19/0x40 [ 239.698643] [<ffffffff8104c2eb>] ? prepare_to_wait+0x5b/0x90 [ 239.698662] [<ffffffffa00331bf>] btrfs_commit_transaction+0x30f/0x9a0 [btrfs] [ 239.698680] [<ffffffffa0032472>] ? join_transaction.clone.26+0x22/0x2e0 [btrfs] [ 239.698685] [<ffffffff8104c050>] ? wake_up_bit+0x40/0x40 [ 239.698701] [<ffffffffa002bb5b>] transaction_kthread+0x25b/0x2d0 [btrfs] [ 239.698717] [<ffffffffa002b900>] ? btrfs_alloc_root+0x30/0x30 [btrfs] [ 239.698733] [<ffffffffa002b900>] ? btrfs_alloc_root+0x30/0x30 [btrfs] [ 239.698737] [<ffffffff8104bb66>] kthread+0x96/0xa0 [ 239.698742] [<ffffffff8160e9d4>] kernel_thread_helper+0x4/0x10 [ 239.698746] [<ffffffff8104bad0>] ? kthread_freezable_should_stop+0x70/0x70 [ 239.698750] [<ffffffff8160e9d0>] ? gs_change+0xb/0xb [ 359.367274] INFO: task btrfs-transacti:997 blocked for more than 120 seconds. [ 359.367278] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 359.367281] btrfs-transacti D ffff88023fcd0a00 0 997 2 0x00000000 [ 359.367288] ffff880233c1bce0 0000000000000046 ffff880234bcc9c0 0000000000010a00 [ 359.367292] ffff880233c1bfd8 ffff880233c1a000 0000000000010a00 0000000000004000 [ 359.367297] ffff880233c1bfd8 0000000000010a00 ffff880236d384c0 ffff880234bcc9c0 [ 359.367302] Call Trace: [ 359.367311] [<ffffffff8105d738>] ? idle_balance+0x108/0x130 [ 359.367341] [<ffffffffa001ec04>] ? do_chunk_alloc.clone.68+0x74/0x400 [btrfs] [ 359.367361] [<ffffffffa0077403>] ? btrfs_find_ref_cluster+0x33/0x170 [btrfs] [ 359.367376] [<ffffffffa001ea33>] ? btrfs_reduce_alloc_profile+0x53/0x120 [btrfs] [ 359.367382] [<ffffffff810caf8c>] ? cache_alloc_refill+0x7c/0x280 [ 359.367387] [<ffffffff8160beba>] schedule+0x3a/0x50 [ 359.367392] [<ffffffff8160a245>] schedule_timeout+0x1c5/0x220 [ 359.367395] [<ffffffff8160aaf9>] ? mutex_lock+0x19/0x40 [ 359.367401] [<ffffffff8104c2eb>] ? prepare_to_wait+0x5b/0x90 [ 359.367418] [<ffffffffa00331bf>] btrfs_commit_transaction+0x30f/0x9a0 [btrfs] [ 359.367434] [<ffffffffa0032472>] ? join_transaction.clone.26+0x22/0x2e0 [btrfs] [ 359.367439] [<ffffffff8104c050>] ? wake_up_bit+0x40/0x40 [ 359.367454] [<ffffffffa002bb5b>] transaction_kthread+0x25b/0x2d0 [btrfs] [ 359.367468] [<ffffffffa002b900>] ? btrfs_alloc_root+0x30/0x30 [btrfs] [ 359.367483] [<ffffffffa002b900>] ? btrfs_alloc_root+0x30/0x30 [btrfs] [ 359.367487] [<ffffffff8104bb66>] kthread+0x96/0xa0 [ 359.367491] [<ffffffff8160e9d4>] kernel_thread_helper+0x4/0x10 [ 359.367495] [<ffffffff8104bad0>] ? kthread_freezable_should_stop+0x70/0x70 [ 359.367499] [<ffffffff8160e9d0>] ? gs_change+0xb/0xb [ 381.402216] device label root devid 2 transid 191279 /dev/sdb2 [ 381.513690] device label root devid 2 transid 191280 /dev/sdb2 [ 381.544355] device label root devid 2 transid 191280 /dev/sdb2 [ 381.598693] device label root devid 2 transid 191280 /dev/sdb2 [ 381.657321] device label root devid 2 transid 191280 /dev/sdb2 [ 385.489174] tg3 0000:02:00.0: irq 43 for MSI/MSI-X [ 386.403428] tg3 0000:02:00.0: eth0: Link is down [ 389.404993] tg3 0000:02:00.0: eth0: Link is up at 1000 Mbps, full duplex [ 389.404998] tg3 0000:02:00.0: eth0: Flow control is on for TX and on for RX [ 400.955504] NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory [ 400.955527] NFSD: starting 90-second grace period [ 598.704766] INFO: task btrfs-transacti:997 blocked for more than 120 seconds. [ 598.704771] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 598.704775] btrfs-transacti D ffff88023fc50a00 0 997 2 0x00000000 [ 598.704781] ffff880233c1ba80 0000000000000046 ffff880234bcc9c0 0000000000010a00 [ 598.704786] ffff880233c1bfd8 ffff880233c1a000 0000000000010a00 0000000000004000 [ 598.704791] ffff880233c1bfd8 0000000000010a00 ffff880236d0a2c0 ffff880234bcc9c0 [ 598.704796] Call Trace: [ 598.704806] [<ffffffff810a21df>] ? release_pages+0x1af/0x200 [ 598.704812] [<ffffffff81096ce0>] ? __lock_page+0x70/0x70 [ 598.704819] [<ffffffff8160beba>] schedule+0x3a/0x50 [ 598.704822] [<ffffffff8160bf2b>] io_schedule+0x5b/0x80 [ 598.704826] [<ffffffff81096ce9>] sleep_on_page+0x9/0x10 [ 598.704831] [<ffffffff8160a352>] __wait_on_bit_lock+0x52/0xb0 [ 598.704835] [<ffffffff81096cd2>] __lock_page+0x62/0x70 [ 598.704840] [<ffffffff8104c090>] ? autoremove_wake_function+0x40/0x40 [ 598.704872] [<ffffffffa0056df1>] extent_write_cache_pages.clone.26.clone.40+0x211/0x3e0 [btrfs] [ 598.704896] [<ffffffffa00571f5>] extent_writepages+0x45/0x60 [btrfs] [ 598.704916] [<ffffffffa0037500>] ? uncompress_inline.clone.44+0x1b0/0x1b0 [btrfs] [ 598.704934] [<ffffffffa0036d42>] btrfs_writepages+0x22/0x30 [btrfs] [ 598.704939] [<ffffffff810a0d4c>] do_writepages+0x1c/0x30 [ 598.704943] [<ffffffff8109791b>] __filemap_fdatawrite_range+0x5b/0x60 [ 598.704948] [<ffffffff810987d7>] filemap_flush+0x17/0x20 [ 598.704967] [<ffffffffa0051c82>] btrfs_run_ordered_operations+0x192/0x200 [btrfs] [ 598.704986] [<ffffffffa0032f26>] btrfs_commit_transaction+0x76/0x9a0 [btrfs] [ 598.704991] [<ffffffff8103bf92>] ? del_timer_sync+0x32/0x50 [ 598.705009] [<ffffffffa0032472>] ? join_transaction.clone.26+0x22/0x2e0 [btrfs] [ 598.705013] [<ffffffff8104c050>] ? wake_up_bit+0x40/0x40 [ 598.705030] [<ffffffffa002bb5b>] transaction_kthread+0x25b/0x2d0 [btrfs] [ 598.705046] [<ffffffffa002b900>] ? btrfs_alloc_root+0x30/0x30 [btrfs] [ 598.705062] [<ffffffffa002b900>] ? btrfs_alloc_root+0x30/0x30 [btrfs] [ 598.705066] [<ffffffff8104bb66>] kthread+0x96/0xa0 [ 598.705071] [<ffffffff8160e9d4>] kernel_thread_helper+0x4/0x10 [ 598.705076] [<ffffffff8104bad0>] ? kthread_freezable_should_stop+0x70/0x70 [ 598.705079] [<ffffffff8160e9d0>] ? gs_change+0xb/0xb
