Re: BTRFS free space handling still needs more work: Hangs again (further tests)

[Martin Steigerwald <Martin@lichtvoll.de>]

[-- Attachment #1: Type: text/plain, Size: 40181 bytes --]

Am Samstag, 27. Dezember 2014, 14:55:58 schrieb Martin Steigerwald:
> Summarized at
> 
> Bug 90401 - btrfs kworker thread uses up 100% of a Sandybridge core for minutes on random write into big file
> https://bugzilla.kernel.org/show_bug.cgi?id=90401
> 
> see below. This is reproducable with fio, no need for Windows XP in
> Virtualbox for reproducing the issue. Next I will try to reproduce with
> a freshly creating filesystem.
> 
> 
> Am Samstag, 27. Dezember 2014, 09:30:43 schrieb Hugo Mills:
> > On Sat, Dec 27, 2014 at 10:01:17AM +0100, Martin Steigerwald wrote:
> > > Am Freitag, 26. Dezember 2014, 14:48:38 schrieb Robert White:
> > > > On 12/26/2014 05:37 AM, Martin Steigerwald wrote:
> > > > > Hello!
> > > > > 
> > > > > First: Have a merry christmas and enjoy a quiet time in these days.
> > > > > 
> > > > > Second: At a time you feel like it, here is a little rant, but also a
> > > > > bug
> > > > > report:
> > > > > 
> > > > > I have this on 3.18 kernel on Debian Sid with BTRFS Dual SSD RAID with
> > > > > space_cache, skinny meta data extents – are these a problem? – and
> > > > 
> > > > > compress=lzo:
> > > > (there is no known problem with skinny metadata, it's actually more
> > > > efficient than the older format. There has been some anecdotes about
> > > > mixing the skinny and fat metadata but nothing has ever been
> > > > demonstrated problematic.)
> > > > 
> > > > > merkaba:~> btrfs fi sh /home
> > > > > Label: 'home'  uuid: b96c4f72-0523-45ac-a401-f7be73dd624a
> > > > > 
> > > > >          Total devices 2 FS bytes used 144.41GiB
> > > > >          devid    1 size 160.00GiB used 160.00GiB path
> > > > >          /dev/mapper/msata-home
> > > > >          devid    2 size 160.00GiB used 160.00GiB path
> > > > >          /dev/mapper/sata-home
> > > > > 
> > > > > Btrfs v3.17
> > > > > merkaba:~> btrfs fi df /home
> > > > > Data, RAID1: total=154.97GiB, used=141.12GiB
> > > > > System, RAID1: total=32.00MiB, used=48.00KiB
> > > > > Metadata, RAID1: total=5.00GiB, used=3.29GiB
> > > > > GlobalReserve, single: total=512.00MiB, used=0.00B
> > > > 
> > > > This filesystem, at the allocation level, is "very full" (see below).
> > > > 
> > > > > And I had hangs with BTRFS again. This time as I wanted to install tax
> > > > > return software in Virtualbox´d Windows XP VM (which I use once a year
> > > > > cause I know no tax return software for Linux which would be suitable
> > > > > for
> > > > > Germany and I frankly don´t care about the end of security cause all
> > > > > surfing and other network access I will do from the Linux box and I
> > > > > only
> > > > > run the VM behind a firewall).
> > > > 
> > > > > And thus I try the balance dance again:
> > > > ITEM: Balance... it doesn't do what you think it does... 8-)
> > > > 
> > > > "Balancing" is something you should almost never need to do. It is only
> > > > for cases of changing geometry (adding disks, switching RAID levels,
> > > > etc.) of for cases when you've radically changed allocation behaviors
> > > > (like you decided to remove all your VM's or you've decided to remove a
> > > > mail spool directory full of thousands of tiny files).
> > > > 
> > > > People run balance all the time because they think they should. They are
> > > > _usually_ incorrect in that belief.
> > > 
> > > I only see the lockups of BTRFS is the trees *occupy* all space on the
> > > device.
> >    No, "the trees" occupy 3.29 GiB of your 5 GiB of mirrored metadata
> > space. What's more, balance does *not* balance the metadata trees. The
> > remaining space -- 154.97 GiB -- is unstructured storage for file
> > data, and you have some 13 GiB of that available for use.
> > 
> >    Now, since you're seeing lockups when the space on your disks is
> > all allocated I'd say that's a bug. However, you're the *only* person
> > who's reported this as a regular occurrence. Does this happen with all
> > filesystems you have, or just this one?
> > 
> > > I *never* so far saw it lockup if there is still space BTRFS can allocate
> > > from to *extend* a tree.
> > 
> >    It's not a tree. It's simply space allocation. It's not even space
> > *usage* you're talking about here -- it's just allocation (i.e. the FS
> > saying "I'm going to use this piece of disk for this purpose").
> > 
> > > This may be a bug, but this is what I see.
> > > 
> > > And no amount of "you should not balance a BTRFS" will make that
> > > perception go away.
> > > 
> > > See, I see the sun coming out on a morning and you tell me "no, it
> > > doesn´t". Simply that is not going to match my perception.
> > 
> >    Duncan's assertion is correct in its detail. Looking at your space
> 
> Robert's :)
> 
> > usage, I would not suggest that running a balance is something you
> > need to do. Now, since you have these lockups that seem quite
> > repeatable, there's probably a lurking bug in there, but hacking
> > around with balance every time you hit it isn't going to get the
> > problem solved properly.
> > 
> >    I think I would suggest the following:
> > 
> >  - make sure you have some way of logging your dmesg permanently (use
> >    a different filesystem for /var/log, or a serial console, or a
> >    netconsole)
> > 
> >  - when the lockup happens, hit Alt-SysRq-t a few times
> > 
> >  - send the dmesg output here, or post to bugzilla.kernel.org
> > 
> >    That's probably going to give enough information to the developers
> > to work out where the lockup is happening, and is clearly the way
> > forward here.
> 
> And I got it reproduced. *Perfectly* reproduced, I´d say.
> 
> But let me run the whole story:
> 
> 1) I downsized my /home BTRFS from dual 170 GiB to dual 160 GiB again.

