Skip to contentSkip to conversation

Abysmal Performance

DISCUSSION Henning Rohlfs 5 participants 12 messages Jun 20, 2011 – Jun 22, 2011 Btrfs file system

lore
Share & tools
lore

Henning Rohlfs

author
#0 lore raw

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.)

- 64bit gentoo with vanilla 2.6.39 kernel
- lzo compression enabled
- 2x WD1000FYPS (1TB WD hdds)
- Athlon x2 2.2GHz with 8GB RAM
- space_cache was enabled, but it seemed to make the problem worse. It's no longer in the mount options.

Any help is appreciated. Thanks,
Henning

server ~ # sync; time sync
real 0m28.869s
user 0m0.000s
sys 0m5.750s

server ~ # uname -a
Linux server 2.6.39 #3 SMP Sat May 28 17:25:31 CEST 2011 x86_64 AMD Athlon(tm) 64 X2 Dual Core Processor 4200+ AuthenticAMD GNU/Linux

server ~ # mount | grep btrfs
/dev/sdb2 on / type btrfs (rw,noatime,compress=lzo,noacl)
/dev/sda2 on /mnt/pool type btrfs (rw,noatime,subvolid=0,compress=lzo) /dev/sda2 on /usr/portage type btrfs (rw,noatime,subvol=newportage,compress=lzo) /dev/sda2 on /home type btrfs (rw,noatime,subvol=home,compress=lzo) /dev/sda2 on /home/mythtv type btrfs (rw,noatime,subvol=mythtv,compress=lzo)

server ~ # btrfs fi show
Label: none uuid: 7676eb78-e411-4505-ac51-ccd12aa5a6b6

	Total devices 2 FS bytes used 281.58GB
	devid    1 size 931.28GB used 898.26GB path /dev/sda2
	devid    3 size 931.27GB used 898.26GB path /dev/sdb2

Btrfs v0.19-35-g1b444cd-dirty

server ~ # btrfs fi df /
Data, RAID1: total=875.00GB, used=279.30GB
System, RAID1: total=8.00MB, used=140.00KB
System: total=4.00MB, used=0.00
Metadata, RAID1: total=23.25GB, used=2.28GB

bonnie++

Version 1.96 ------Sequential Output------ --Sequential Input- --Random-
Concurrency 1 -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- --Seeks--
Machine Size K/sec %CP K/sec %CP K/sec %CP K/sec %CP K/sec %CP /sec %CP
server 16G 147 90 76321 18 31787 16 1370 71 64812 14 27.0 66

Latency             66485us    7581ms    4455ms   25011us     695ms     959ms
Version  1.96       ------Sequential Create------ --------Random Create--------
server              -Create-- --Read--- -Delete-- -Create-- --Read--- -Delete--
              files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  
/sec %CP
                 16   238  51 +++++ +++   219  51   284  52 +++++ +++

390 57
Latency 1914ms 524us 3461ms 1141ms 39us 1308ms
1.96,1.96,server,1,1308618030,16G,,147,90,76321,18,31787,16,1370,71,64812,14,27.0,66,16,,,,,238,51,+++++,+++,219,51,284,52,+++++,+++,390,57,66485us,7581ms,4455ms,25011us,695ms,959ms,1914ms,524us,3461ms,1141ms,39us,1308ms

server ~ # iostat -m 5

avg-cpu: %user %nice %system %iowait %steal %idle

           3.00    0.00   45.20    5.20    0.00   46.60

Device: tps MB_read/s MB_wrtn/s MB_read MB_wrtn

sda               0.00         0.00         0.00          0          0
sdb              15.20         0.06         0.00          0          0
md0               0.00         0.00         0.00          0          0

avg-cpu: %user %nice %system %iowait %steal %idle

           4.30    0.00   37.46   42.36    0.00   15.88

Device: tps MB_read/s MB_wrtn/s MB_read MB_wrtn

sda              45.00         0.00         0.38          0          1
sdb             467.60         0.02         2.06          0         10
md0               0.00         0.00         0.00          0          0

avg-cpu: %user %nice %system %iowait %steal %idle

           4.31    0.00   19.34   58.82    0.00   17.54

