Fwd: xfs remove / unlink extremely slow ?

Fwd: xfs remove / unlink extremely slow ?

[Michael Arndt]

Hello XFS Gurus,

Problem: /bin/rm extremely slow on a major xfs (SSD based) HPC Storage
slow == 90 seconds for unlink of an empty file without any extents
strace says: time completely used for unlink call

Question; Is there any issue resolution ?

Information re XFS Version and OS at end of this Post

Example of issue:


[root@atgrzsl3150 DOM_0]# xfs_bmap -a .AN_720.0000122.fl3step_0.lock 

.AN_720.0000122.fl3step_0.lock: no extents
[root@atgrzsl3150 DOM_0]# ls -laFtr .AN_720.0000122.fl3step_0.lock 

-rw-rw-r-- 1 user group 0 Oct 22 14:14 .AN_720.0000122.fl3step_0.lock


strace -T -tt /bin/rm .AN_720.0000122.fl3step_0.lock 


1:41:11.621005 execve("/bin/rm", ["/bin/rm", ".AN_720.0000122.fl3step_0.lock"], [/* 31 vars */]) = 0 <0.000169>11:41:11.621312 brk(NULL)               = 0x6f5000 <0.000023>11:41:11.621378 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f4d96017000 <0.000058>
…….
11:41:11.622485 newfstatat(AT_FDCWD, ".AN_720.0000122.fl3step_0.lock", {st_mode=S_IFREG|0664, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0 <0.000009>
11:41:11.622522 geteuid()               = 0 <0.000009>
-> 11:41:11.622546 unlinkat(AT_FDCWD, ".AN_720.0000122.fl3step_0.lock", 0) = 0 <89.612833>
-> 11:42:41.235428 lseek(0, 0, SEEK_CUR)   = -1 ESPIPE (Illegal seek) <0.000065>
11:42:41.235548 close(0)                = 0 <0.000052>
11:42:41.235689 close(1)                = 0 <0.000011>
11:42:41.235738 close(2)                = 0 <0.000055>
11:42:41.235830 exit_group(0)           = ?
11:42:41.235941 +++ exited with 0 +++

xfs_info /dev/mapper/vg_calc2-calc2
meta-data=/dev/mapper/vg_calc2-calc2 isize=512    agcount=50, agsize=268435448 blks
        =                       sectsz=512   attr=2, projid32bit=1
        =                       crc=1        finobt=0 spinodes=0
data     =                       bsize=4096   blocks=13421711360, imaxpct=20
        =                       sunit=8      swidth=40 blks
naming   =version 2              bsize=4096   ascii-ci=0 ftype=1
log      =internal               bsize=4096   blocks=521728, version=2
        =                       sectsz=512   sunit=8 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0

Issue on:

xfsprogs-4.5.0-18.el7.x86_64
xfsdump-3.1.7-1.el7.x86_64
Red Hat Enterprise Linux Server release 7.4 (Maipo)
df -kh .
Filesystem                  Size  Used Avail Use% Mounted on
/dev/mapper/vg_calc2        50T   20T   31T  40% /calc2

Layers: 

SSD based commercial Storage exports many small LUN’s -> LUN#s striped via LVM2 for speed, xfs with default opts on top of LVM
Currently no discard Option for mount and no fstrim manually called

Mount Options used
/dev/mapper/vg_calc2-calc2 /calc2 xfs noatime,delaylog,nobarrier,nodiratime,logbsize=256k,logbufs=8 0 0 

thanks for any tip / hint / question
Micha

Re: Fwd: xfs remove / unlink extremely slow ?

[Brian Foster]

On Wed, Nov 14, 2018 at 12:42:49PM +0100, Michael Arndt wrote:
> Hello XFS Gurus,
> 
> Problem: /bin/rm extremely slow on a major xfs (SSD based) HPC Storage
> slow == 90 seconds for unlink of an empty file without any extents
> strace says: time completely used for unlink call
> 
> Question; Is there any issue resolution ?
> 
> Information re XFS Version and OS at end of this Post
> 
> Example of issue:
> 
> 
> [root@atgrzsl3150 DOM_0]# xfs_bmap -a .AN_720.0000122.fl3step_0.lock 
> 
> .AN_720.0000122.fl3step_0.lock: no extents
> [root@atgrzsl3150 DOM_0]# ls -laFtr .AN_720.0000122.fl3step_0.lock 
> 
> -rw-rw-r-- 1 user group 0 Oct 22 14:14 .AN_720.0000122.fl3step_0.lock
> 
> 
> strace -T -tt /bin/rm .AN_720.0000122.fl3step_0.lock 
> 
> 
> 1:41:11.621005 execve("/bin/rm", ["/bin/rm", ".AN_720.0000122.fl3step_0.lock"], [/* 31 vars */]) = 0 <0.000169>11:41:11.621312 brk(NULL)               = 0x6f5000 <0.000023>11:41:11.621378 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f4d96017000 <0.000058>
> …….
> 11:41:11.622485 newfstatat(AT_FDCWD, ".AN_720.0000122.fl3step_0.lock", {st_mode=S_IFREG|0664, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0 <0.000009>
> 11:41:11.622522 geteuid()               = 0 <0.000009>
> -> 11:41:11.622546 unlinkat(AT_FDCWD, ".AN_720.0000122.fl3step_0.lock", 0) = 0 <89.612833>
> -> 11:42:41.235428 lseek(0, 0, SEEK_CUR)   = -1 ESPIPE (Illegal seek) <0.000065>
> 11:42:41.235548 close(0)                = 0 <0.000052>
> 11:42:41.235689 close(1)                = 0 <0.000011>
> 11:42:41.235738 close(2)                = 0 <0.000055>
> 11:42:41.235830 exit_group(0)           = ?
> 11:42:41.235941 +++ exited with 0 +++
> 

It might be useful to do something like:

  trace-cmd record -e xfs:* <rm command>

... and either put the resulting trace.dat somewhere where it can be
downloaded or if not too large, run 'trace-cmd report' and copy the text
into a mail (without reformatting it).

Brian

> xfs_info /dev/mapper/vg_calc2-calc2
> meta-data=/dev/mapper/vg_calc2-calc2 isize=512    agcount=50, agsize=268435448 blks
>         =                       sectsz=512   attr=2, projid32bit=1
>         =                       crc=1        finobt=0 spinodes=0
> data     =                       bsize=4096   blocks=13421711360, imaxpct=20
>         =                       sunit=8      swidth=40 blks
> naming   =version 2              bsize=4096   ascii-ci=0 ftype=1
> log      =internal               bsize=4096   blocks=521728, version=2
>         =                       sectsz=512   sunit=8 blks, lazy-count=1
> realtime =none                   extsz=4096   blocks=0, rtextents=0
> 
> Issue on:
> 
> xfsprogs-4.5.0-18.el7.x86_64
> xfsdump-3.1.7-1.el7.x86_64
> Red Hat Enterprise Linux Server release 7.4 (Maipo)
> df -kh .
> Filesystem                  Size  Used Avail Use% Mounted on
> /dev/mapper/vg_calc2        50T   20T   31T  40% /calc2
> 
> Layers: 
> 
> SSD based commercial Storage exports many small LUN’s -> LUN#s striped via LVM2 for speed, xfs with default opts on top of LVM
> Currently no discard Option for mount and no fstrim manually called
> 
> Mount Options used
> /dev/mapper/vg_calc2-calc2 /calc2 xfs noatime,delaylog,nobarrier,nodiratime,logbsize=256k,logbufs=8 0 0 
> 
> thanks for any tip / hint / question
> Micha
> 

Re: Fwd: xfs remove / unlink extremely slow ?

[Brian Foster]

On Wed, Nov 14, 2018 at 09:45:11AM -0500, Brian Foster wrote:
> On Wed, Nov 14, 2018 at 12:42:49PM +0100, Michael Arndt wrote:
> > Hello XFS Gurus,
> > 
> > Problem: /bin/rm extremely slow on a major xfs (SSD based) HPC Storage
> > slow == 90 seconds for unlink of an empty file without any extents
> > strace says: time completely used for unlink call
> > 
> > Question; Is there any issue resolution ?
> > 
> > Information re XFS Version and OS at end of this Post
> > 
> > Example of issue:
> > 
> > 
> > [root@atgrzsl3150 DOM_0]# xfs_bmap -a .AN_720.0000122.fl3step_0.lock 
> > 
> > .AN_720.0000122.fl3step_0.lock: no extents
> > [root@atgrzsl3150 DOM_0]# ls -laFtr .AN_720.0000122.fl3step_0.lock 
> > 
> > -rw-rw-r-- 1 user group 0 Oct 22 14:14 .AN_720.0000122.fl3step_0.lock
> > 
> > 
> > strace -T -tt /bin/rm .AN_720.0000122.fl3step_0.lock 
> > 
> > 
> > 1:41:11.621005 execve("/bin/rm", ["/bin/rm", ".AN_720.0000122.fl3step_0.lock"], [/* 31 vars */]) = 0 <0.000169>11:41:11.621312 brk(NULL)               = 0x6f5000 <0.000023>11:41:11.621378 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f4d96017000 <0.000058>
> > …….
> > 11:41:11.622485 newfstatat(AT_FDCWD, ".AN_720.0000122.fl3step_0.lock", {st_mode=S_IFREG|0664, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0 <0.000009>
> > 11:41:11.622522 geteuid()               = 0 <0.000009>
> > -> 11:41:11.622546 unlinkat(AT_FDCWD, ".AN_720.0000122.fl3step_0.lock", 0) = 0 <89.612833>
> > -> 11:42:41.235428 lseek(0, 0, SEEK_CUR)   = -1 ESPIPE (Illegal seek) <0.000065>
> > 11:42:41.235548 close(0)                = 0 <0.000052>
> > 11:42:41.235689 close(1)                = 0 <0.000011>
> > 11:42:41.235738 close(2)                = 0 <0.000055>
> > 11:42:41.235830 exit_group(0)           = ?
> > 11:42:41.235941 +++ exited with 0 +++
> > 
> 
> It might be useful to do something like:
> 
>   trace-cmd record -e xfs:* <rm command>
> 
> ... and either put the resulting trace.dat somewhere where it can be
> downloaded or if not too large, run 'trace-cmd report' and copy the text
> into a mail (without reformatting it).
> 
> Brian
> 

Michael provided the tracepoint data requested above privately. In
short, it shows the delay but doesn't provide enough context to root
cause. The relevant snippets are shown below.

rm-23740 [003] 1902680.707761: xfs_filemap_fault:    dev 253:0 ino 0x8e392
...
rm-23740 [042] 1902680.708246: xfs_iunlock:          dev 253:0 ino 0x201b46a flags MMAPLOCK_SHARED caller xfs_filemap_fault
rm-23740 [022] 1902770.759100: xfs_remove:           dev 253:84 dp ino 0xb00a143cd name .AN_718.0000122.fl3step_0.lock
...
rm-23740 [022] 1902770.759276: xfs_iunlock:          dev 253:0 ino 0x201b463 flags IOLOCK_EXCL caller xfs_release

This shows the very first event emitted by the process, up through the
xfs_remove event, followed by the very last event emitted by the
process. The time between XFS receiving the unlink request and the last
event is under 1ms. The time between the first event and xfs_remove is
90s, but that's about the same gap as between the event immediately
prior to xfs_remove so we don't know exactly what's happening there.

The strace shows this time within unlinkat(), so I suspect some portion
of the VFS aspect of this operation is consuming this time. If lookups
were the problem, I'd expect to see xfs_lookup events in the trace.

Hmm, I think you might have to try and collect some more data to
identify the problem. A simple thing to check might be to 'cat /proc/<rm
pid>/stack' while the rm is stuck and see if that shows anything useful.
If not, perhaps 'trace-cmd record -p function_graph <rm cmd>' will show
enough to make sense of the problem. Note that the latter might generate
a ton of data and so might be easier to trace through yourself. Run
'trace-cmd report > trace.out' to generate a text file from the
resulting trace.dat and poke through that to try and find the
delay/latency.

Brian

> > xfs_info /dev/mapper/vg_calc2-calc2
> > meta-data=/dev/mapper/vg_calc2-calc2 isize=512    agcount=50, agsize=268435448 blks
> >         =                       sectsz=512   attr=2, projid32bit=1
> >         =                       crc=1        finobt=0 spinodes=0
> > data     =                       bsize=4096   blocks=13421711360, imaxpct=20
> >         =                       sunit=8      swidth=40 blks
> > naming   =version 2              bsize=4096   ascii-ci=0 ftype=1
> > log      =internal               bsize=4096   blocks=521728, version=2
> >         =                       sectsz=512   sunit=8 blks, lazy-count=1
> > realtime =none                   extsz=4096   blocks=0, rtextents=0
> > 
> > Issue on:
> > 
> > xfsprogs-4.5.0-18.el7.x86_64
> > xfsdump-3.1.7-1.el7.x86_64
> > Red Hat Enterprise Linux Server release 7.4 (Maipo)
> > df -kh .
> > Filesystem                  Size  Used Avail Use% Mounted on
> > /dev/mapper/vg_calc2        50T   20T   31T  40% /calc2
> > 
> > Layers: 
> > 
> > SSD based commercial Storage exports many small LUN’s -> LUN#s striped via LVM2 for speed, xfs with default opts on top of LVM
> > Currently no discard Option for mount and no fstrim manually called
> > 
> > Mount Options used
> > /dev/mapper/vg_calc2-calc2 /calc2 xfs noatime,delaylog,nobarrier,nodiratime,logbsize=256k,logbufs=8 0 0 
> > 
> > thanks for any tip / hint / question
> > Micha
> > 

Re: xfs remove / unlink extremely slow ?

[Michael Arndt]

Brian,

Info, supporting your remark about VFS layer: 

I did a reboot of cluster headnode and after that the remove was „fast“ meanig the typical millsecond /single file  to seconds /  removal of whole trees.

What does your intuition say, what could be suspected in the VFS layer / lvm2 layer or below to trigger this problem 
( just to collect ideas, where to search). ?

Caused by the fact, that the problem was seen also two times before, the issue will reappear after some time.

Off topic: is the mount option delaylog still functional or obsoleted, because already default behaviour ?

best
Micha
thx for extremely friendly help

Re: xfs remove / unlink extremely slow ?

[Michael Arndt]

Brian,

Info, supporting your remark about VFS layer: 

I did a reboot of cluster headnode and after that the remove was „fast“ meanig the typical millsecond /single file  to seconds /  removal of whole trees.

What does your intuition say, what could be suspected in the VFS layer / lvm2 layer or below to trigger this problem 
( just to collect ideas, where to search). ?

Caused by the fact, that the problem was seen also two times before, the issue will reappear after some time.

Off topic: is the mount option delaylog still functional or obsoleted, because already default behaviour ?

best
Micha
thx for extremely friendly help

Re: xfs remove / unlink extremely slow ?

[Brian Foster]

On Thu, Nov 15, 2018 at 06:07:46PM +0100, Michael Arndt wrote:
> Brian,
> 
> Info, supporting your remark about VFS layer: 
> 
> I did a reboot of cluster headnode and after that the remove was „fast“ meanig the typical millsecond /single file  to seconds /  removal of whole trees.
> 
> What does your intuition say, what could be suspected in the VFS layer / lvm2 layer or below to trigger this problem 
> ( just to collect ideas, where to search). ?
> 

If the problem only occurs after a period of time like this, I suppose
that could suggest some kind of cache effect is contributing to it. You
could see if an 'echo 2 > /proc/sys/vm/drop_caches' clears the problem
once it occurs, for example, but note that will clear all cached
dentries/inodes on the system.

I'm not familiar enough with the VFS code and associated caching to
speculate much beyond that. Other things that might be interesting are
whether other operations on said file take the same amount of time
(i.e., an mv before an rm?), whether this is a common filename pattern
that sees a lot of create/delete operations (perhaps polluting a lookup
cache with unlinked entries? i.e., does changing the filename have any
effect?), whether a relocation of the file to another directory changes
anything, whether other operations in the same dir on unrelated files
show the same problem, etc.

Your best bet is probably to collect as much trace data as you can and
then possibly report this to the general linux-fsdevel mailing list.
Note that if you're using a distro kernel, it might be more appropriate
to report an issue with your distro vendor than an upstream list.

Brian

> Caused by the fact, that the problem was seen also two times before, the issue will reappear after some time.
> 
> Off topic: is the mount option delaylog still functional or obsoleted, because already default behaviour ?
> 
> best
> Micha
> thx for extremely friendly help
> 

Re: Fwd: xfs remove / unlink extremely slow ?

[Dave Chinner]

On Thu, Nov 15, 2018 at 10:38:16AM -0500, Brian Foster wrote:
> On Wed, Nov 14, 2018 at 09:45:11AM -0500, Brian Foster wrote:
> > On Wed, Nov 14, 2018 at 12:42:49PM +0100, Michael Arndt wrote:
> > > Hello XFS Gurus,
> > > 
> > > Problem: /bin/rm extremely slow on a major xfs (SSD based) HPC Storage
> > > slow == 90 seconds for unlink of an empty file without any extents
> > > strace says: time completely used for unlink call
> > > 
> > > Question; Is there any issue resolution ?
> > > 
> > > Information re XFS Version and OS at end of this Post
> > > 
> > > Example of issue:
> > > 
> > > 
> > > [root@atgrzsl3150 DOM_0]# xfs_bmap -a .AN_720.0000122.fl3step_0.lock 
> > > 
> > > .AN_720.0000122.fl3step_0.lock: no extents
> > > [root@atgrzsl3150 DOM_0]# ls -laFtr .AN_720.0000122.fl3step_0.lock 
> > > 
> > > -rw-rw-r-- 1 user group 0 Oct 22 14:14 .AN_720.0000122.fl3step_0.lock
> > > 
> > > 
> > > strace -T -tt /bin/rm .AN_720.0000122.fl3step_0.lock 
> > > 
> > > 
> > > 1:41:11.621005 execve("/bin/rm", ["/bin/rm", ".AN_720.0000122.fl3step_0.lock"], [/* 31 vars */]) = 0 <0.000169>11:41:11.621312 brk(NULL)               = 0x6f5000 <0.000023>11:41:11.621378 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f4d96017000 <0.000058>
> > > …….
> > > 11:41:11.622485 newfstatat(AT_FDCWD, ".AN_720.0000122.fl3step_0.lock", {st_mode=S_IFREG|0664, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0 <0.000009>
> > > 11:41:11.622522 geteuid()               = 0 <0.000009>
> > > -> 11:41:11.622546 unlinkat(AT_FDCWD, ".AN_720.0000122.fl3step_0.lock", 0) = 0 <89.612833>
> > > -> 11:42:41.235428 lseek(0, 0, SEEK_CUR)   = -1 ESPIPE (Illegal seek) <0.000065>
> > > 11:42:41.235548 close(0)                = 0 <0.000052>
> > > 11:42:41.235689 close(1)                = 0 <0.000011>
> > > 11:42:41.235738 close(2)                = 0 <0.000055>
> > > 11:42:41.235830 exit_group(0)           = ?
> > > 11:42:41.235941 +++ exited with 0 +++
> > > 
> > 
> > It might be useful to do something like:
> > 
> >   trace-cmd record -e xfs:* <rm command>
> > 
> > ... and either put the resulting trace.dat somewhere where it can be
> > downloaded or if not too large, run 'trace-cmd report' and copy the text
> > into a mail (without reformatting it).
> > 
> > Brian
> > 
> 
> Michael provided the tracepoint data requested above privately. In
> short, it shows the delay but doesn't provide enough context to root
> cause. The relevant snippets are shown below.
> 
> rm-23740 [003] 1902680.707761: xfs_filemap_fault:    dev 253:0 ino 0x8e392
> ...
> rm-23740 [042] 1902680.708246: xfs_iunlock:          dev 253:0 ino 0x201b46a flags MMAPLOCK_SHARED caller xfs_filemap_fault
> rm-23740 [022] 1902770.759100: xfs_remove:           dev 253:84 dp ino 0xb00a143cd name .AN_718.0000122.fl3step_0.lock
> ...
> rm-23740 [022] 1902770.759276: xfs_iunlock:          dev 253:0 ino 0x201b463 flags IOLOCK_EXCL caller xfs_release

This kinda reminds me of what happens where then is a memory
allocation stall. You just see a long delay between XFS tracepoints
and there's nothing else in the trace. But that's unlikely, because
the brk() call was not delayed at all..

There could be multiple things going on here, though. For example,
before calling ->unlink and getting into XFS, the vfs calls
try_break_deleg() to break delegation leases. If that fails, it
backs out, breaks the delegation and waits on it before retrying the
unlink.

So if the filesystem is exported by NFS, or it's some kind of
userspace delegation lock file, could could see this sort of delay
occurring while the delegation is recalled and released. Indeed,
89.6s is strikingly close to the default NFS reponse timeouts
of 90s.

Food for thought...

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com