Hi!
Since upgrading from 2.6.35+bits to 2.6.38 and then more recently to 3.0,
our "big btrfs backup box" with 20 * 3 TB AOE-attached btrfs volumes
started showing more CPU usage and backups were no longer completing in a
day. I tried Linus HEAD from yesterday merged with btrfs for-linus (same
as Linus HEAD as of today), and things are better again, but "perf
top"
output still looks pretty interesting after a night of rsync running:
samples pcnt function DSO
_______ _____ __________________________________ ______________
13537.00 59.2% rb_next [kernel]
3539.00 15.5% _raw_spin_lock [kernel]
1668.00 7.3% setup_cluster_no_bitmap [kernel]
799.00 3.5% tree_search_offset [kernel]
476.00 2.1% fill_window [kernel]
370.00 1.6% find_free_extent [kernel]
238.00 1.0% longest_match [kernel]
128.00 0.6% build_tree [kernel]
95.00 0.4% pqdownheap [kernel]
79.00 0.3% chksum_update [kernel]
72.00 0.3% btrfs_find_space_cluster [kernel]
65.00 0.3% deflate_fast [kernel]
61.00 0.3% memcpy [kernel]
With call-graphs enabled:
- 50.24% btrfs-transacti [kernel.kallsyms] [k] rb_next
- rb_next
- 97.36% setup_cluster_no_bitmap
btrfs_find_space_cluster
find_free_extent
btrfs_reserve_extent
btrfs_alloc_free_block
__btrfs_cow_block
+ btrfs_cow_block
- 2.29% btrfs_find_space_cluster
find_free_extent
btrfs_reserve_extent
btrfs_alloc_free_block
__btrfs_cow_block
btrfs_cow_block
- btrfs_search_slot
- 56.96% lookup_inline_extent_backref
- 97.23% __btrfs_free_extent
run_clustered_refs
- btrfs_run_delayed_refs
- 91.23% btrfs_commit_transaction
transaction_kthread
kthread
kernel_thread_helper
- 8.77% btrfs_write_dirty_block_groups
commit_cowonly_roots
btrfs_commit_transaction
transaction_kthread
kthread
kernel_thread_helper
- 2.77% insert_inline_extent_backref
__btrfs_inc_extent_ref
run_clustered_refs
btrfs_run_delayed_refs
btrfs_commit_transaction
transaction_kthread
kthread
kernel_thread_helper
- 41.03% btrfs_insert_empty_items
- 99.89% run_clustered_refs
- btrfs_run_delayed_refs
+ 89.93% btrfs_commit_transaction
+ 10.07% btrfs_write_dirty_block_groups
+ 1.87% btrfs_write_dirty_block_groups
- 7.41% btrfs-transacti [kernel.kallsyms] [k] setup_cluster_no_bitmap
+ setup_cluster_no_bitmap
+ 4.34% rsync [kernel.kallsyms] [k] _raw_spin_lock
+ 3.68% rsync [kernel.kallsyms] [k] rb_next
+ 3.09% btrfs-transacti [kernel.kallsyms] [k] tree_search_offset
+ 1.40% btrfs-delalloc- [kernel.kallsyms] [k] fill_window
+ 1.31% btrfs-transacti [kernel.kallsyms] [k] _raw_spin_lock
+ 1.19% btrfs-delalloc- [kernel.kallsyms] [k] longest_match
+ 1.18% btrfs-delalloc- [kernel.kallsyms] [k] deflate_fast
+ 1.09% btrfs-transacti [kernel.kallsyms] [k] find_free_extent
+ 0.90% btrfs-delalloc- [kernel.kallsyms] [k] pqdownheap
+ 0.67% btrfs-delalloc- [kernel.kallsyms] [k] compress_block
+ 0.66% btrfs-delalloc- [kernel.kallsyms] [k] build_tree
+ 0.61% rsync [kernel.kallsyms] [k] page_fault
rb_next() from setup_cluster_no_bitmap() is very hot. From the
annotated assembly output, it looks like the "while (window_free
<min_bytes)" loop is where the CPU is spending most of the time.
A few thoughts:
Shouldn''t (window_free <= min_bytes) be (window_free <
min_bytes)?
I''m not really up to speed with SMP memory caching behaviour, but
I''m
thinking the constant list creation of bitmap entries from the shared
free_space_cache objects might be helping bounce around these pages
between CPUs, which is why instructions that deference the object
pointers always seem to be cache misses...Or there''s just too much of
this stuff in memory for it to fit in cache. Top of slabtop -sc:
OBJS ACTIVE USE OBJ SIZE SLABS OBJ/SLAB CACHE SIZE NAME
1760061 1706286 96% 0.97K 53351 33 1707232K nfs_inode_cache
1623423 1617242 99% 0.95K 49279 33 1576928K btrfs_inode_cache
788998 676959 85% 0.55K 28204 28 451264K radix_tree_node
1379889 1344544 97% 0.19K 65709 21 262836K dentry
1399100 1248587 89% 0.16K 55964 25 223856K extent_buffers
1077876 1007921 93% 0.11K 29941 36 119764K journal_head
This is all per-blockgroup, but I don''t know how many blockgroups the
thing keeps looking at. There are 20 mounted volumes, as I mentioned.
16 GB of memory, and 4 apparent cores (dual HT Xeon).
The calculation for comparison with max_gap and entry->offset -
window_start > (min_bytes * 2) are also the hot parts of the loop, but
this is not much compared to the initial deference within rb_next() that
pretty much always looks to be a cache miss. It would seem that not
walking so much would be worthwhile, if possible.
So, are all of the gap avoidance and stuff really necessary? I presume
this is to try to avoid fragmentation. Would it make sense to leave some
kind of pointer hanging around pointing to the last useful offset, or
something? (eg: make the block group checking circular instead of walking
the whole thing.) I''m just stabbing in the dark without more counters
to
see what''s really going on here.
I see Josef''s 86d4a77ba3dc4ace238a0556541a41df2bd71d49 introduced the
bitmaps list. I could try temporarily reverting this (some fixups needed)
if anybody thinks my cache bouncing idea might be slightly possible.
Cheers!
Simon-
--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs"
in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
On Wed, Aug 03, 2011 at 03:06:55PM -0700, Simon Kirby wrote:> I see Josef''s 86d4a77ba3dc4ace238a0556541a41df2bd71d49 introduced the > bitmaps list. I could try temporarily reverting this (some fixups needed) > if anybody thinks my cache bouncing idea might be slightly possible.I''ll try the attached and see how the profile changes. Simon-
On Wed, Aug 03, 2011 at 03:39:49PM -0700, Simon Kirby wrote:> On Wed, Aug 03, 2011 at 03:06:55PM -0700, Simon Kirby wrote: > > > I see Josef''s 86d4a77ba3dc4ace238a0556541a41df2bd71d49 introduced the > > bitmaps list. I could try temporarily reverting this (some fixups needed) > > if anybody thinks my cache bouncing idea might be slightly possible. > > I''ll try the attached and see how the profile changes.Hmm, I bound the SMP affinity of all of the btrfs processes to one CPU, and the page dirtying rate got slower, so I suspect the writes aren''t really a big deal, and the problem is just that there is way too much walking going on after rsync has ran for a while and loads everything into memory. Any ideas? Simon- -- To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Excerpts from Simon Kirby''s message of 2011-08-03 19:10:59 -0400:> On Wed, Aug 03, 2011 at 03:39:49PM -0700, Simon Kirby wrote: > > > On Wed, Aug 03, 2011 at 03:06:55PM -0700, Simon Kirby wrote: > > > > > I see Josef''s 86d4a77ba3dc4ace238a0556541a41df2bd71d49 introduced the > > > bitmaps list. I could try temporarily reverting this (some fixups needed) > > > if anybody thinks my cache bouncing idea might be slightly possible. > > > > I''ll try the attached and see how the profile changes. > > Hmm, I bound the SMP affinity of all of the btrfs processes to one CPU, > and the page dirtying rate got slower, so I suspect the writes aren''t > really a big deal, and the problem is just that there is way too much > walking going on after rsync has ran for a while and loads everything > into memory. > > Any ideas?The current for-linus branch gets rid of all the bottlenecks in the metadata blocks. So now we''re stuck with the bottlenecks in the allocator. There are a few simple things we can do here but Josef has a patch that fixes delalloc reservations for inline extents that might help as a first step. -chris -- To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Perhaps as a further clue as to what is going on, on this same backup box after all of the rsyncs are finished/killed and a good amount of time has passed (no cleaner processes running in the background or anything), "sync" is still consistently takes ~4 minutes to run, and pushes out a lot to disk every time it is run. Example: echo 3 > /proc/sys/vm/drop_caches sync echo 3 > /proc/sys/vm/drop_caches sync vmstat 1 & time sync procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu---- r b swpd free buff cache si so bi bo in cs us sy id wa 0 0 68 15656528 3660 258232 0 0 783 673 72 33 3 30 13 54 0 0 68 15656612 3660 258232 0 0 0 0 439 152 0 0 100 0 0 0 68 15656488 3660 258232 0 0 0 0 395 87 0 0 100 0 0 0 68 15656488 3660 258232 0 0 0 0 309 89 0 0 100 0 0 0 68 15655992 3660 258232 0 0 0 0 450 128 0 0 100 0 0 0 68 15655984 3660 258232 0 0 0 0 446 159 0 1 99 0 0 0 68 15655860 3660 258232 0 0 0 0 448 105 0 0 100 0 0 0 68 15655720 3660 258276 0 0 0 0 824 238 1 2 98 0 1 0 68 15651388 3660 258276 0 0 0 0 621 150 2 0 98 0 0 0 68 15655860 3660 258276 0 0 0 44 886 236 2 1 98 0 0 0 68 15656604 3660 258276 0 0 0 0 544 161 0 1 99 0 0 0 68 15656612 3660 258276 0 0 0 0 616 328 0 1 99 0 <sync started here> 0 2 68 15655764 3660 258420 0 0 328 607 1777 1450 0 1 74 25 0 1 68 15654648 3660 259968 0 0 752 0 1978 1519 0 1 66 33 0 1 68 15654028 3660 260520 0 0 616 0 1498 1186 0 0 75 25 0 1 68 15653556 3660 260992 0 0 220 1545 1878 1937 0 1 75 24 1 0 68 15652288 3660 262540 0 0 392 1976 2990 3072 0 4 75 21 1 0 68 15652252 3660 262496 0 0 0 0 2848 164 0 27 73 0 1 0 68 15652260 3660 262496 0 0 0 0 2586 86 0 26 74 0 1 0 68 15652260 3660 262496 0 0 0 0 2591 148 0 25 75 0 1 0 68 15652136 3660 262496 0 0 0 0 2544 98 0 24 76 0 1 0 68 15652136 3660 262496 0 0 0 0 2518 75 0 26 74 0 1 0 68 15652136 3660 262496 0 0 0 0 2676 105 0 25 75 0 1 0 68 15652136 3660 262496 0 0 0 0 2531 83 0 25 75 0 1 0 68 15652136 3660 262496 0 0 0 0 2595 81 0 25 75 0 1 0 68 15652136 3660 262496 0 0 0 0 2570 89 0 25 75 0 1 0 68 15652136 3660 262496 0 0 0 0 2539 76 0 25 75 0 1 0 68 15652004 3660 262540 0 0 0 0 2914 166 0 25 74 0 1 0 68 15652012 3660 262540 0 0 0 0 2596 87 0 25 75 0 1 0 68 15652012 3660 262540 0 0 0 0 2591 82 0 25 75 0 1 0 68 15652012 3660 262540 0 0 0 0 2607 90 0 25 75 0 1 0 68 15652012 3660 262540 0 0 0 0 2535 89 0 25 75 0 1 0 68 15652012 3660 262540 0 0 0 0 2629 109 0 26 74 0 1 0 68 15652012 3660 262540 0 0 0 0 2549 81 0 25 75 0 1 0 68 15652012 3660 262540 0 0 0 0 2757 230 0 26 73 0 1 0 68 15652012 3660 262540 0 0 0 0 2571 105 0 24 76 0 1 0 68 15652012 3660 262540 0 0 0 0 2568 96 0 26 74 0 1 0 68 15651880 3660 262584 0 0 0 0 2930 173 0 28 72 0 1 0 68 15651888 3660 262584 0 0 0 0 2564 79 0 26 74 0 1 0 68 15651888 3660 262584 0 0 0 0 2594 84 0 22 78 0 1 0 68 15651888 3660 262584 0 0 0 0 2568 96 0 25 75 0 1 0 68 15651888 3660 262584 0 0 0 0 2578 91 0 25 75 0 1 0 68 15651888 3660 262584 0 0 0 0 2660 104 0 26 74 0 1 0 68 15651888 3660 262584 0 0 0 0 2537 84 0 25 75 0 1 0 68 15651888 3660 262584 0 0 0 0 2553 82 0 25 75 0 1 0 68 15651888 3660 262584 0 0 0 39 2808 204 0 26 74 0 1 0 68 15651888 3660 262584 0 0 0 0 2573 91 0 25 75 0 1 0 68 15651756 3660 262628 0 0 0 44 2868 153 1 29 71 0 1 0 68 15651764 3660 262628 0 0 0 0 2569 79 0 23 76 0 1 0 68 15651764 3660 262628 0 0 0 0 2587 79 0 27 73 0 1 0 68 15651764 3660 262628 0 0 0 0 2509 73 0 23 77 0 1 0 68 15651764 3660 262628 0 0 0 0 2520 81 0 25 75 0 1 0 68 15651764 3660 262628 0 0 0 0 2664 97 0 25 75 0 1 0 68 15651740 3660 262628 0 0 112 0 2680 146 0 25 75 0 1 0 68 15651640 3660 262740 0 0 0 0 2627 79 0 25 75 0 1 0 68 15651640 3660 262740 0 0 0 0 2534 83 0 25 75 0 1 0 68 15651640 3660 262740 0 0 0 0 2525 85 0 25 75 0 1 0 68 15651756 3660 262784 0 0 0 44 3059 307 0 27 72 0 1 0 68 15651764 3660 262784 0 0 0 0 2593 73 0 29 71 0 1 0 68 15651764 3660 262784 0 0 0 0 2573 82 0 22 78 0 1 0 68 15651764 3660 262784 0 0 0 0 2567 84 0 26 74 0 1 0 68 15651764 3660 262784 0 0 0 0 2577 90 0 25 75 0 1 0 68 15651764 3660 262784 0 0 0 0 2675 86 0 25 75 0 1 0 68 15651764 3660 262784 0 0 0 0 2577 91 0 25 75 0 1 0 68 15651764 3660 262784 0 0 0 0 2610 86 0 25 75 0 1 0 68 15651764 3660 262784 0 0 0 0 2558 88 0 25 75 0 1 0 68 15651764 3660 262784 0 0 0 0 2537 83 0 25 75 0 1 0 68 15651252 3660 262832 0 0 0 44 2959 181 0 26 74 0 1 0 68 15651268 3660 262832 0 0 0 0 2572 88 0 25 75 0 1 0 68 15651764 3660 262832 0 0 0 0 3136 138 3 25 72 0 1 0 68 15651764 3660 262832 0 0 0 0 2525 70 0 29 71 0 1 0 68 15651764 3660 262832 0 0 0 0 2584 96 0 22 78 0 1 0 68 15651640 3660 262832 0 0 0 0 2703 106 0 25 75 0 1 0 68 15651640 3660 262832 0 0 0 0 2572 101 0 25 75 0 1 0 68 15651516 3660 262832 0 0 0 0 2588 75 0 25 75 0 procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu---- r b swpd free buff cache si so bi bo in cs us sy id wa 2 0 68 15651516 3660 262832 0 0 0 79 2624 110 0 25 75 0 1 0 68 15651516 3660 262832 0 0 0 0 2555 85 0 25 75 0 1 0 68 15651136 3660 262876 0 0 0 44 2858 159 0 25 74 0 1 0 68 15651144 3660 262876 0 0 0 0 2560 86 0 25 75 0 1 0 68 15651144 3660 262876 0 0 0 0 2643 138 0 25 75 0 1 0 68 15651020 3660 262876 0 0 0 0 2818 291 0 26 74 0 1 0 68 15651020 3660 262876 0 0 0 0 2542 89 0 25 75 0 1 0 68 15650896 3660 262876 0 0 0 0 2645 111 0 25 75 0 1 0 68 15650896 3660 262876 0 0 0 0 2535 87 0 25 75 0 1 0 68 15650896 3660 262876 0 0 0 0 2562 84 0 25 75 0 1 0 68 15650896 3660 262876 0 0 0 0 2533 85 0 25 75 0 1 0 68 15650896 3660 262876 0 0 0 0 2534 92 0 25 75 0 1 0 68 15650888 3660 262920 0 0 0 44 2881 158 0 26 74 0 1 0 68 15650772 3660 262920 0 0 0 0 2585 84 0 25 75 0 1 0 68 15650772 3660 262920 0 0 0 0 2590 82 0 25 75 0 1 0 68 15650772 3660 262920 0 0 0 0 2565 73 0 25 75 0 1 0 68 15650772 3660 262920 0 0 0 0 2577 82 0 25 75 0 1 0 68 15650772 3660 262920 0 0 0 0 2655 102 0 25 75 0 1 0 68 15650772 3660 262920 0 0 0 0 2548 87 0 25 75 0 1 0 68 15650772 3660 262920 0 0 0 0 2569 80 0 29 71 0 1 0 68 15650648 3660 262920 0 0 0 0 2569 83 0 22 78 0 1 0 68 15650648 3660 262920 0 0 0 0 2574 92 0 25 75 0 1 0 68 15650516 3660 262964 0 0 0 0 2944 155 0 26 73 0 1 0 68 15650524 3660 262964 0 0 0 0 2555 98 0 25 75 0 1 0 68 15650524 3660 262964 0 0 0 0 2584 98 0 25 75 0 1 0 68 15650524 3660 262964 0 0 0 0 2549 84 0 25 75 0 1 0 68 15650524 3660 262964 0 0 0 0 2549 85 0 25 75 0 1 0 68 15650400 3660 262964 0 0 0 56 2694 102 0 25 75 0 2 0 68 15650400 3660 262964 0 0 0 0 2650 157 0 25 75 0 1 0 68 15650400 3660 262964 0 0 0 0 2717 220 0 26 74 0 1 0 68 15650400 3660 262964 0 0 0 53 2588 106 0 25 75 0 1 0 68 15650400 3660 262964 0 0 0 0 2574 75 0 25 75 0 1 0 68 15650516 3660 263008 0 0 0 44 3056 247 1 27 73 0 1 0 68 15650524 3660 263008 0 0 0 0 2530 95 0 26 74 0 1 0 68 15650400 3660 263008 0 0 0 0 2570 83 0 24 76 0 1 0 68 15650400 3660 263008 0 0 0 0 2538 81 0 27 73 0 1 0 68 15650400 3660 263008 0 0 0 0 2545 87 0 23 77 0 1 0 68 15650400 3660 263008 0 0 0 0 2661 99 0 26 74 0 1 0 68 15650400 3660 263008 0 0 0 0 2568 79 0 25 75 0 1 0 68 15650400 3660 263008 0 0 0 0 2551 72 0 25 75 0 1 0 68 15650400 3660 263008 0 0 0 0 2537 83 0 25 75 0 1 0 68 15650276 3660 263008 0 0 0 0 2539 98 0 25 75 0 1 0 68 15650144 3660 263052 0 0 0 44 2868 163 0 25 74 0 1 0 68 15650152 3660 263052 0 0 0 0 2572 82 0 25 75 0 1 0 68 15650152 3660 263052 0 0 0 0 2579 85 0 25 75 0 0 2 68 15648672 3660 263052 0 0 0 776 2510 359 0 21 69 10 0 2 68 15648680 3660 263052 0 0 0 2728 3182 3256 0 1 62 37 0 2 68 15648804 3660 263052 0 0 0 2608 3274 3240 0 0 64 36 0 2 68 15648804 3660 263052 0 0 0 4140 4235 4838 0 1 63 36 0 2 68 15648804 3660 263052 0 0 0 3056 3958 3869 0 1 51 48 0 2 68 15648804 3660 263052 0 0 0 3792 4189 4663 0 0 50 50 0 2 68 15648804 3660 263052 0 0 0 4880 5483 6341 0 1 52 47 0 2 68 15649028 3668 263100 0 0 8 4300 5806 5987 2 6 51 42 0 2 68 15648648 3668 263100 0 0 0 5016 6278 6481 4 1 51 43 0 2 68 15648680 3668 263100 0 0 0 4712 5037 5670 0 1 50 50 1 2 68 15648804 3668 263100 0 0 0 8432 7785 10086 0 1 57 42 0 2 68 15649052 3668 263100 0 0 0 10256 8857 11715 0 2 54 44 1 0 68 15650416 3684 263092 0 0 0 9344 9150 11329 0 11 64 25 1 0 68 15650556 3684 263100 0 0 0 0 2597 87 0 28 72 0 1 0 68 15650556 3684 263100 0 0 0 0 2584 85 0 26 74 0 1 0 68 15650556 3684 263100 0 0 0 105 2627 178 0 23 77 0 1 0 68 15650556 3684 263100 0 0 0 0 2573 107 0 24 76 0 1 0 68 15650548 3684 263144 0 0 0 44 2856 164 0 25 74 0 1 0 68 15650556 3684 263144 0 0 0 0 2538 85 0 27 73 0 1 0 68 15650556 3684 263144 0 0 0 0 2650 90 0 27 73 0 1 0 68 15650680 3684 263144 0 0 0 0 2682 186 0 22 78 0 1 0 68 15650080 3684 263144 0 0 0 0 2794 193 0 25 75 0 1 0 68 15649664 3684 263144 0 0 0 0 3080 253 1 25 74 0 1 0 68 15649804 3684 263144 0 0 0 0 2529 84 0 25 75 0 1 0 68 15649804 3684 263144 0 0 0 0 2558 79 0 25 75 0 1 0 68 15649804 3684 263144 0 0 0 0 2548 80 0 25 75 0 1 0 68 15649740 3684 263144 0 0 0 0 2648 141 0 25 75 0 1 0 68 15649548 3684 263188 0 0 0 44 3198 507 0 28 72 0 1 0 68 15649132 3688 263184 0 0 124 0 2966 291 0 25 74 0 1 0 68 15649292 3688 263308 0 0 0 0 2984 144 1 26 74 0 procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu---- r b swpd free buff cache si so bi bo in cs us sy id wa 3 0 68 15649184 3688 263308 0 0 0 0 3593 237 0 35 65 0 2 0 68 15649184 3688 263308 0 0 0 16 5052 83 0 50 50 0 2 0 68 15649152 3688 263308 0 0 0 0 5313 159 1 51 48 0 2 0 68 15649028 3688 263308 0 0 0 0 5908 702 2 52 47 0 4 0 68 15648948 3696 263300 0 0 0 32 5836 861 2 53 45 0 2 0 68 15643968 3696 263308 0 0 0 0 5901 293 6 52 42 0 2 0 68 15643976 3696 263308 0 0 0 0 5016 87 0 50 50 0 2 0 68 15643968 3696 263352 0 0 0 48 5285 145 0 51 49 0 2 0 68 15643976 3696 263352 0 0 0 0 4956 79 0 50 50 0 2 0 68 15643976 3696 263352 0 0 0 0 4994 85 0 50 50 0 2 0 68 15643976 3704 263344 0 0 0 32 5014 91 0 50 50 0 2 0 68 15643976 3704 263352 0 0 0 0 5016 77 0 50 50 0 2 0 68 15643976 3704 263352 0 0 0 0 5070 90 0 51 49 0 2 0 68 15643976 3704 263352 0 0 0 0 5011 83 0 50 50 0 2 0 68 15643976 3704 263352 0 0 0 0 4961 84 0 49 51 0 2 0 68 15650176 3704 263352 0 0 0 62 5005 120 0 50 50 0 2 0 68 15650184 3704 263352 0 0 0 0 4949 85 0 51 49 0 2 0 68 15650052 3704 263396 0 0 0 60 5238 142 0 51 48 0 2 0 68 15649812 3704 263396 0 0 0 0 5086 175 0 50 50 0 2 0 68 15649812 3704 263396 0 0 0 0 4961 75 0 51 49 0 2 0 68 15649812 3704 263396 0 0 0 0 4995 75 0 50 50 0 2 0 68 15649812 3704 263396 0 0 0 0 4880 79 0 51 49 0 2 0 68 15649812 3704 263396 0 0 0 4 5054 96 0 50 50 0 2 0 68 15649812 3704 263396 0 0 0 0 5102 202 0 53 47 0 2 0 68 15649812 3704 263396 0 0 0 0 5002 74 0 50 50 0 2 0 68 15649812 3704 263396 0 0 0 208 5023 91 0 50 50 0 2 0 68 15649688 3704 263396 0 0 0 0 4991 85 0 50 50 0 2 0 68 15649400 3704 263440 0 0 0 0 5304 209 0 51 49 0 2 0 68 15649440 3704 263440 0 0 0 0 5002 70 0 50 50 0 2 0 68 15649440 3704 263440 0 0 0 0 4956 78 0 50 50 0 2 0 68 15649440 3704 263440 0 0 0 0 5012 82 0 50 50 0 2 0 68 15649440 3704 263440 0 0 0 16 4926 86 0 50 50 0 2 0 68 15649316 3704 263440 0 0 0 44 5082 94 0 50 50 0 2 0 68 15649316 3704 263440 0 0 0 0 4935 81 0 50 50 0 2 0 68 15649316 3704 263440 0 0 0 0 5055 90 0 50 50 0 2 0 68 15649316 3704 263440 0 0 0 0 4931 80 0 50 50 0 2 0 68 15649316 3704 263440 0 0 0 0 5078 89 0 50 50 0 2 0 68 15649052 3704 263488 0 0 0 68 5291 168 0 51 49 0 2 0 68 15648920 3704 263488 0 0 0 0 5404 126 3 50 47 0 2 0 68 15649068 3704 263488 0 0 0 0 4903 81 0 50 50 0 2 0 68 15649068 3704 263488 0 0 0 8 5024 81 0 50 50 0 2 0 68 15649068 3704 263488 0 0 0 0 5029 81 0 50 50 0 2 0 68 15649068 3704 263488 0 0 0 0 5130 118 0 50 50 0 2 0 68 15649068 3704 263488 0 0 0 0 5062 79 0 50 50 0 2 2 68 15648512 3704 263488 0 0 0 656 5137 114 0 50 47 2 2 2 68 15648896 3704 263488 0 0 0 4782 6934 5075 0 26 40 34 1 2 68 15648928 3704 263488 0 0 0 5580 7916 6711 0 27 39 34 1 2 68 15648920 3704 263532 0 0 0 6880 8815 7614 0 27 33 39 1 2 68 15648928 3704 263532 0 0 0 6252 8454 7160 0 26 32 43 1 2 68 15648928 3704 263532 0 0 0 4136 6695 4881 0 25 34 41 1 2 68 15648928 3704 263532 0 0 0 5136 7219 5559 0 26 31 43 1 2 68 15648928 3704 263532 0 0 0 5572 7200 5775 0 26 30 44 2 0 68 15648844 3704 263884 0 0 92 1944 5819 3102 0 34 48 18 2 0 68 15649068 3704 263828 0 0 0 0 5013 77 0 50 50 0 2 0 68 15649068 3704 263828 0 0 0 0 4954 92 0 50 50 0 2 0 68 15649068 3704 263828 0 0 0 0 5015 85 0 50 50 0 2 0 68 15649068 3704 263828 0 0 0 0 5008 72 0 50 50 0 2 0 68 15649184 3704 263872 0 0 0 44 5233 153 1 51 49 0 2 0 68 15649068 3704 263872 0 0 0 0 5010 93 0 50 50 0 2 0 68 15649068 3704 263872 0 0 0 0 5065 83 0 50 50 0 2 0 68 15648944 3704 263872 0 0 0 0 4985 76 0 50 50 0 2 0 68 15648820 3704 263872 0 0 0 0 4964 80 0 50 50 0 2 0 68 15648820 3704 263872 0 0 0 0 5067 112 0 50 50 0 2 0 68 15648572 3704 263872 0 0 0 0 4999 85 0 50 50 0 2 0 68 15648572 3704 263872 0 0 0 0 4989 71 0 50 50 0 2 0 68 15648448 3704 263872 0 0 0 0 4926 82 0 50 50 0 2 0 68 15648324 3704 263872 0 0 0 0 4972 87 0 50 50 0 2 2 68 15646872 3704 263916 0 0 0 3148 5919 2947 0 30 32 37 1 2 68 15646944 3704 263916 0 0 0 3548 6195 4149 0 26 39 35 1 2 68 15646944 3704 263916 0 0 0 2244 5206 2890 0 27 34 39 1 2 68 15646944 3704 263916 0 0 0 3024 5736 3625 0 26 33 42 1 2 68 15646944 3704 263916 0 0 0 3144 5638 3633 0 26 29 45 1 2 68 15646944 3704 263916 0 0 0 2600 5400 3222 0 25 29 46 1 2 68 15646944 3704 263916 0 0 0 3264 5927 3960 0 26 36 38 3 2 68 15646944 3704 263916 0 0 0 5904 8307 7033 0 28 28 44 procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu---- r b swpd free buff cache si so bi bo in cs us sy id wa 3 2 68 15646944 3704 263916 0 0 0 4945 8941 4388 0 50 13 37 4 2 68 15646944 3704 263916 0 0 0 4976 8981 4674 0 51 12 37 2 2 68 15646564 3704 263960 0 0 0 4756 9027 4543 0 51 19 30 3 2 68 15646816 3704 263960 0 0 0 10248 11107 6925 0 51 12 36 2 2 68 15647068 3704 263960 0 0 0 5480 9019 4345 0 51 11 37 3 0 68 15647944 3704 263960 0 0 0 952 7274 1747 0 61 22 17 3 0 68 15647952 3704 264004 0 0 0 0 7166 75 0 75 25 0 3 0 68 15647952 3704 264004 0 0 0 0 7185 98 0 75 25 0 3 0 68 15647952 3704 264004 0 0 0 0 7118 72 0 75 25 0 3 0 68 15647952 3704 264004 0 0 0 0 7144 74 0 75 25 0 3 0 68 15647952 3704 264004 0 0 0 0 7124 78 0 75 25 0 3 0 68 15647952 3704 264004 0 0 0 0 7118 84 0 75 25 0 3 0 68 15647944 3704 264048 0 0 0 44 7249 140 0 76 24 0 3 0 68 15647952 3704 264048 0 0 0 0 7149 76 0 75 25 0 3 0 68 15647952 3704 264048 0 0 0 0 7144 77 0 75 25 0 3 0 68 15647952 3704 264048 0 0 0 16 7125 88 0 75 25 0 3 0 68 15647952 3704 264048 0 0 0 0 7153 74 0 75 25 0 3 0 68 15647828 3704 264048 0 0 0 0 7288 199 0 76 24 0 3 0 68 15647828 3704 264048 0 0 0 0 7169 89 0 75 25 0 3 0 68 15647580 3704 264048 0 0 0 0 7168 82 0 75 25 0 2 2 68 15647572 3704 264048 0 0 0 4240 8458 3963 0 53 19 27 2 2 68 15647696 3704 264048 0 0 0 3784 8568 4128 0 51 14 36 2 0 68 15647680 3704 264096 0 0 0 4432 8868 4449 0 55 15 29 2 0 68 15647936 3704 264096 0 0 0 0 5447 130 3 50 47 0 2 0 68 15647960 3704 264096 0 0 0 0 4989 79 0 53 47 0 2 0 68 15647960 3704 264096 0 0 0 0 5003 81 0 48 52 0 2 0 68 15647960 3704 264096 0 0 0 0 5015 181 0 53 47 0 2 0 68 15647960 3704 264096 0 0 0 8 5107 139 0 47 53 0 2 0 68 15647960 3704 264096 0 0 0 0 5046 178 0 50 50 0 2 0 68 15647712 3704 264096 0 0 0 0 4997 84 0 50 50 0 2 0 68 15647712 3704 264096 0 0 0 54 5098 163 0 52 48 0 2 0 68 15647712 3704 264096 0 0 0 0 4978 104 0 50 50 0 2 0 68 15648076 3704 264140 0 0 0 44 5260 141 1 50 49 0 2 0 68 15648084 3704 264140 0 0 0 0 4957 84 0 51 50 0 2 0 68 15648084 3704 264140 0 0 0 0 5052 181 0 50 50 0 2 0 68 15647836 3704 264140 0 0 0 0 5063 133 0 50 50 0 1 2 68 15646464 3704 264140 0 0 0 3992 6813 3727 0 33 34 33 1 2 68 15646340 3704 264140 0 0 0 5668 8204 6632 0 26 36 38 1 2 68 15646332 3704 264140 0 0 0 7140 8842 7701 0 26 31 43 2 2 68 15646332 3704 264140 0 0 0 7972 9638 9240 0 26 34 41 1 2 68 15646332 3704 264140 0 0 0 9224 10442 9945 0 29 29 42 1 2 68 15646332 3704 264140 0 0 0 4684 6481 4572 0 26 43 31 3 2 68 15646448 3704 264184 0 0 0 2136 5114 2539 0 26 37 36 1 2 68 15646456 3704 264184 0 0 0 3292 5654 3349 0 26 43 31 1 2 68 15646456 3704 264184 0 0 0 2848 5365 3155 0 25 29 46 1 2 68 15646456 3704 264184 0 0 0 3936 6192 4294 0 26 30 45 2 2 68 15646952 3704 264184 0 0 0 5784 7514 6012 0 26 28 46 1 2 68 15647076 3704 264184 0 0 0 3900 6474 4544 0 26 36 39 <sync finishes around here> 1 0 68 15647836 3704 264184 0 0 0 3424 6108 4457 0 27 45 27 1 0 68 15647960 3704 264184 0 0 0 0 2560 76 0 29 71 0 1 0 68 15647960 3704 264184 0 0 0 0 2607 107 0 22 78 0 1 0 68 15647960 3704 264184 0 0 0 0 2571 90 0 28 72 0 1 0 68 15647952 3704 264228 0 0 0 48 2943 175 0 23 76 0 1 0 68 15647960 3704 264228 0 0 0 0 2552 73 0 29 71 0 1 0 68 15647960 3704 264228 0 0 0 0 2591 95 0 22 78 0 1 0 68 15647960 3704 264228 0 0 0 0 2570 84 0 25 75 0 1 0 68 15647960 3704 264228 0 0 0 0 2602 98 0 25 75 0 1 0 68 15647960 3704 264228 0 0 0 0 2672 83 0 25 75 0 1 0 68 15647960 3704 264228 0 0 0 0 2815 113 0 25 75 0 1 0 68 15647960 3704 264228 0 0 0 0 2623 93 0 25 75 0 1 0 68 15647960 3704 264228 0 0 0 53 2628 121 0 25 75 0 1 0 68 15648084 3704 264228 0 0 0 0 2604 89 0 26 74 0 1 0 68 15648200 3704 264272 0 0 0 44 2868 154 0 26 74 0 1 0 68 15648208 3704 264272 0 0 0 0 2737 215 0 26 74 0 0 2 68 15648128 3704 264272 0 0 0 2084 2682 1967 0 5 55 40 0 2 68 15648128 3704 264272 0 0 0 3936 4635 4782 0 2 49 50 0 2 68 15648128 3704 264272 0 0 0 3552 4006 4310 0 1 49 50 0 2 68 15648128 3704 264272 0 0 0 4244 4798 5309 0 1 50 50 0 2 68 15648128 3704 264272 0 0 0 5988 6143 7430 0 1 50 49 0 2 68 15648128 3704 264272 0 0 0 7480 7222 8853 0 2 61 37 0 2 68 15648128 3704 264272 0 0 0 6756 6671 8141 0 2 60 39 0 0 68 15649128 3704 264272 0 0 0 6356 6545 8209 0 1 61 38 0 0 68 15649128 3704 264316 0 0 0 44 645 161 0 1 99 0 0 0 68 15649136 3704 264316 0 0 0 0 334 71 0 0 100 0 0 0 68 15649136 3704 264316 0 0 0 0 367 83 0 0 100 0 procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu---- r b swpd free buff cache si so bi bo in cs us sy id wa 1 0 68 15649136 3704 264316 0 0 0 16 319 87 0 0 100 0 0 0 68 15649136 3704 264316 0 0 0 0 382 100 0 0 100 0 0 0 68 15649136 3704 264316 0 0 0 0 449 76 0 0 100 0 0 0 68 15649136 3704 264316 0 0 0 0 348 90 0 0 100 0 0 0 68 15649136 3704 264316 0 0 0 0 411 87 0 0 100 0 0 0 68 15649136 3704 264316 0 0 0 0 357 91 0 0 100 0 1 0 68 15649384 3704 264316 0 0 0 0 401 97 0 0 100 0 0 0 68 15649136 3704 264368 0 0 0 0 311 79 0 0 100 0 0 0 68 15649128 3704 264368 0 0 0 0 410 88 0 0 100 0 Nothing (other than "sync") was writing during this time, all cleaner processes were idle. I tried to umount -t btrfs -a and after "umount" finally finishes, mounting them again is normal and umounts immediately after are instantaneous. Simon- -- To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Excerpts from Simon Kirby''s message of 2011-08-03 21:32:10 -0400:> Perhaps as a further clue as to what is going on, on this same backup box > after all of the rsyncs are finished/killed and a good amount of time has > passed (no cleaner processes running in the background or anything), > "sync" is still consistently takes ~4 minutes to run, and pushes out a > lot to disk every time it is run. Example: > > echo 3 > /proc/sys/vm/drop_caches > sync > echo 3 > /proc/sys/vm/drop_caches > sync > vmstat 1 & > time syncJust to confirm, the profiling during this time shows your system time is all in rb_next? -chris -- To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Thu, Aug 04, 2011 at 10:04:29AM -0400, Chris Mason wrote:> Excerpts from Simon Kirby''s message of 2011-08-03 21:32:10 -0400: > > Perhaps as a further clue as to what is going on, on this same backup box > > after all of the rsyncs are finished/killed and a good amount of time has > > passed (no cleaner processes running in the background or anything), > > "sync" is still consistently takes ~4 minutes to run, and pushes out a > > lot to disk every time it is run. Example: > > > > echo 3 > /proc/sys/vm/drop_caches > > sync > > echo 3 > /proc/sys/vm/drop_caches > > sync > > vmstat 1 & > > time sync > > Just to confirm, the profiling during this time shows your system time > is all in rb_next?Correct, rb_next() called from setup_cluster_no_bitmap(). Also, much of the other CPU time is spent spinning (on refill_lock, I think). It''s in this state again now (just one overnight backup run does it). It doesn''t seem to happen for the first few hours, but shows up by the next morning. Simon- -- To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html