[… story of trying to reproduce with Windows XP defragmenting which was
unsuccessful as BTRFS still had free device space to allocate new chunks
from …]

> But finally I got to:
> 
> merkaba:~> date; btrfs fi sh /home ; btrfs fi df /home
> Sa 27. Dez 13:26:39 CET 2014
> Label: 'home'  uuid: [some UUID]
>         Total devices 2 FS bytes used 152.83GiB
>         devid    1 size 160.00GiB used 160.00GiB path /dev/mapper/msata-home
>         devid    2 size 160.00GiB used 160.00GiB path /dev/mapper/sata-home
> 
> Btrfs v3.17
> Data, RAID1: total=154.97GiB, used=149.58GiB
> System, RAID1: total=32.00MiB, used=48.00KiB
> Metadata, RAID1: total=5.00GiB, used=3.26GiB
> GlobalReserve, single: total=512.00MiB, used=0.00B
> 
> 
> 
> So I did, if Virtualbox can write randomly in a file, I can too.
> 
> So I did:
> 
> 
> martin@merkaba:~> cat ssd-test.fio 
> [global]
> bs=4k
> #ioengine=libaio
> #iodepth=4
> size=4g
> #direct=1
> runtime=120
> filename=ssd.test.file
> 
> [seq-write]
> rw=write
> stonewall
> 
> [rand-write]
> rw=randwrite
> stonewall
> 
> 
> 
> And got:
> 
> ATOP - merkaba                          2014/12/27  13:41:02                          -----------                           10s elapsed
> PRC |  sys   10.14s |  user   0.38s |  #proc    332  | #trun      2  |  #tslpi   548 |  #tslpu     0 |  #zombie    0  | no  procacct  |
> CPU |  sys     102% |  user      4% |  irq       0%  | idle    295%  |  wait      0% |  guest     0% |  curf 3.10GHz  | curscal  96%  |
> cpu |  sys      76% |  user      0% |  irq       0%  | idle     24%  |  cpu001 w  0% |  guest     0% |  curf 3.20GHz  | curscal  99%  |
> cpu |  sys      24% |  user      1% |  irq       0%  | idle     75%  |  cpu000 w  0% |  guest     0% |  curf 3.19GHz  | curscal  99%  |
> cpu |  sys       1% |  user      1% |  irq       0%  | idle     98%  |  cpu002 w  0% |  guest     0% |  curf 3.00GHz  | curscal  93%  |
> cpu |  sys       1% |  user      1% |  irq       0%  | idle     98%  |  cpu003 w  0% |  guest     0% |  curf 3.00GHz  | curscal  93%  |
> CPL |  avg1    0.82 |  avg5    0.78 |  avg15   0.99  |               |  csw     6233 |  intr   12023 |                | numcpu     4  |
> MEM |  tot    15.5G |  free    4.0G |  cache   9.7G  | buff    0.0M  |  slab  333.1M |  shmem 206.6M |  vmbal   0.0M  | hptot   0.0M  |
> SWP |  tot    12.0G |  free   11.7G |                |               |               |               |  vmcom   3.4G  | vmlim  19.7G  |
> LVM |     sata-home |  busy      0% |  read       8  | write      0  |  KiB/w      0 |  MBr/s   0.00 |  MBw/s   0.00  | avio 0.12 ms  |
> DSK |           sda |  busy      0% |  read       8  | write      0  |  KiB/w      0 |  MBr/s   0.00 |  MBw/s   0.00  | avio 0.12 ms  |
> NET |  transport    |  tcpi      16 |  tcpo      16  | udpi       0  |  udpo       0 |  tcpao      1 |  tcppo      1  | tcprs      0  |
> NET |  network      |  ipi       16 |  ipo       16  | ipfrw      0  |  deliv     16 |               |  icmpi      0  | icmpo      0  |
> NET |  lo      ---- |  pcki      16 |  pcko      16  | si    2 Kbps  |  so    2 Kbps |  erri       0 |  erro       0  | drpo       0  |
> 
>   PID    TID   RUID      EUID        THR  SYSCPU   USRCPU   VGROW    RGROW   RDDSK    WRDSK  ST   EXC  S   CPUNR   CPU   CMD        1/2
> 18079      -   martin    martin        2   9.99s    0.00s      0K       0K      0K      16K  --     -  R       1  100%   fio
>  4746      -   martin    martin        2   0.01s    0.14s      0K       0K      0K       0K  --     -  S       2    2%   konsole
>  3291      -   martin    martin        4   0.01s    0.11s      0K       0K      0K       0K  --     -  S       0    1%   plasma-desktop
>  1488      -   root      root          1   0.03s    0.04s      0K       0K      0K       0K  --     -  S       0    1%   Xorg
> 10036      -   root      root          1   0.04s    0.02s      0K       0K      0K       0K  --     -  R       2    1%   atop
> 
> while fio was just *laying* out the 4 GiB file. Yes, thats 100% system CPU
> for 10 seconds while allocatiing a 4 GiB file on a filesystem like:
> 
> martin@merkaba:~> LANG=C df -hT /home
> Filesystem             Type   Size  Used Avail Use% Mounted on
> /dev/mapper/msata-home btrfs  170G  156G   17G  91% /home
> 
> where a 4 GiB file should easily fit, no? (And this output is with the 4
> GiB file. So it was even 4 GiB more free before.)
> 
> 
> But it gets even more visible:
> 
> martin@merkaba:~> fio ssd-test.fio
> seq-write: (g=0): rw=write, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=1
> rand-write: (g=1): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=1
> fio-2.1.11
> Starting 2 processes
> Jobs: 1 (f=1): [_(1),w(1)] [19.3% done] [0KB/0KB/0KB /s] [0/0/0 iops] [eta 01m:57s]       
> 0$ zsh  1$ zsh  2$ zsh  3-$ zsh  4$ zsh  5$* zsh                                   
> 
> 
> yes, thats 0 IOPS.
> 
> 0 IOPS and in zero IOPS. For minutes.
> 
> 
> 
> And here is why:
> 
> ATOP - merkaba                          2014/12/27  13:46:52                          -----------                           10s elapsed
> PRC |  sys   10.77s |  user   0.31s |  #proc    334  | #trun      2  |  #tslpi   548 |  #tslpu     3 |  #zombie    0  | no  procacct  |
> CPU |  sys     108% |  user      3% |  irq       0%  | idle    286%  |  wait      2% |  guest     0% |  curf 3.08GHz  | curscal  96%  |
> cpu |  sys      72% |  user      1% |  irq       0%  | idle     28%  |  cpu000 w  0% |  guest     0% |  curf 3.00GHz  | curscal  93%  |
> cpu |  sys      19% |  user      0% |  irq       0%  | idle     81%  |  cpu001 w  0% |  guest     0% |  curf 3.00GHz  | curscal  93%  |
> cpu |  sys      11% |  user      1% |  irq       0%  | idle     87%  |  cpu003 w  1% |  guest     0% |  curf 3.19GHz  | curscal  99%  |
> cpu |  sys       6% |  user      1% |  irq       0%  | idle     91%  |  cpu002 w  1% |  guest     0% |  curf 3.11GHz  | curscal  97%  |
> CPL |  avg1    2.78 |  avg5    1.34 |  avg15   1.12  |               |  csw    50192 |  intr   32379 |                | numcpu     4  |
> MEM |  tot    15.5G |  free    5.0G |  cache   8.7G  | buff    0.0M  |  slab  332.6M |  shmem 207.2M |  vmbal   0.0M  | hptot   0.0M  |
> SWP |  tot    12.0G |  free   11.7G |                |               |               |               |  vmcom   3.4G  | vmlim  19.7G  |
> LVM |     sata-home |  busy      5% |  read     160  | write  11177  |  KiB/w      3 |  MBr/s   0.06 |  MBw/s   4.36  | avio 0.05 ms  |
> LVM |    msata-home |  busy      4% |  read      28  | write  11177  |  KiB/w      3 |  MBr/s   0.01 |  MBw/s   4.36  | avio 0.04 ms  |
> LVM |   sata-debian |  busy      0% |  read       0  | write    844  |  KiB/w      4 |  MBr/s   0.00 |  MBw/s   0.33  | avio 0.02 ms  |
> LVM |  msata-debian |  busy      0% |  read       0  | write    844  |  KiB/w      4 |  MBr/s   0.00 |  MBw/s   0.33  | avio 0.02 ms  |
> DSK |           sda |  busy      5% |  read     160  | write  10200  |  KiB/w      4 |  MBr/s   0.06 |  MBw/s   4.69  | avio 0.05 ms  |
> DSK |           sdb |  busy      4% |  read      28  | write  10558  |  KiB/w      4 |  MBr/s   0.01 |  MBw/s   4.69  | avio 0.04 ms  |
> NET |  transport    |  tcpi      35 |  tcpo      33  | udpi       3  |  udpo       3 |  tcpao      2 |  tcppo      1  | tcprs      0  |
> NET |  network      |  ipi       38 |  ipo       36  | ipfrw      0  |  deliv     38 |               |  icmpi      0  | icmpo      0  |
> NET |  eth0      0% |  pcki      22 |  pcko      20  | si    9 Kbps  |  so    2 Kbps |  erri       0 |  erro       0  | drpo       0  |
> NET |  lo      ---- |  pcki      16 |  pcko      16  | si    2 Kbps  |  so    2 Kbps |  erri       0 |  erro       0  | drpo       0  |
> 
>   PID    TID   RUID      EUID        THR  SYSCPU   USRCPU   VGROW    RGROW   RDDSK    WRDSK  ST   EXC  S   CPUNR   CPU   CMD        1/3
> 14973      -   root      root          1   8.92s    0.00s      0K       0K      0K     144K  --     -  S       0   89%   kworker/u8:14
> 17450      -   root      root          1   0.86s    0.00s      0K       0K      0K      32K  --     -  R       3    9%   kworker/u8:5
>   788      -   root      root          1   0.25s    0.00s      0K       0K    128K   18880K  --     -  S       3    3%   btrfs-transact
> 12254      -   root      root          1   0.14s    0.00s      0K       0K     64K     576K  --     -  S       2    1%   kworker/u8:3
> 17332      -   root      root          1   0.11s    0.00s      0K       0K    112K    1348K  --     -  S       2    1%   kworker/u8:4
>  3291      -   martin    martin        4   0.01s    0.09s      0K       0K      0K       0K  --     -  S       1    1%   plasma-deskto
> 
> 
> 
> 
> ATOP - merkaba                          2014/12/27  13:47:12                          -----------                           10s elapsed
> PRC |  sys   10.78s |  user   0.44s |  #proc    334  | #trun      3  |  #tslpi   547 |  #tslpu     3 |  #zombie    0  | no  procacct  |
> CPU |  sys     106% |  user      4% |  irq       0%  | idle    288%  |  wait      1% |  guest     0% |  curf 3.00GHz  | curscal  93%  |
> cpu |  sys      93% |  user      0% |  irq       0%  | idle      7%  |  cpu002 w  0% |  guest     0% |  curf 3.00GHz  | curscal  93%  |
> cpu |  sys       7% |  user      0% |  irq       0%  | idle     93%  |  cpu003 w  0% |  guest     0% |  curf 3.01GHz  | curscal  94%  |
> cpu |  sys       3% |  user      2% |  irq       0%  | idle     94%  |  cpu000 w  0% |  guest     0% |  curf 3.00GHz  | curscal  93%  |
> cpu |  sys       3% |  user      2% |  irq       0%  | idle     95%  |  cpu001 w  0% |  guest     0% |  curf 3.00GHz  | curscal  93%  |
> CPL |  avg1    3.33 |  avg5    1.56 |  avg15   1.20  |               |  csw    38253 |  intr   23104 |                | numcpu     4  |
> MEM |  tot    15.5G |  free    4.9G |  cache   8.7G  | buff    0.0M  |  slab  336.5M |  shmem 207.2M |  vmbal   0.0M  | hptot   0.0M  |
> SWP |  tot    12.0G |  free   11.7G |                |               |               |               |  vmcom   3.4G  | vmlim  19.7G  |
> LVM |    msata-home |  busy      2% |  read       0  | write   2337  |  KiB/w      3 |  MBr/s   0.00 |  MBw/s   0.91  | avio 0.07 ms  |
> LVM |     sata-home |  busy      2% |  read      36  | write   2337  |  KiB/w      3 |  MBr/s   0.01 |  MBw/s   0.91  | avio 0.07 ms  |
> LVM |  msata-debian |  busy      1% |  read       1  | write   1630  |  KiB/w      4 |  MBr/s   0.00 |  MBw/s   0.65  | avio 0.03 ms  |
> LVM |   sata-debian |  busy      0% |  read       0  | write   1019  |  KiB/w      4 |  MBr/s   0.00 |  MBw/s   0.41  | avio 0.02 ms  |
> DSK |           sdb |  busy      2% |  read       1  | write   2545  |  KiB/w      5 |  MBr/s   0.00 |  MBw/s   1.45  | avio 0.07 ms  |
> DSK |           sda |  busy      1% |  read      36  | write   2461  |  KiB/w      5 |  MBr/s   0.01 |  MBw/s   1.28  | avio 0.06 ms  |
> NET |  transport    |  tcpi      20 |  tcpo      20  | udpi       1  |  udpo       1 |  tcpao      1 |  tcppo      1  | tcprs      0  |
> NET |  network      |  ipi       21 |  ipo       21  | ipfrw      0  |  deliv     21 |               |  icmpi      0  | icmpo      0  |
> NET |  eth0      0% |  pcki       5 |  pcko       5  | si    0 Kbps  |  so    0 Kbps |  erri       0 |  erro       0  | drpo       0  |
> NET |  lo      ---- |  pcki      16 |  pcko      16  | si    2 Kbps  |  so    2 Kbps |  erri       0 |  erro       0  | drpo       0  |
> 
>   PID    TID   RUID      EUID        THR  SYSCPU   USRCPU   VGROW    RGROW   RDDSK    WRDSK  ST   EXC  S   CPUNR   CPU   CMD        1/3
> 17450      -   root      root          1   9.96s    0.00s      0K       0K      0K       0K  --     -  R       2  100%   kworker/u8:5
>  4746      -   martin    martin        2   0.06s    0.15s      0K       0K      0K       0K  --     -  S       1    2%   konsole
> 10508      -   root      root          1   0.13s    0.00s      0K       0K     96K    4048K  --     -  S       1    1%   kworker/u8:18
>  1488      -   root      root          1   0.06s    0.06s      0K       0K      0K       0K  --     -  S       0    1%   Xorg
> 17332      -   root      root          1   0.12s    0.00s      0K       0K     96K     580K  --     -  R       3    1%   kworker/u8:4
> 17454      -   root      root          1   0.11s    0.00s      0K       0K     32K    4416K  --     -  D       1    1%   kworker/u8:6
> 17516      -   root      root          1   0.09s    0.00s      0K       0K     16K     136K  --     -  S       3    1%   kworker/u8:7
>  3268      -   martin    martin        3   0.02s    0.05s      0K       0K      0K       0K  --     -  S       1    1%   kwin
> 10036      -   root      root          1   0.05s    0.02s      0K       0K      0K       0K  --     -  R       0    1%   atop
> 
> 
> 
> So BTRFS is basically busy with itself and nothing else. Look at the SSD
> usage. They are *idling* around. Heck 2400 write accesses in 10 seconds.
> Thats a joke with SSDs that can do 40000 IOPS (depending on how and what
> you measure of course, like request size, read, write, iodepth and so).
> 
> Its kworker/u8:5 utilizing 100% of one core for minutes.
> 
> 
> 
> Its the random write case it seems. Here are values from fio job:
> 
> martin@merkaba:~> fio ssd-test.fio
> seq-write: (g=0): rw=write, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=1
> rand-write: (g=1): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=1
> fio-2.1.11
> Starting 2 processes
> Jobs: 1 (f=1): [_(1),w(1)] [3.6% done] [0KB/0KB/0KB /s] [0/0/0 iops] [eta 01h:06m:26s]
> seq-write: (groupid=0, jobs=1): err= 0: pid=19212: Sat Dec 27 13:48:33 2014
>   write: io=4096.0MB, bw=343683KB/s, iops=85920, runt= 12204msec
>     clat (usec): min=3, max=38048, avg=10.52, stdev=205.25
>      lat (usec): min=3, max=38048, avg=10.66, stdev=205.43
>     clat percentiles (usec):
>      |  1.00th=[    4],  5.00th=[    4], 10.00th=[    4], 20.00th=[    4],
>      | 30.00th=[    4], 40.00th=[    5], 50.00th=[    5], 60.00th=[    5],
>      | 70.00th=[    7], 80.00th=[    8], 90.00th=[    8], 95.00th=[    9],
>      | 99.00th=[   14], 99.50th=[   20], 99.90th=[  211], 99.95th=[ 2128],
>      | 99.99th=[10304]
>     bw (KB  /s): min=164328, max=812984, per=100.00%, avg=345585.75, stdev=201695.20
>     lat (usec) : 4=0.18%, 10=95.31%, 20=4.00%, 50=0.18%, 100=0.12%
>     lat (usec) : 250=0.12%, 500=0.02%, 750=0.01%, 1000=0.01%
>     lat (msec) : 2=0.01%, 4=0.01%, 10=0.03%, 20=0.01%, 50=0.01%
>   cpu          : usr=13.55%, sys=46.89%, ctx=7810, majf=0, minf=6
>   IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
>      submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
>      complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
>      issued    : total=r=0/w=1048576/d=0, short=r=0/w=0/d=0
>      latency   : target=0, window=0, percentile=100.00%, depth=1
> 
> Seems fine.
> 
> 
> But:
> 
> rand-write: (groupid=1, jobs=1): err= 0: pid=19243: Sat Dec 27 13:48:33 2014
>   write: io=140336KB, bw=1018.4KB/s, iops=254, runt=137803msec
>     clat (usec): min=4, max=21299K, avg=3708.02, stdev=266885.61
>      lat (usec): min=4, max=21299K, avg=3708.14, stdev=266885.61
>     clat percentiles (usec):
>      |  1.00th=[    4],  5.00th=[    5], 10.00th=[    5], 20.00th=[    5],
>      | 30.00th=[    6], 40.00th=[    6], 50.00th=[    6], 60.00th=[    6],
>      | 70.00th=[    7], 80.00th=[    7], 90.00th=[    9], 95.00th=[   10],
>      | 99.00th=[   18], 99.50th=[   19], 99.90th=[   28], 99.95th=[  116],
>      | 99.99th=[16711680]
>     bw (KB  /s): min=    0, max= 3426, per=100.00%, avg=1030.10, stdev=938.02
>     lat (usec) : 10=92.63%, 20=6.89%, 50=0.43%, 100=0.01%, 250=0.02%
>     lat (msec) : 250=0.01%, 500=0.01%, >=2000=0.02%
>   cpu          : usr=0.06%, sys=1.59%, ctx=28720, majf=0, minf=7
>   IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
>      submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
>      complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
>      issued    : total=r=0/w=35084/d=0, short=r=0/w=0/d=0
>      latency   : target=0, window=0, percentile=100.00%, depth=1
> 
> Run status group 0 (all jobs):
>   WRITE: io=4096.0MB, aggrb=343682KB/s, minb=343682KB/s, maxb=343682KB/s, mint=12204msec, maxt=12204msec
> 
> Run status group 1 (all jobs):
>   WRITE: io=140336KB, aggrb=1018KB/s, minb=1018KB/s, maxb=1018KB/s, mint=137803msec, maxt=137803msec
> 
> 
> What? 254 IOPS? With a Dual SSD BTRFS RAID 1?
> 
> What?
> 
> Ey, *what*?
> 
> 
> 
> Repeating with the random write case.
> 
> Its a different kworker now, but similar result:
> 
> ATOP - merkaba                          2014/12/27  13:51:48                          -----------                           10s elapsed
> PRC |  sys   10.66s |  user   0.25s |  #proc    330  | #trun      2  |  #tslpi   545 |  #tslpu     2 |  #zombie    0  | no  procacct  |
> CPU |  sys     105% |  user      3% |  irq       0%  | idle    292%  |  wait      0% |  guest     0% |  curf 3.07GHz  | curscal  95%  |
> cpu |  sys      92% |  user      0% |  irq       0%  | idle      8%  |  cpu002 w  0% |  guest     0% |  curf 3.19GHz  | curscal  99%  |
> cpu |  sys       8% |  user      0% |  irq       0%  | idle     92%  |  cpu003 w  0% |  guest     0% |  curf 3.09GHz  | curscal  96%  |
> cpu |  sys       3% |  user      2% |  irq       0%  | idle     95%  |  cpu000 w  0% |  guest     0% |  curf 3.00GHz  | curscal  93%  |
> cpu |  sys       2% |  user      1% |  irq       0%  | idle     97%  |  cpu001 w  0% |  guest     0% |  curf 3.00GHz  | curscal  93%  |
> CPL |  avg1    1.00 |  avg5    1.32 |  avg15   1.23  |               |  csw    34484 |  intr   23182 |                | numcpu     4  |
> MEM |  tot    15.5G |  free    5.4G |  cache   8.3G  | buff    0.0M  |  slab  334.8M |  shmem 207.2M |  vmbal   0.0M  | hptot   0.0M  |
> SWP |  tot    12.0G |  free   11.7G |                |               |               |               |  vmcom   3.4G  | vmlim  19.7G  |
> LVM |     sata-home |  busy      1% |  read      36  | write   2502  |  KiB/w      4 |  MBr/s   0.01 |  MBw/s   0.98  | avio 0.06 ms  |
> LVM |    msata-home |  busy      1% |  read      48  | write   2502  |  KiB/w      4 |  MBr/s   0.02 |  MBw/s   0.98  | avio 0.04 ms  |
> LVM |  msata-debian |  busy      0% |  read       0  | write      6  |  KiB/w      7 |  MBr/s   0.00 |  MBw/s   0.00  | avio 1.33 ms  |
> LVM |   sata-debian |  busy      0% |  read       0  | write      6  |  KiB/w      7 |  MBr/s   0.00 |  MBw/s   0.00  | avio 0.17 ms  |
> DSK |           sda |  busy      1% |  read      36  | write   2494  |  KiB/w      4 |  MBr/s   0.01 |  MBw/s   0.98  | avio 0.06 ms  |
> DSK |           sdb |  busy      1% |  read      48  | write   2494  |  KiB/w      4 |  MBr/s   0.02 |  MBw/s   0.98  | avio 0.04 ms  |
> NET |  transport    |  tcpi      32 |  tcpo      30  | udpi       2  |  udpo       2 |  tcpao      2 |  tcppo      1  | tcprs      0  |
> NET |  network      |  ipi       35 |  ipo       32  | ipfrw      0  |  deliv     35 |               |  icmpi      0  | icmpo      0  |
> NET |  eth0      0% |  pcki      19 |  pcko      16  | si    9 Kbps  |  so    2 Kbps |  erri       0 |  erro       0  | drpo       0  |
> NET |  lo      ---- |  pcki      16 |  pcko      16  | si    2 Kbps  |  so    2 Kbps |  erri       0 |  erro       0  | drpo       0  |
> 
>   PID    TID   RUID      EUID        THR  SYSCPU   USRCPU   VGROW    RGROW   RDDSK    WRDSK  ST   EXC  S   CPUNR   CPU   CMD        1/2
> 11746      -   root      root          1  10.00s    0.00s      0K       0K      0K       0K  --     -  R       2  100%   kworker/u8:0
> 12254      -   root      root          1   0.16s    0.00s      0K       0K    112K    1712K  --     -  S       3    2%   kworker/u8:3  
> 17517      -   root      root          1   0.16s    0.00s      0K       0K    144K    1764K  --     -  S       1    2%   kworker/u8:8
> 
> 
> 
> And now the graphical environemnt is locked. Continuining on TTY1.
> 
> Doing another fio job with tee so I can get output easily.
> 
> Wow! I wonder whether this is reproducable with a fresh BTRFS with fio stressing it.
> 
> Like a 10 GiB BTRFS with 5 GiB fio test file and just letting it run.
> 
> 
> Okay, I let the final fio job complete and include the output here.
> 
> 
> Okay, and there we are and I do have sysrq-t figures. 
> 
> Okay, this is 1,2 MiB xz packed. So I better start a bug report about this
> and attach it there. Is dislike cloud URLs that may disappear at some time.
> 
> 
> 
> Now please finally acknowledge that there is an issue. Maybe I was not
> using the correct terms at the beginning, but there is a real issue. I do
> performance things for half a decade at least, I know that there is an issue
> when I see it.
> 
> 
> 
> 
> There we go:
> 
> Bug 90401 - btrfs kworker thread uses up 100% of a Sandybridge core for minutes on random write into big file
> https://bugzilla.kernel.org/show_bug.cgi?id=90401

