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 a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).