From: Henning Rohlfs <x+btrfs@xehonk.de>
To: <linux-btrfs@vger.kernel.org>
Subject: Re: Abysmal Performance
Date: Tue, 21 Jun 2011 09:10:28 +0200 [thread overview]
Message-ID: <05abdd9c91fce946549c45265f442b3b@localhost> (raw)
In-Reply-To: <4DFFE1E0.4040601@redhat.com>
[-- Attachment #1: Type: text/plain, Size: 1021 bytes --]
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.
[-- Attachment #2: blocked-sync.txt --]
[-- Type: text/plain, Size: 17019 bytes --]
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
next prev parent reply other threads:[~2011-06-21 7:10 UTC|newest]
Thread overview: 37+ messages / expand[flat|nested] mbox.gz Atom feed top
2011-06-20 21:51 Abysmal Performance Henning Rohlfs
2011-06-21 0:12 ` Josef Bacik
2011-06-21 7:10 ` Henning Rohlfs [this message]
2011-06-21 8:00 ` Sander
2011-06-21 9:26 ` Henning Rohlfs
2011-06-21 15:18 ` Josef Bacik
2011-06-21 16:55 ` Henning Rohlfs
2011-06-21 15:24 ` Calvin Walton
2011-06-22 14:15 ` Henning Rohlfs
2011-06-22 15:39 ` Josef Bacik
2011-06-22 15:57 ` Calvin Walton
2011-06-22 15:58 ` Josef Bacik
-- strict thread matches above, loose matches on Subject: below --
2011-04-29 14:46 abysmal performance John Wyzer
2011-04-29 15:01 ` Chris Mason
2011-04-30 17:33 ` Mitch Harder
2011-04-30 20:40 ` John Wyzer
2011-04-30 22:16 ` Mitch Harder
2011-04-30 22:33 ` John Wyzer
2011-05-03 11:05 ` Chris Mason
2011-05-03 11:06 ` Chris Mason
2011-04-30 23:55 ` Peter Stuge
2011-05-03 10:33 ` Bernhard Schmidt
2011-05-03 11:00 ` cwillu
2011-05-03 11:26 ` Bernhard Schmidt
2011-05-03 11:08 ` Chris Mason
2011-05-03 11:30 ` Bernhard Schmidt
2011-05-03 11:36 ` Chris Mason
2011-05-03 11:43 ` Bernhard Schmidt
2011-05-03 12:52 ` Chris Mason
2011-05-03 13:03 ` Bernhard Schmidt
2011-05-03 13:41 ` Mitch Harder
2011-05-03 14:41 ` Daniel J Blueman
2011-05-03 15:42 ` Mitch Harder
2011-05-03 16:51 ` Chris Mason
2011-05-03 14:54 ` Daniel J Blueman
2011-05-03 15:10 ` Bernhard Schmidt
[not found] ` <1304100271-sup-4177@localhost>
[not found] ` <1304100862-sup-1493@think>
[not found] ` <1304107977-sup-3815@localhost>
[not found] ` <1304110058-sup-7292@think>
[not found] ` <1304146193-sup-2200@localhost>
2011-04-30 20:51 ` John Wyzer
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=05abdd9c91fce946549c45265f442b3b@localhost \
--to=x+btrfs@xehonk.de \
--cc=linux-btrfs@vger.kernel.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.