Device: tps MB_read/s MB_wrtn/s MB_read MB_wrtn

sda               8.80         0.00         0.04          0          0
sdb             649.80         0.02         2.67          0         13
md0               0.00         0.00         0.00          0          0

avg-cpu: %user %nice %system %iowait %steal %idle

           3.20    0.00   63.24   31.97    0.00    1.60

Device: tps MB_read/s MB_wrtn/s MB_read MB_wrtn

sda             585.80         0.00         2.36          0         11
sdb              20.80         0.08         0.16          0          0
md0               0.00         0.00         0.00          0          0

avg-cpu: %user %nice %system %iowait %steal %idle

           3.30    0.00   42.60   39.30    0.00   14.80

Device: tps MB_read/s MB_wrtn/s MB_read MB_wrtn

sda             514.20         0.00         2.29          0         11
sdb              59.20         0.10         0.17          0          0
md0               0.00         0.00         0.00          0          0
#1 lore raw
Quoted 8 lines · Henning Rohlfs

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.

Quoted 6 lines

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

author
#2 lore raw
Quoted 16 lines · Josef Bacik
Quoted 8 lines · Henning Rohlfs

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.

Quoted 6 lines

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.)

Quoted 4 lines

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
#3 lore raw
In reply to Henning Rohlfs

Henning Rohlfs wrote (ao):

Quoted 2 lines

- space_cache was enabled, but it seemed to make the problem worse. It's no longer in the mount options.

space_cache is a one time mount option which enabled space_cache. Not supplying it anymore as a mount option has no effect (dmesg | grep btrfs).

Sander

Signature · 2 lines
Humilis IT Services and Solutions
http://www.humilis.net
author
#4 lore raw
Quoted 6 lines · Sander

Henning Rohlfs wrote (ao):

Quoted 2 lines

- space_cache was enabled, but it seemed to make the problem worse. It's no longer in the mount options.

space_cache is a one time mount option which enabled space_cache. Not supplying it anymore as a mount option has no effect (dmesg | grep btrfs).

I'm sure that after the first reboot after removing the flag from the mount options, the system was faster for a while. That must have been a coincidence (or just an error on my part).

Anyway, I rebooted with clear_cache as mount option and there was no improvement either.

Thanks for pointing this out,
Henning

#5 lore raw
Quoted 5 lines · Henning Rohlfs
Quoted 4 lines · Sander

Henning Rohlfs wrote (ao):

Quoted 2 lines

- space_cache was enabled, but it seemed to make the problem worse. It's no longer in the mount options.

Quoted 8 lines
Quoted 3 lines

space_cache is a one time mount option which enabled space_cache. Not supplying it anymore as a mount option has no effect (dmesg | grep btrfs).

I'm sure that after the first reboot after removing the flag from the mount options, the system was faster for a while. That must have been a coincidence (or just an error on my part).

No, the space cache will make your system faster _after_ having been enabled once. The reason for this is because we have to build the cache the slow way at first, and then after that we can do it the fast way. What is probably happening is your box is slowing down trying to build this cache. Don't mount with clear_cache unless there is a bug in your cache. Let it do it's thing and stuff will get faster. Thanks,

Josef

#6 lore raw
Quoted 16 lines · Josef Bacik
Quoted 6 lines · Henning Rohlfs
Quoted 5 lines · Sander

Henning Rohlfs wrote (ao):

Quoted 3 lines

- space_cache was enabled, but it seemed to make the problem worse.
It's no longer in the mount options.

Quoted 8 lines
Quoted 3 lines

space_cache is a one time mount option which enabled space_cache. Not supplying it anymore as a mount option has no effect (dmesg | grep btrfs).

I'm sure that after the first reboot after removing the flag from the mount options, the system was faster for a while. That must have been a coincidence (or just an error on my part).

Quoted 6 lines

No, the space cache will make your system faster _after_ having been enabled once. The reason for this is because we have to build the cache the slow way at first, and then after that we can do it the fast way. What is probably happening is your box is slowing down trying to build this cache. Don't mount with clear_cache unless there is a bug in your cache. Let it do it's thing and stuff will get faster.