I have done more tests.

This is on the same /home after extending it to 170 GiB and balancing it to
btrfs balance start -dusage=80

It has plenty of free space free. I updated the bug report and hope it can
give an easy enough to comprehend summary. The new tests are in:

https://bugzilla.kernel.org/show_bug.cgi?id=90401#c6



Pasting below for discussion on list. Summary: I easily get 38000 (!)
IOPS. It may be an idea to reduce to 160 GiB, but right now this does
not work as it says no free space on device when trying to downsize it.
I may try with 165 or 162GiB.

So now we have three IOPS figures:

- 256 IOPS in worst case scenario
- 4700 IOPS when trying to reproduce worst case scenario with a fresh and small
BTRFS
- 38000 IOPS when /home has unused device space to allocate chunks from

https://bugzilla.kernel.org/show_bug.cgi?id=90401#c8


This is another test.

With my /home. This time while it has enough free device space to reserve
new chunks from.

Remember this for the case where is hasn´t:

merkaba:~> btrfs fi sh /home
Label: 'home'  uuid: [some UUID]
        Total devices 2 FS bytes used 144.19GiB
        devid    1 size 160.00GiB used 150.01GiB path /dev/mapper/msata-home
        devid    2 size 160.00GiB used 150.01GiB path /dev/mapper/sata-home

