On Mon, 20 Jun 2011 20:12:16 -0400, Josef Bacik wrote:
On 06/20/2011 05:51 PM, Henning Rohlfs wrote:
Hello,
I've migrated my system to btrfs (raid1) a few months ago. Since
then
the performance has been pretty bad, but recently it's gotten
unbearable: a simple sync called while the system is idle can take
20 up
to 60 seconds. Creating or deleting files often has several seconds
latency, too.
One curious - but maybe unrelated - observation is that even though
I'm
using a raid1 btrfs setup, the hdds are often being written to
sequentially. One hard-drive sees some write activity and after it
subsides, the other drive sees some activity. (See attached
sequential-writes.txt.)
Can you do sysrq+w while this is happening so we can see who is doing
the writing? Thanks,
Josef
When I call sync, it starts with several seconds of 100% (one core) cpu
usage by sync itself. Afterwards btrfs-submit-0 and sync are blocked.
sysrq+w output is attached.SysRq : Show Blocked State
task PC stack pid father
btrfs-submit-0 D ffff88021c8bbf00 0 851 2 0x00000000
ffff880245b07b20 0000000000000046 0000000000000048 ffff880245b06010
ffff880246ce2b80 0000000000011340 ffff880245b07fd8 0000000000004000
ffff880245b07fd8 0000000000011340 ffff88021f2d95c0 ffff880246ce2b80
Call Trace:
[<ffffffff81333f7a>] ? put_device+0x12/0x14
[<ffffffff81343af6>] ? scsi_request_fn+0x341/0x40d
[<ffffffff812a4643>] ? __blk_run_queue+0x16/0x18
[<ffffffff814fdc2f>] io_schedule+0x51/0x66
[<ffffffff812a6bd9>] get_request_wait+0xa1/0x12f
[<ffffffff81050c85>] ? wake_up_bit+0x25/0x25
[<ffffffff812a3585>] ? elv_merge+0x99/0xa9
[<ffffffff812a6dee>] __make_request+0x187/0x27f
[<ffffffff812a540f>] generic_make_request+0x229/0x2a4
[<ffffffff812a5553>] submit_bio+0xc9/0xe8
[<ffffffff81267b24>] run_scheduled_bios+0x296/0x415
[<ffffffff81044692>] ? del_timer+0x83/0x83
[<ffffffff81267cb3>] pending_bios_fn+0x10/0x12
[<ffffffff8126d591>] worker_loop+0x189/0x4b7
[<ffffffff8126d408>] ? btrfs_queue_worker+0x263/0x263
[<ffffffff8126d408>] ? btrfs_queue_worker+0x263/0x263
[<ffffffff810508bc>] kthread+0x7d/0x85
[<ffffffff81500c94>] kernel_thread_helper+0x4/0x10
[<ffffffff8105083f>] ? kthread_worker_fn+0x13a/0x13a
[<ffffffff81500c90>] ? gs_change+0xb/0xb
sync D 0000000102884001 0 22091 19401 0x00000000
ffff88019f0edc98 0000000000000086 ffff880100000000 ffff88019f0ec010
ffff880227808000 0000000000011340 ffff88019f0edfd8 0000000000004000
ffff88019f0edfd8 0000000000011340 ffffffff8181f020 ffff880227808000
Call Trace:
[<ffffffff810b189b>] ? add_partial+0x1b/0x64
[<ffffffff810b36d6>] ? kmem_cache_free+0x8e/0x93
[<ffffffff812623ad>] ? free_extent_state+0x43/0x47
[<ffffffff81086c2b>] ? __lock_page+0x68/0x68
[<ffffffff814fdc2f>] io_schedule+0x51/0x66
[<ffffffff81086c34>] sleep_on_page+0x9/0xd
[<ffffffff814fe32c>] __wait_on_bit+0x43/0x76
[<ffffffff81086df3>] wait_on_page_bit+0x6d/0x74
[<ffffffff81050cb9>] ? autoremove_wake_function+0x34/0x34
[<ffffffff81086b0e>] ? find_get_page+0x19/0x66
[<ffffffff81247d60>] btrfs_wait_marked_extents+0xeb/0x124
[<ffffffff81247ee6>] btrfs_write_and_wait_marked_extents+0x2a/0x3c
[<ffffffff81247f3a>] btrfs_write_and_wait_transaction+0x42/0x44
[<ffffffff81248676>] btrfs_commit_transaction+0x53c/0x650
[<ffffffff81050c85>] ? wake_up_bit+0x25/0x25
[<ffffffff810db775>] ? __sync_filesystem+0x75/0x75
[<ffffffff8122a33a>] btrfs_sync_fs+0x66/0x6b
[<ffffffff810db761>] __sync_filesystem+0x61/0x75
[<ffffffff810db786>] sync_one_sb+0x11/0x13
[<ffffffff810bc89c>] iterate_supers+0x67/0xbd
[<ffffffff810db7c8>] sys_sync+0x40/0x57
[<ffffffff814fff7b>] system_call_fastpath+0x16/0x1b
Sched Debug Version: v0.10, 2.6.39 #3
ktime : 141912370.788052
sched_clk : 141831001.710073
cpu_clk : 141912370.788875
jiffies : 4337451011
sched_clock_stable : 0
sysctl_sched
.sysctl_sched_latency : 12.000000
.sysctl_sched_min_granularity : 1.500000
.sysctl_sched_wakeup_granularity : 2.000000
.sysctl_sched_child_runs_first : 0
.sysctl_sched_features : 7279
.sysctl_sched_tunable_scaling : 1 (logaritmic)
cpu#0, 2009.138 MHz
.nr_running : 0
.load : 0
.nr_switches : 145331671
.nr_load_updates : 14210439
.nr_uninterruptible : 0
.next_balance : 4337.451012
.curr->pid : 0
.clock : 141912370.762325
.cpu_load[0] : 0
.cpu_load[1] : 0
.cpu_load[2] : 14
.cpu_load[3] : 87
.cpu_load[4] : 139
.yld_count : 20406719
.sched_switch : 0
.sched_count : 167876926
.sched_goidle : 51210495
.avg_idle : 835252
.ttwu_count : 78324179
.ttwu_local : 51824984
.bkl_count : 0
cfs_rq[0]:/autogroup-49
.exec_clock : 422553.128760
.MIN_vruntime : 0.000001
.min_vruntime : 321772.360035
.max_vruntime : 0.000001
.spread : 0.000000
.spread0 : -44285292.572040
.nr_spread_over : 229
.nr_running : 0
.load : 0
.load_avg : 167.025784
.load_period : 6.022728
.load_contrib : 27
.load_tg : 27
.se->exec_start : 141912368.437919
.se->vruntime : 44607059.310813
.se->sum_exec_runtime : 422561.882460
.se->statistics.wait_start : 0.000000
.se->statistics.sleep_start : 0.000000
.se->statistics.block_start : 0.000000
.se->statistics.sleep_max : 0.000000
.se->statistics.block_max : 0.000000
.se->statistics.exec_max : 51.388441
.se->statistics.slice_max : 25.949119
.se->statistics.wait_max : 65.392792
.se->statistics.wait_sum : 156059.730060
.se->statistics.wait_count : 4204371
.se->load.weight : 2
cfs_rq[0]:/autogroup-40
.exec_clock : 605168.668669
.MIN_vruntime : 0.000001
.min_vruntime : 605161.611298
.max_vruntime : 0.000001
.spread : 0.000000
.spread0 : -44001903.381029
.nr_spread_over : 3
.nr_running : 0
.load : 0
.load_avg : 39.999996
.load_period : 5.926694
.load_contrib : 6
.load_tg : 180
.se->exec_start : 141912331.697676
.se->vruntime : 44607058.841296
.se->sum_exec_runtime : 605171.006071
.se->statistics.wait_start : 0.000000
.se->statistics.sleep_start : 0.000000
.se->statistics.block_start : 0.000000
.se->statistics.sleep_max : 0.000000
.se->statistics.block_max : 0.000000
.se->statistics.exec_max : 41.311985
.se->statistics.slice_max : 64.763488
.se->statistics.wait_max : 277.272092
.se->statistics.wait_sum : 85941.008888
.se->statistics.wait_count : 3857989
.se->load.weight : 2
cfs_rq[0]:/autogroup-6606
.exec_clock : 390924.295583
.MIN_vruntime : 0.000001
.min_vruntime : 390385.678251
.max_vruntime : 0.000001
.spread : 0.000000
.spread0 : -44216679.314076
.nr_spread_over : 21
.nr_running : 0
.load : 0
.load_avg : 36.783281
.load_period : 6.071262
.load_contrib : 6
.load_tg : 13
.se->exec_start : 141912362.779247
.se->vruntime : 44607059.020711
.se->sum_exec_runtime : 390925.810660
.se->statistics.wait_start : 0.000000
.se->statistics.sleep_start : 0.000000
.se->statistics.block_start : 0.000000
.se->statistics.sleep_max : 0.000000
.se->statistics.block_max : 0.000000
.se->statistics.exec_max : 6.906599
.se->statistics.slice_max : 57.161522
.se->statistics.wait_max : 32.987270
.se->statistics.wait_sum : 55137.427273
.se->statistics.wait_count : 294878
.se->load.weight : 2
cfs_rq[0]:/autogroup-67
.exec_clock : 13569548.916161
.MIN_vruntime : 0.000001
.min_vruntime : 7304002.576262
.max_vruntime : 0.000001
.spread : 0.000000
.spread0 : -37303062.475986
.nr_spread_over : 2495
.nr_running : 0
.load : 0
.load_avg : 149.399974
.load_period : 6.421008
.load_contrib : 23
.load_tg : 49
.se->exec_start : 141912370.118364
.se->vruntime : 44607060.001860
.se->sum_exec_runtime : 13569663.320444
.se->statistics.wait_start : 0.000000
.se->statistics.sleep_start : 0.000000
.se->statistics.block_start : 0.000000
.se->statistics.sleep_max : 0.000000
.se->statistics.block_max : 0.000000
.se->statistics.exec_max : 51.770648
.se->statistics.slice_max : 66.102982
.se->statistics.wait_max : 148.774325
.se->statistics.wait_sum : 2325737.897221
.se->statistics.wait_count : 57199515
.se->load.weight : 2
cfs_rq[0]:/
.exec_clock : 42518959.323607
.MIN_vruntime : 0.000001
.min_vruntime : 44607065.052248
.max_vruntime : 0.000001
.spread : 0.000000
.spread0 : 0.000000
.nr_spread_over : 7056
.nr_running : 0
.load : 0
.load_avg : 0.000000
.load_period : 0.000000
.load_contrib : 0
.load_tg : 0
rt_rq[0]:
.rt_nr_running : 0
.rt_throttled : 0
.rt_time : 0.000000
.rt_runtime : 950.000000
runnable tasks:
task PID tree-key switches prio exec-runtime
sum-exec sum-sleep
----------------------------------------------------------------------------------------------------------
cpu#1, 2009.138 MHz
.nr_running : 1
.load : 1017
.nr_switches : 134029296
.nr_load_updates : 15663195
.nr_uninterruptible : 1
.next_balance : 4337.451017
.curr->pid : 0
.clock : 141912370.751092
.cpu_load[0] : 0
.cpu_load[1] : 8
.cpu_load[2] : 65
.cpu_load[3] : 131
.cpu_load[4] : 142
.yld_count : 45556538
.sched_switch : 0
.sched_count : 190136659
.sched_goidle : 45498985
.avg_idle : 956897
.ttwu_count : 73382490
.ttwu_local : 60102512
.bkl_count : 0
cfs_rq[1]:/autogroup-40
.exec_clock : 590188.619254
.MIN_vruntime : 0.000001
.min_vruntime : 590194.777093
.max_vruntime : 0.000001
.spread : 0.000000
.spread0 : -44016870.275155
.nr_spread_over : 0
.nr_running : 0
.load : 0
.load_avg : 1279.999872
.load_period : 7.354108
.load_contrib : 174
.load_tg : 180
.se->exec_start : 141912354.700492
.se->vruntime : 47687190.448099
.se->sum_exec_runtime : 590189.718382
.se->statistics.wait_start : 0.000000
.se->statistics.sleep_start : 0.000000
.se->statistics.block_start : 0.000000
.se->statistics.sleep_max : 0.000000
.se->statistics.block_max : 0.000000
.se->statistics.exec_max : 37.702102
.se->statistics.slice_max : 67.857220
.se->statistics.wait_max : 450.337317
.se->statistics.wait_sum : 107254.369568
.se->statistics.wait_count : 3731680
.se->load.weight : 2
cfs_rq[1]:/autogroup-8532
.exec_clock : 13132.462638
.MIN_vruntime : 0.000001
.min_vruntime : 14920.315501
.max_vruntime : 0.000001
.spread : 0.000000
.spread0 : -44592144.736747
.nr_spread_over : 979
.nr_running : 0
.load : 0
.load_avg : 185.203956
.load_period : 7.531595
.load_contrib : 24
.load_tg : 24
.se->exec_start : 141912336.944095
.se->vruntime : 47687195.840843
.se->sum_exec_runtime : 13132.517825
.se->statistics.wait_start : 0.000000
.se->statistics.sleep_start : 0.000000
.se->statistics.block_start : 0.000000
.se->statistics.sleep_max : 0.000000
.se->statistics.block_max : 0.000000
.se->statistics.exec_max : 5.525199
.se->statistics.slice_max : 15.355378
.se->statistics.wait_max : 22.093189
.se->statistics.wait_sum : 1246.745792
.se->statistics.wait_count : 10884
.se->load.weight : 2
cfs_rq[1]:/autogroup-6606
.exec_clock : 220454.371902
.MIN_vruntime : 0.000001
.min_vruntime : 220154.461555
.max_vruntime : 0.000001
.spread : 0.000000
.spread0 : -44386916.681120
.nr_spread_over : 38
.nr_running : 0
.load : 0
.load_avg : 919.191514
.load_period : 9.421373
.load_contrib : 7
.load_tg : 16
.se->exec_start : 141912325.856540
.se->vruntime : 47687190.843682
.se->sum_exec_runtime : 220455.300850
.se->statistics.wait_start : 0.000000
.se->statistics.sleep_start : 0.000000
.se->statistics.block_start : 0.000000
.se->statistics.sleep_max : 0.000000
.se->statistics.block_max : 0.000000
.se->statistics.exec_max : 11.798679
.se->statistics.slice_max : 216.375331
.se->statistics.wait_max : 29.371565
.se->statistics.wait_sum : 53833.944831
.se->statistics.wait_count : 243307
.se->load.weight : 2
cfs_rq[1]:/autogroup-67
.exec_clock : 16088979.991476
.MIN_vruntime : 0.000001
.min_vruntime : 8686788.465245
.max_vruntime : 0.000001
.spread : 0.000000
.spread0 : -35920282.677430
.nr_spread_over : 2599
.nr_running : 0
.load : 0
.load_avg : 192.884281
.load_period : 7.306848
.load_contrib : 26
.load_tg : 47
.se->exec_start : 141912370.095909
.se->vruntime : 47687190.909224
.se->sum_exec_runtime : 16089050.165780
.se->statistics.wait_start : 0.000000
.se->statistics.sleep_start : 0.000000
.se->statistics.block_start : 0.000000
.se->statistics.sleep_max : 0.000000
.se->statistics.block_max : 0.000000
.se->statistics.exec_max : 191.854446
.se->statistics.slice_max : 246.895824
.se->statistics.wait_max : 172.819165
.se->statistics.wait_sum : 2727601.602106
.se->statistics.wait_count : 53656471
.se->load.weight : 2
cfs_rq[1]:/
.exec_clock : 47837439.429324
.MIN_vruntime : 47687190.843682
.min_vruntime : 47687196.843682
.max_vruntime : 47687190.843682
.spread : 0.000000
.spread0 : 3080125.701007
.nr_spread_over : 7511
.nr_running : 1
.load : 1018
.load_avg : 0.000000
.load_period : 0.000000
.load_contrib : 0
.load_tg : 0
rt_rq[1]:
.rt_nr_running : 0
.rt_throttled : 0
.rt_time : 0.000000
.rt_runtime : 950.000000
runnable tasks:
task PID tree-key switches prio exec-runtime
sum-exec sum-sleep
----------------------------------------------------------------------------------------------------------
X 2530 590194.777093 7559895 120 590194.777093
1195228.445892 140477131.913151 /autogroup-40