I'm just reporting what I experienced. I had space_cache in the mount options while the problem developed and removed it when the system got too slow. After the next reboot the system was responsive for a short time (an hour maybe - which seems to have been unrelated to the mount option though from what you described). Now there's no difference whatsoever between no options, space_cache and clear_cache.

To sum it up: I only played with the clear_cache option because the system got too slow in the first place. I don't see how the problem can be related to this option if changing it it makes no difference.

Thanks,
Henning

#7 lore raw
In reply to Henning Rohlfs
Quoted 3 lines · Henning Rohlfs

Hello,
=20
I've migrated my system to btrfs (raid1) a few months ago. Since the=

n=20

Quoted 2 lines

the performance has been pretty bad, but recently it's gotten=20
unbearable: a simple sync called while the system is idle can take 2=

0 up=20

Quoted 2 lines

to 60 seconds. Creating or deleting files often has several seconds=20 latency, too.

I think I=E2=80=99ve been seeing a fairly similar, or possibly the same= ? issue
as well. It looks like it=E2=80=99s actually a regression introduced in=
2.6.39 -
if I switch back to a 2.6.38 kernel, my latency issues magically go away! (I'm curious: does using the older 2.6.38.x kernel help with anyone else that's seeing the issue?)

Some hardware/configuration details:
btrfs on a single disc (Seagate Momentus XT hybrid), lzo compression an= d
space cache enabled. Some snapshots in use.

I notice that in latencytop I'm seeing a lot of lines with (cropped) traces like

sleep_on_page wait_on_page_bit read_extent_buffer_ 13.3 msec 0=
=2E5 %

showing up that I didn't see with the 2.6.38 kernel. I occasionally see latencies as bad as 20-30 seconds on operations like fsync or synchronous writes.

I think I can reproduce the issue well enough to bisect it, so I might give that a try. It'll be slow going, though.

--=20
Calvin Walton <[email protected]>

--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" = in
the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

author
#8 lore raw
Quoted 11 lines · Calvin Walton
Quoted 9 lines · Henning Rohlfs

Hello,

I've migrated my system to btrfs (raid1) a few months ago. Since=20
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
20 up
to 60 seconds. Creating or deleting files often has several seconds latency, too.

Quoted 1 line

I think I=E2=80=99ve been seeing a fairly similar, or possibly the sa=

me?=20

Quoted 2 lines

issue
as well. It looks like it=E2=80=99s actually a regression introduced =

in=20

Quoted 10 lines

2.6.39 -
if I switch back to a 2.6.38 kernel, my latency issues magically go away! (I'm curious: does using the older 2.6.38.x kernel help with anyone else that's seeing the issue?)

Some hardware/configuration details:
btrfs on a single disc (Seagate Momentus XT hybrid), lzo compression=20 and
space cache enabled. Some snapshots in use.

Quoted 4 lines

I notice that in latencytop I'm seeing a lot of lines with (cropped) traces like

sleep_on_page wait_on_page_bit read_extent_buffer_ 13.3 msec =

=20

Quoted 10 lines

0.5 %

showing up that I didn't see with the 2.6.38 kernel. I occasionally=20 see
latencies as bad as 20-30 seconds on operations like fsync or synchronous writes.

I think I can reproduce the issue well enough to bisect it, so I=20 might
give that a try. It'll be slow going, though.

You are right. This seems to be a regression in the .39 kernel. I=20 tested with 2.6.38.2 just now and the performance is back to normal.

Thanks,
Henning

server ~ # uname -a
Linux server 2.6.38.2 #1 SMP Thu Apr 14 13:05:35 CEST 2011 x86_64 AMD=20 Athlon(tm) 64 X2 Dual Core Processor 4200+ AuthenticAMD GNU/Linux

server ~ # sync; time sync
real 0m0.144s
user 0m0.000s
sys 0m0.020s