Btrfs v3.17
merkaba:~> btrfs fi df /home
Data, RAID1: total=144.98GiB, used=140.95GiB
System, RAID1: total=32.00MiB, used=48.00KiB
Metadata, RAID1: total=5.00GiB, used=3.24GiB
GlobalReserve, single: total=512.00MiB, used=0.00B

rand-write: (groupid=1, jobs=1): err= 0: pid=19243: Sat Dec 27 13:48:33 2014
  write: io=140336KB, bw=1018.4KB/s, iops=254, runt=137803msec
    clat (usec): min=4, max=21299K, avg=3708.02, stdev=266885.61
     lat (usec): min=4, max=21299K, avg=3708.14, stdev=266885.61
    clat percentiles (usec):
     |  1.00th=[    4],  5.00th=[    5], 10.00th=[    5], 20.00th=[    5],
     | 30.00th=[    6], 40.00th=[    6], 50.00th=[    6], 60.00th=[    6],
     | 70.00th=[    7], 80.00th=[    7], 90.00th=[    9], 95.00th=[   10],
     | 99.00th=[   18], 99.50th=[   19], 99.90th=[   28], 99.95th=[  116],
     | 99.99th=[16711680]
    bw (KB  /s): min=    0, max= 3426, per=100.00%, avg=1030.10, stdev=938.02
    lat (usec) : 10=92.63%, 20=6.89%, 50=0.43%, 100=0.01%, 250=0.02%
    lat (msec) : 250=0.01%, 500=0.01%, >=2000=0.02%
  cpu          : usr=0.06%, sys=1.59%, ctx=28720, majf=0, minf=7
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=0/w=35084/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=1
[…]
Run status group 1 (all jobs):
  WRITE: io=140336KB, aggrb=1018KB/s, minb=1018KB/s, maxb=1018KB/s, mint=137803msec, maxt=137803msec

That is where I saw this kworker thread at 100% of one Sandybridge core
for minutes. This is where I made kern.log with sysrq-t triggers in

https://bugzilla.kernel.org/show_bug.cgi?id=90401#c0

made from.


But now as I extended it to 170 GiB and did some basic rebalancing
(upto btrfs balance start -dusage=80) I have this:


First attempt:

merkaba:~> date; btrfs fi sh /home ; btrfs fi df /home
So 28. Dez 13:13:47 CET 2014
Label: 'home'  uuid: [some UUID]
        Total devices 2 FS bytes used 151.09GiB
        devid    1 size 170.00GiB used 158.03GiB path /dev/mapper/msata-home
        devid    2 size 170.00GiB used 158.03GiB path /dev/mapper/sata-home

Btrfs v3.17
Data, RAID1: total=153.00GiB, used=147.83GiB
System, RAID1: total=32.00MiB, used=48.00KiB
Metadata, RAID1: total=5.00GiB, used=3.26GiB
GlobalReserve, single: total=512.00MiB, used=0.00B


martin@merkaba:~> fio ssd-test.fio 
rand-write: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=1
fio-2.1.11
Starting 1 process
rand-write: Laying out IO file(s) (1 file(s) / 4096MB)
Jobs: 1 (f=1): [w(1)] [100.0% done] [0KB/84528KB/0KB /s] [0/21.2K/0 iops] [eta 00m:00s]
rand-write: (groupid=0, jobs=1): err= 0: pid=9987: Sun Dec 28 13:14:32 2014
  write: io=4096.0MB, bw=155304KB/s, iops=38826, runt= 27007msec
    clat (usec): min=5, max=28202, avg=22.03, stdev=240.04
     lat (usec): min=5, max=28202, avg=22.28, stdev=240.16
    clat percentiles (usec):
     |  1.00th=[    6],  5.00th=[    7], 10.00th=[    7], 20.00th=[    8],
     | 30.00th=[   10], 40.00th=[   11], 50.00th=[   12], 60.00th=[   13],
     | 70.00th=[   14], 80.00th=[   15], 90.00th=[   17], 95.00th=[   23],
     | 99.00th=[   93], 99.50th=[  175], 99.90th=[ 2096], 99.95th=[ 6816],
     | 99.99th=[10176]
    bw (KB  /s): min=76832, max=413616, per=100.00%, avg=156706.75, stdev=101101.26
    lat (usec) : 10=29.85%, 20=62.43%, 50=5.74%, 100=1.07%, 250=0.57%
    lat (usec) : 500=0.16%, 750=0.04%, 1000=0.02%
    lat (msec) : 2=0.02%, 4=0.01%, 10=0.08%, 20=0.01%, 50=0.01%
  cpu          : usr=12.05%, sys=47.34%, ctx=86985, majf=0, minf=5
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=0/w=1048576/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
  WRITE: io=4096.0MB, aggrb=155304KB/s, minb=155304KB/s, maxb=155304KB/s, mint=27007msec, maxt=27007msec