server ~ # bonnie++ -d tmp -u 0:0
Version 1.96 ------Sequential Output------ --Sequential Input-=20
--Random-
Concurrency 1 -Per Chr- --Block-- -Rewrite- -Per Chr- --Block--=20
--Seeks--
Machine Size K/sec %CP K/sec %CP K/sec %CP K/sec %CP K/sec %CP =
=20
/sec %CP
server 16G 147 97 279933 56 73245 34 1258 78 102379 2=
3=20
177.3 50
Latency 423ms 103ms 645ms 163ms 404ms =
=20
264ms
Version 1.96 ------Sequential Create------ --------Random=20
Create--------
server -Create-- --Read--- -Delete-- -Create-- --Read---=20
-Delete--
files /sec %CP /sec %CP /sec %CP /sec %CP /sec %CP =
=20
/sec %CP

                 16  3784  28 +++++ +++  8519  60 13694  59 +++++ +++=20

11710 76
Latency 127ms 1024us 18718us 15958us 119us =
=20
2459us 1.96,1.96,server,1,1308745595,16G,,147,97,279933,56,73245,34,1258,78,1= 02379,23,177.3,50,16,,,,,3784,28,+++++,+++,8519,60,13694,59,+++++,+++,1= 1710,76,423ms,103ms,645ms,163ms,404ms,264ms,127ms,1024us,18718us,15958u= s,119us,2459us

--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" = in
the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

#9 lore raw
Quoted 5 lines · Henning Rohlfs
Quoted 4 lines · Calvin Walton
Quoted 3 lines · Henning Rohlfs

Hello,

I've migrated my system to btrfs (raid1) a few months ago. Since t=

hen

Quoted 4 lines
Quoted 4 lines
Quoted 4 lines

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 second=

s

Quoted 3 lines
Quoted 3 lines
Quoted 1 line

latency, too.

I think I=E2=80=99ve been seeing a fairly similar, or possibly the s=

ame? issue

Quoted 1 line
Quoted 1 line

as well. It looks like it=E2=80=99s actually a regression introduced=

in 2.6.39 -

Quoted 6 lines
Quoted 6 lines

if I switch back to a 2.6.38 kernel, my latency issues magically go away! (I'm curious: does using the older 2.6.38.x kernel help with anyone else that's seeing the issue?)

Some hardware/configuration details:
btrfs on a single disc (Seagate Momentus XT hybrid), lzo compression=

and

Quoted 6 lines
Quoted 6 lines

space cache enabled. Some snapshots in use.

I notice that in latencytop I'm seeing a lot of lines with (cropped) traces like

sleep_on_page wait_on_page_bit read_extent_buffer_ 13.3 msec =

=20

Quoted 3 lines
Quoted 3 lines

0.5 %

showing up that I didn't see with the 2.6.38 kernel. I occasionally =

see

Quoted 4 lines
Quoted 4 lines

latencies as bad as 20-30 seconds on operations like fsync or synchronous writes.

I think I can reproduce the issue well enough to bisect it, so I mig=

ht

Quoted 3 lines
Quoted 1 line

give that a try. It'll be slow going, though.

=20
You are right. This seems to be a regression in the .39 kernel. I tes=

ted

Quoted 1 line

with 2.6.38.2 just now and the performance is back to normal.

Would you mind bisecting? You can make it go faster by doing

git bisect start fs/

that way only changes in fs are used. Thanks,

Josef
--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" = in
the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

#10 lore raw
Quoted 6 lines · Josef Bacik
Quoted 5 lines · Henning Rohlfs
Quoted 4 lines · Calvin Walton
Quoted 3 lines · Henning Rohlfs

Hello,

I've migrated my system to btrfs (raid1) a few months ago. Since=

then

Quoted 2 lines
Quoted 2 lines
Quoted 2 lines
Quoted 2 lines

the performance has been pretty bad, but recently it's gotten
unbearable: a simple sync called while the system is idle can ta=

ke

Quoted 2 lines
Quoted 2 lines
Quoted 2 lines
Quoted 2 lines

20 up
to 60 seconds. Creating or deleting files often has several seco=

nds

Quoted 3 lines
Quoted 3 lines
Quoted 3 lines
Quoted 1 line

latency, too.

I think I=E2=80=99ve been seeing a fairly similar, or possibly the=

same? issue

Quoted 1 line
Quoted 1 line
Quoted 1 line

as well. It looks like it=E2=80=99s actually a regression introduc=

ed in 2.6.39 -

Quoted 1 line
Quoted 1 line
Quoted 1 line