Second attempt:



merkaba:~> date; btrfs fi sh /home ; btrfs fi df /home
So 28. Dez 13:16:19 CET 2014
Label: 'home'  uuid: [some UUID]
        Total devices 2 FS bytes used 155.11GiB
        devid    1 size 170.00GiB used 162.03GiB path /dev/mapper/msata-home
        devid    2 size 170.00GiB used 162.03GiB path /dev/mapper/sata-home

Btrfs v3.17
Data, RAID1: total=157.00GiB, used=151.83GiB
System, RAID1: total=32.00MiB, used=48.00KiB
Metadata, RAID1: total=5.00GiB, used=3.27GiB
GlobalReserve, single: total=512.00MiB, used=0.00B



martin@merkaba:~> fio ssd-test.fio
rand-write: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=1
fio-2.1.11
Starting 1 process
Jobs: 1 (f=1): [w(1)] [100.0% done] [0KB/113.5MB/0KB /s] [0/29.3K/0 iops] [eta 00m:00s]
rand-write: (groupid=0, jobs=1): err= 0: pid=10043: Sun Dec 28 13:17:34 2014
  write: io=4096.0MB, bw=145995KB/s, iops=36498, runt= 28729msec
    clat (usec): min=4, max=143201, avg=23.95, stdev=518.47
     lat (usec): min=4, max=143201, avg=24.13, stdev=518.48
    clat percentiles (usec):
     |  1.00th=[    6],  5.00th=[    7], 10.00th=[    7], 20.00th=[    8],
     | 30.00th=[    9], 40.00th=[   10], 50.00th=[   11], 60.00th=[   12],
     | 70.00th=[   13], 80.00th=[   13], 90.00th=[   15], 95.00th=[   16],
     | 99.00th=[   33], 99.50th=[   70], 99.90th=[ 5472], 99.95th=[ 8640],
     | 99.99th=[20864]
    bw (KB  /s): min=    4, max=433760, per=100.00%, avg=149179.63, stdev=136784.14
    lat (usec) : 10=38.35%, 20=58.99%, 50=1.96%, 100=0.38%, 250=0.16%
    lat (usec) : 500=0.03%, 750=0.01%, 1000=0.01%
    lat (msec) : 2=0.01%, 4=0.01%, 10=0.08%, 20=0.02%, 50=0.01%
    lat (msec) : 100=0.01%, 250=0.01%
  cpu          : usr=10.25%, sys=42.40%, ctx=42642, majf=0, minf=8
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=0/w=1048576/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
  WRITE: io=4096.0MB, aggrb=145995KB/s, minb=145995KB/s, maxb=145995KB/s, mint=28729msec, maxt=28729msec



Third attempt:

merkaba:~> date; btrfs fi sh /home ; btrfs fi df /home
So 28. Dez 13:18:24 CET 2014
Label: 'home'  uuid: [some UUID]
        Total devices 2 FS bytes used 156.16GiB
        devid    1 size 170.00GiB used 160.03GiB path /dev/mapper/msata-home
        devid    2 size 170.00GiB used 160.03GiB path /dev/mapper/sata-home

Btrfs v3.17
Data, RAID1: total=155.00GiB, used=152.83GiB
System, RAID1: total=32.00MiB, used=48.00KiB
Metadata, RAID1: total=5.00GiB, used=3.34GiB
GlobalReserve, single: total=512.00MiB, used=0.00B


martin@merkaba:~> fio ssd-test.fio
rand-write: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=1
fio-2.1.11
Starting 1 process
Jobs: 1 (f=1): [w(1)] [100.0% done] [0KB/195.7MB/0KB /s] [0/50.9K/0 iops] [eta 00m:00s]
rand-write: (groupid=0, jobs=1): err= 0: pid=10058: Sun Dec 28 13:18:59 2014
  write: io=4096.0MB, bw=202184KB/s, iops=50545, runt= 20745msec
    clat (usec): min=4, max=28261, avg=15.84, stdev=214.59
     lat (usec): min=4, max=28261, avg=16.06, stdev=214.78
    clat percentiles (usec):
     |  1.00th=[    6],  5.00th=[    7], 10.00th=[    7], 20.00th=[    8],
     | 30.00th=[    8], 40.00th=[    9], 50.00th=[   11], 60.00th=[   12],
     | 70.00th=[   12], 80.00th=[   13], 90.00th=[   15], 95.00th=[   17],
     | 99.00th=[   52], 99.50th=[  105], 99.90th=[  426], 99.95th=[  980],
     | 99.99th=[12736]
    bw (KB  /s): min=    4, max=426344, per=100.00%, avg=207355.30, stdev=105104.72
    lat (usec) : 10=41.44%, 20=55.33%, 50=2.17%, 100=0.54%, 250=0.34%
    lat (usec) : 500=0.10%, 750=0.02%, 1000=0.01%
    lat (msec) : 2=0.02%, 4=0.01%, 10=0.01%, 20=0.02%, 50=0.01%
  cpu          : usr=14.15%, sys=59.06%, ctx=81711, majf=0, minf=6
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=0/w=1048576/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
  WRITE: io=4096.0MB, aggrb=202183KB/s, minb=202183KB/s, maxb=202183KB/s, mint=20745msec, maxt=20745msec