if I switch back to a 2.6.38 kernel, my latency issues magically g=

o

Quoted 4 lines
Quoted 4 lines
Quoted 4 lines

away! (I'm curious: does using the older 2.6.38.x kernel help with anyone else that's seeing the issue?)

I think I can reproduce the issue well enough to bisect it, so I m=

ight

Quoted 3 lines
Quoted 3 lines
Quoted 1 line

give that a try. It'll be slow going, though.

=20
You are right. This seems to be a regression in the .39 kernel. I t=

ested

Quoted 3 lines
Quoted 1 line

with 2.6.38.2 just now and the performance is back to normal.

=20
Would you mind bisecting?

Just before I was going to try bisecting, I tried the 3.0-rc4 kernel ou= t
of curiosity. And it seems to be quite a bit better; at the very least, I=E2=80=99m not seeing gui applications stalling for ~10 seconds when d= oing
things like opening or writing files. Latencytop is reporting fsync() latencies staying pretty steady in the range of under 300ms, with occasional outliers at up to 2s, and it's not getting worse with time.

I'll still look into doing a bisect between 2.6.38 and 2.6.39, I'm curious what went wrong.

--=20
Calvin Walton <[email protected]>

--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" = in
the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

#11 lore raw
Quoted 7 lines · Calvin Walton
Quoted 6 lines · Josef Bacik
Quoted 5 lines · Henning Rohlfs
Quoted 4 lines · Calvin Walton
Quoted 3 lines · Henning Rohlfs

Hello,

I've migrated my system to btrfs (raid1) a few months ago. Since=

then

Quoted 2 lines
Quoted 2 lines
Quoted 2 lines
Quoted 2 lines
Quoted 2 lines

the performance has been pretty bad, but recently it's gotten
unbearable: a simple sync called while the system is idle can ta=

ke

Quoted 2 lines
Quoted 2 lines
Quoted 2 lines
Quoted 2 lines
Quoted 2 lines

20 up
to 60 seconds. Creating or deleting files often has several seco=

nds

Quoted 3 lines
Quoted 3 lines
Quoted 3 lines
Quoted 3 lines
Quoted 1 line

latency, too.

I think I=E2=80=99ve been seeing a fairly similar, or possibly the=

same? issue

Quoted 1 line
Quoted 1 line
Quoted 1 line
Quoted 1 line

as well. It looks like it=E2=80=99s actually a regression introduc=

ed in 2.6.39 -

Quoted 1 line
Quoted 1 line
Quoted 1 line
Quoted 1 line

if I switch back to a 2.6.38 kernel, my latency issues magically g=

o

Quoted 4 lines
Quoted 2 lines
Quoted 2 lines
Quoted 2 lines

away! (I'm curious: does using the older 2.6.38.x kernel help with anyone else that's seeing the issue?)

=20

Quoted 1 line
Quoted 1 line
Quoted 1 line

I think I can reproduce the issue well enough to bisect it, so I m=

ight

Quoted 3 lines
Quoted 3 lines
Quoted 3 lines
Quoted 1 line

give that a try. It'll be slow going, though.

You are right. This seems to be a regression in the .39 kernel. I t=

ested

Quoted 5 lines
Quoted 3 lines
Quoted 1 line

with 2.6.38.2 just now and the performance is back to normal.

Would you mind bisecting?

=20
Just before I was going to try bisecting, I tried the 3.0-rc4 kernel =

out

Quoted 1 line

of curiosity. And it seems to be quite a bit better; at the very leas=

t,

Quoted 1 line

I=E2=80=99m not seeing gui applications stalling for ~10 seconds when=

doing

Quoted 3 lines

things like opening or writing files. Latencytop is reporting fsync() latencies staying pretty steady in the range of under 300ms, with occasional outliers at up to 2s, and it's not getting worse with time=

=2E

Quoted 4 lines

=20
I'll still look into doing a bisect between 2.6.38 and 2.6.39, I'm curious what went wrong.
=20

Yeah that makes two of us :). There were some other plugging changes that went into to 38, so maybe bisect all of the kernel, not just fs/ just in case it was those and not us. Thanks,

Josef
--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" = in
the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html