merkaba:~> date; btrfs fi sh /home ; btrfs fi df /home
So 28. Dez 13:19:15 CET 2014
Label: 'home'  uuid: [some UUID]
        Total devices 2 FS bytes used 155.16GiB
        devid    1 size 170.00GiB used 162.03GiB path /dev/mapper/msata-home
        devid    2 size 170.00GiB used 162.03GiB path /dev/mapper/sata-home

Btrfs v3.17
Data, RAID1: total=157.00GiB, used=151.85GiB
System, RAID1: total=32.00MiB, used=48.00KiB
Metadata, RAID1: total=5.00GiB, used=3.31GiB
GlobalReserve, single: total=512.00MiB, used=0.00B



So here BTRFS was fast. It is getting trouble on my /home when its
almost full. But more so than with a empty 10 GiB filesystem as I
have shown in testcase
https://bugzilla.kernel.org/show_bug.cgi?id=90401#c3


There I had:

merkaba:/mnt/btrfsraid1> fio ssd-test.fio
rand-write: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=1
fio-2.1.11
Starting 1 process
rand-write: Laying out IO file(s) (1 file(s) / 4096MB)
Jobs: 1 (f=1): [w(1)] [100.0% done] [0KB/20924KB/0KB /s] [0/5231/0 iops] [eta 00m:00s]
rand-write: (groupid=0, jobs=1): err= 0: pid=6221: Sat Dec 27 15:34:14 2014
  write: io=2645.8MB, bw=22546KB/s, iops=5636, runt=120165msec
    clat (usec): min=4, max=3054.8K, avg=174.87, stdev=11455.26
     lat (usec): min=4, max=3054.8K, avg=175.03, stdev=11455.27
    clat percentiles (usec):
     |  1.00th=[    6],  5.00th=[    6], 10.00th=[    6], 20.00th=[    7],
     | 30.00th=[    7], 40.00th=[    8], 50.00th=[    9], 60.00th=[   10],
     | 70.00th=[   11], 80.00th=[   12], 90.00th=[   14], 95.00th=[   17],
     | 99.00th=[   30], 99.50th=[   40], 99.90th=[ 1992], 99.95th=[25984],
     | 99.99th=[411648]
    bw (KB  /s): min=  168, max=70703, per=100.00%, avg=27325.46, stdev=14887.94
    lat (usec) : 10=55.81%, 20=41.12%, 50=2.70%, 100=0.14%, 250=0.06%
    lat (usec) : 500=0.02%, 750=0.01%, 1000=0.02%
    lat (msec) : 2=0.02%, 4=0.02%, 10=0.02%, 20=0.01%, 50=0.01%
    lat (msec) : 100=0.01%, 250=0.01%, 500=0.02%, 750=0.01%, 1000=0.01%
    lat (msec) : 2000=0.01%, >=2000=0.01%
  cpu          : usr=1.56%, sys=5.57%, ctx=29822, majf=0, minf=7
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued    : total=r=0/w=677303/d=0, short=r=0/w=0/d=0
     latency   : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
  WRITE: io=2645.8MB, aggrb=22545KB/s, minb=22545KB/s, maxb=22545KB/s, mint=120165msec, maxt=120165msec



-- 
Martin 'Helios' Steigerwald - http://www.Lichtvoll.de
GPG: 03B0 0D6C 0040 0710 4AFA  B82F 991B EAAC A599 84C7

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 181 bytes --]