Skip to contentSkip to conversation

very slow file deletion on an SSD

DISCUSSION Joe Landman 13 participants 25 messages May 25, 2012 – May 27, 2012 MD RAID

lore
Share & tools
lore
#0 lore raw

Hi folks:

Just ran into this (see posted output at bottom). 3.2.14 kernel, MD
RAID 5, xfs file system. Not sure (precisely) where the problem is, hence posting to both lists.

[root@siFlash ~]# cat /proc/mdstat
Personalities : [raid1] [raid6] [raid5] [raid4]
md22 : active raid5 sdl[0] sds[7] sdx[6] sdu[5] sdk[4] sdz[3] sdw[2] sdr[1]

      1641009216 blocks super 1.2 level 5, 32k chunk, algorithm 2 [8/8] 

[UUUUUUUU]

md20 : active raid5 sdh[0] sdf[7] sdm[6] sdd[5] sdc[4] sde[3] sdi[2] sdg[1]

      1641009216 blocks super 1.2 level 5, 32k chunk, algorithm 2 [8/8] 

[UUUUUUUU]

md21 : active raid5 sdy[0] sdq[7] sdp[6] sdo[5] sdn[4] sdj[3] sdv[2] sdt[1]

      1641009216 blocks super 1.2 level 5, 32k chunk, algorithm 2 [8/8] 

[UUUUUUUU]

md0 : active raid1 sdb1[1] sda1[0]

      93775800 blocks super 1.0 [2/2] [UU]
      bitmap: 1/1 pages [4KB], 65536KB chunk

md2* are SSD RAID5 arrays we are experimenting with. Xfs file systems atop them:

[root@siFlash ~]# mount | grep md2
/dev/md20 on /data/1 type xfs (rw)
/dev/md21 on /data/2 type xfs (rw)
/dev/md22 on /data/3 type xfs (rw)

vanilla mount options (following Dave Chinner's long standing advice)

meta-data=/dev/md20              isize=2048   agcount=32, agsize=12820392 blks
         =                       sectsz=512   attr=2
data     =                       bsize=4096   blocks=410252304, imaxpct=5
         =                       sunit=8      swidth=56 blks
naming   =version 2              bsize=65536  ascii-ci=0
log      =internal               bsize=4096   blocks=30720, version=2
         =                       sectsz=512   sunit=8 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0

[root@siFlash ~]# mdadm --detail /dev/md20
/dev/md20:

        Version : 1.2

Creation Time : Sun Apr 1 19:36:39 2012
Raid Level : raid5
Array Size : 1641009216 (1564.99 GiB 1680.39 GB)
Used Dev Size : 234429888 (223.57 GiB 240.06 GB)
Raid Devices : 8
Total Devices : 8
Persistence : Superblock is persistent

Update Time : Fri May 25 06:26:23 2012
State : clean
Active Devices : 8
Working Devices : 8
Failed Devices : 0
Spare Devices : 0

Layout : left-symmetric
Chunk Size : 32K

Name : siFlash.sicluster:20
UUID : 2f023323:6ec29eb9:a943de06:f6e0c25d
Events : 296

Number Major Minor RaidDevice State
0 8 112 0 active sync /dev/sdh
1 8 96 1 active sync /dev/sdg
2 8 128 2 active sync /dev/sdi
3 8 64 3 active sync /dev/sde
4 8 32 4 active sync /dev/sdc
5 8 48 5 active sync /dev/sdd
6 8 192 6 active sync /dev/sdm
7 8 80 7 active sync /dev/sdf

All the SSDs are on deadline scheduler

[root@siFlash ~]# cat /sys/block/sd*/queue/scheduler | uniq noop [deadline] cfq

All this said, deletes from this unit are taking 1-2 seconds per file ...

[root@siFlash ~]# strace -ttt -T rm -f /data/2/test/*
1337941514.040788 execve("/bin/rm", ["rm", "-f", "/data/2/test/2.8t-r.97.0", "/data/2/test/2.8t-r.98.0", "/data/2/test/2.8t-r.99.0", "/data/2/test/2.9.0"], [/* 40 vars */]) = 0 <0.000552>
1337941514.041713 brk(0) = 0x60d000 <0.000031>
1337941514.041927 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7bc2779000 <0.000032>
1337941514.042113 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) <0.000109>
1337941514.042395 open("/etc/ld.so.cache", O_RDONLY) = 3 <0.000050>
1337941514.042614 fstat(3, {st_mode=S_IFREG|0644, st_size=81118, ...}) = 0 <0.000102>
1337941514.042928 mmap(NULL, 81118, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f7bc2765000 <0.000042>
1337941514.043078 close(3) = 0 <0.000019>
1337941514.043235 open("/lib64/libc.so.6", O_RDONLY) = 3 <0.000115>
1337941514.043477 read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360\355\301W4\0\0\0"..., 832) = 832 <0.000039>
1337941514.043647 fstat(3, {st_mode=S_IFREG|0755, st_size=1908792, ...}) = 0 <0.000020>
1337941514.043860 mmap(0x3457c00000, 3733672, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3457c00000 <0.000085>
1337941514.044065 mprotect(0x3457d86000, 2097152, PROT_NONE) = 0 <0.000034>

1337941514.044191 mmap(0x3457f86000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x186000) = 0x3457f86000 <0.000034>
1337941514.044388 mmap(0x3457f8b000, 18600, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x3457f8b000 <0.000085>
1337941514.044592 close(3)              = 0 <0.000058>
1337941514.044763 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7bc2764000 <0.000039>
1337941514.044893 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7bc2763000 <0.000020>
1337941514.044981 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7bc2762000 <0.000018>

1337941514.045076 arch_prctl(ARCH_SET_FS, 0x7f7bc2763700) = 0 <0.000018>
1337941514.045183 mprotect(0x3457f86000, 16384, PROT_READ) = 0 <0.000023>
1337941514.045270 mprotect(0x345761f000, 4096, PROT_READ) = 0 <0.000019>
1337941514.045350 munmap(0x7f7bc2765000, 81118) = 0 <0.000028>
1337941514.045619 brk(0) = 0x60d000 <0.000017>
1337941514.045698 brk(0x62e000) = 0x62e000 <0.000018>
1337941514.045803 open("/usr/lib/locale/locale-archive", O_RDONLY) = 3 <0.000028>
1337941514.045904 fstat(3, {st_mode=S_IFREG|0644, st_size=99158704, ...}) = 0 <0.000017>
1337941514.046012 mmap(NULL, 99158704, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f7bbc8d1000 <0.000020>
1337941514.046099 close(3) = 0 <0.000017>
1337941514.046235 ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0 <0.000020> 1337941514.046373 newfstatat(AT_FDCWD, "/data/2/test/2.8t-r.97.0", {st_mode=S_IFREG|0600, st_size=1073741824, ...}, AT_SYMLINK_NOFOLLOW) = 0 <0.000024> 1337941514.046504 unlinkat(AT_FDCWD, "/data/2/test/2.8t-r.97.0", 0) = 0 <1.357571>
1337941515.404257 newfstatat(AT_FDCWD, "/data/2/test/2.8t-r.98.0", {st_mode=S_IFREG|0600, st_size=1073741824, ...}, AT_SYMLINK_NOFOLLOW) = 0 <0.000072> 1337941515.404485 unlinkat(AT_FDCWD, "/data/2/test/2.8t-r.98.0", 0) = 0 <1.608016>
1337941517.012706 newfstatat(AT_FDCWD, "/data/2/test/2.8t-r.99.0", {st_mode=S_IFREG|0600, st_size=1073741824, ...}, AT_SYMLINK_NOFOLLOW) = 0 <0.000082> 1337941517.012957 unlinkat(AT_FDCWD, "/data/2/test/2.8t-r.99.0", 0) = 0 <1.133890>
1337941518.146983 newfstatat(AT_FDCWD, "/data/2/test/2.9.0", {st_mode=S_IFREG|0600, st_size=8589934592, ...}, AT_SYMLINK_NOFOLLOW) = 0 <0.000023> 1337941518.147145 unlinkat(AT_FDCWD, "/data/2/test/2.9.0", 0) = 0 <0.938754>

1337941519.086125 close(0)              = 0 <0.000102>
1337941519.086357 close(1)              = 0 <0.000061>
1337941519.086540 close(2)              = 0 <0.000021>
1337941519.086694 exit_group(0)         = ?

Anything obvious that we are doing wrong?

Machine may be occupied for a bit. Might be a few days before we can get results back.

Signature · 9 lines
Joseph Landman, Ph.D
Founder and CEO
Scalable Informatics Inc.
email: [email protected]
web  : http://scalableinformatics.com
       http://scalableinformatics.com/sicluster
phone: +1 734 786 8423 x121
fax  : +1 866 888 3112
cell : +1 734 612 4615
#1 lore raw

Hello Joe,

Quoted 5 lines · Joe Landman

Hi folks:

Just ran into this (see posted output at bottom). 3.2.14 kernel, MD RAID 5, xfs file system. Not sure (precisely) where the problem is, hence posting to both lists.

do you have anything enabled, that would make your files to have xattrs?

http://oss.sgi.com/archives/xfs/2011-08/msg00233.html

Cheers,
Bernd

#2 lore raw
Quoted 10 lines · Bernd Schubert

Hello Joe,

Quoted 5 lines · Joe Landman

Hi folks:

Just ran into this (see posted output at bottom). 3.2.14 kernel, MD RAID 5, xfs file system. Not sure (precisely) where the problem is, hence posting to both lists.

do you have anything enabled, that would make your files to have xattrs?

Not to my knowledge. I'll go back and re-create some files and see.

Quoted 1 line

http://oss.sgi.com/archives/xfs/2011-08/msg00233.html

Hmmm

Signature · 9 lines
Joseph Landman, Ph.D
Founder and CEO
Scalable Informatics Inc.
email: [email protected]
web  : http://scalableinformatics.com
       http://scalableinformatics.com/sicluster
phone: +1 734 786 8423 x121
fax  : +1 866 888 3112
cell : +1 734 612 4615
#3 lore raw

noop scheduler could be better for ssd?

2012/5/25 Joe Landman <[email protected]>:

Quoted 40 lines · Bernd Schubert
Quoted 5 lines

Hello Joe,

Quoted 1 line · Joe Landman
Quoted 8 lines
Quoted 5 lines

Hi folks:

Just ran into this (see posted output at bottom). 3.2.14 kernel, MD RAID 5, xfs file system. Not sure (precisely) where the problem is, hence posting to both lists.

do you have anything enabled, that would make your files to have xattrs?

Not to my knowledge.  I'll go back and re-create some files and see.

Quoted 1 line

http://oss.sgi.com/archives/xfs/2011-08/msg00233.html

Hmmm

--
Joseph Landman, Ph.D
Founder and CEO
Scalable Informatics Inc.
email: [email protected]
web  : http://scalableinformatics.com
      http://scalableinformatics.com/sicluster
phone: +1 734 786 8423 x121
fax  : +1 866 888 3112
cell : +1 734 612 4615

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

Signature · 6 lines
Roberto Spadim
Spadim Technology / SPAEmpresarial
--
To unsubscribe from this list: send the line "unsubscribe linux-raid" in
the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Reviewed-by Christoph Hellwig Reviewed-by Christoph Hellwig
#4 lore raw
In reply to Joe Landman

Hey Joe,

Quoted 157 lines · Joe Landman

Just ran into this (see posted output at bottom). 3.2.14 kernel,
MD RAID 5, xfs file system. Not sure (precisely) where the problem is, hence posting to both lists.

[root@siFlash ~]# cat /proc/mdstat
Personalities : [raid1] [raid6] [raid5] [raid4]
md22 : active raid5 sdl[0] sds[7] sdx[6] sdu[5] sdk[4] sdz[3] sdw[2] sdr[1]

      1641009216 blocks super 1.2 level 5, 32k chunk, algorithm 2

[8/8] [UUUUUUUU]

md20 : active raid5 sdh[0] sdf[7] sdm[6] sdd[5] sdc[4] sde[3] sdi[2] sdg[1]

      1641009216 blocks super 1.2 level 5, 32k chunk, algorithm 2

[8/8] [UUUUUUUU]

md21 : active raid5 sdy[0] sdq[7] sdp[6] sdo[5] sdn[4] sdj[3] sdv[2] sdt[1]

      1641009216 blocks super 1.2 level 5, 32k chunk, algorithm 2

[8/8] [UUUUUUUU]

md0 : active raid1 sdb1[1] sda1[0]

      93775800 blocks super 1.0 [2/2] [UU]
      bitmap: 1/1 pages [4KB], 65536KB chunk

md2* are SSD RAID5 arrays we are experimenting with. Xfs file systems atop them:

[root@siFlash ~]# mount | grep md2
/dev/md20 on /data/1 type xfs (rw)
/dev/md21 on /data/2 type xfs (rw)
/dev/md22 on /data/3 type xfs (rw)

vanilla mount options (following Dave Chinner's long standing advice)

meta-data=/dev/md20 isize=2048 agcount=32,
agsize=12820392 blks

         =                       sectsz=512   attr=2
data     =                       bsize=4096   blocks=410252304, imaxpct=5
         =                       sunit=8      swidth=56 blks
naming   =version 2              bsize=65536  ascii-ci=0
log      =internal               bsize=4096   blocks=30720, version=2
         =                       sectsz=512   sunit=8 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0

[root@siFlash ~]# mdadm --detail /dev/md20
/dev/md20:

        Version : 1.2

Creation Time : Sun Apr 1 19:36:39 2012
Raid Level : raid5
Array Size : 1641009216 (1564.99 GiB 1680.39 GB)
Used Dev Size : 234429888 (223.57 GiB 240.06 GB)
Raid Devices : 8
Total Devices : 8
Persistence : Superblock is persistent

Update Time : Fri May 25 06:26:23 2012
State : clean
Active Devices : 8
Working Devices : 8
Failed Devices : 0
Spare Devices : 0

Layout : left-symmetric
Chunk Size : 32K

Name : siFlash.sicluster:20
UUID : 2f023323:6ec29eb9:a943de06:f6e0c25d
Events : 296

Number Major Minor RaidDevice State
0 8 112 0 active sync /dev/sdh
1 8 96 1 active sync /dev/sdg
2 8 128 2 active sync /dev/sdi
3 8 64 3 active sync /dev/sde
4 8 32 4 active sync /dev/sdc
5 8 48 5 active sync /dev/sdd
6 8 192 6 active sync /dev/sdm
7 8 80 7 active sync /dev/sdf

All the SSDs are on deadline scheduler

[root@siFlash ~]# cat /sys/block/sd*/queue/scheduler | uniq noop [deadline] cfq

All this said, deletes from this unit are taking 1-2 seconds per file ...

[root@siFlash ~]# strace -ttt -T rm -f /data/2/test/*
1337941514.040788 execve("/bin/rm", ["rm", "-f",
"/data/2/test/2.8t-r.97.0", "/data/2/test/2.8t-r.98.0", "/data/2/test/2.8t-r.99.0", "/data/2/test/2.9.0"], [/* 40 vars */])
= 0 <0.000552>
1337941514.041713 brk(0) = 0x60d000 <0.000031>
1337941514.041927 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7bc2779000 <0.000032>
1337941514.042113 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No
such file or directory) <0.000109>
1337941514.042395 open("/etc/ld.so.cache", O_RDONLY) = 3 <0.000050> 1337941514.042614 fstat(3, {st_mode=S_IFREG|0644, st_size=81118,
...}) = 0 <0.000102>
1337941514.042928 mmap(NULL, 81118, PROT_READ, MAP_PRIVATE, 3, 0) =
0x7f7bc2765000 <0.000042>
1337941514.043078 close(3) = 0 <0.000019>
1337941514.043235 open("/lib64/libc.so.6", O_RDONLY) = 3 <0.000115> 1337941514.043477 read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360\355\301W4\0\0\0"...,
832) = 832 <0.000039>
1337941514.043647 fstat(3, {st_mode=S_IFREG|0755, st_size=1908792,
...}) = 0 <0.000020>
1337941514.043860 mmap(0x3457c00000, 3733672, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3457c00000 <0.000085>
1337941514.044065 mprotect(0x3457d86000, 2097152, PROT_NONE) = 0 <0.000034> 1337941514.044191 mmap(0x3457f86000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x186000) = 0x3457f86000
<0.000034>
1337941514.044388 mmap(0x3457f8b000, 18600, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x3457f8b000
<0.000085>
1337941514.044592 close(3) = 0 <0.000058>
1337941514.044763 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7bc2764000 <0.000039>
1337941514.044893 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7bc2763000 <0.000020>
1337941514.044981 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7bc2762000 <0.000018>
1337941514.045076 arch_prctl(ARCH_SET_FS, 0x7f7bc2763700) = 0 <0.000018> 1337941514.045183 mprotect(0x3457f86000, 16384, PROT_READ) = 0 <0.000023> 1337941514.045270 mprotect(0x345761f000, 4096, PROT_READ) = 0 <0.000019> 1337941514.045350 munmap(0x7f7bc2765000, 81118) = 0 <0.000028>
1337941514.045619 brk(0) = 0x60d000 <0.000017>
1337941514.045698 brk(0x62e000) = 0x62e000 <0.000018>
1337941514.045803 open("/usr/lib/locale/locale-archive", O_RDONLY) =
3 <0.000028>
1337941514.045904 fstat(3, {st_mode=S_IFREG|0644, st_size=99158704,
...}) = 0 <0.000017>
1337941514.046012 mmap(NULL, 99158704, PROT_READ, MAP_PRIVATE, 3, 0)
= 0x7f7bbc8d1000 <0.000020>
1337941514.046099 close(3) = 0 <0.000017>
1337941514.046235 ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400
opost isig icanon echo ...}) = 0 <0.000020>
1337941514.046373 newfstatat(AT_FDCWD, "/data/2/test/2.8t-r.97.0", {st_mode=S_IFREG|0600, st_size=1073741824, ...},
AT_SYMLINK_NOFOLLOW) = 0 <0.000024>
1337941514.046504 unlinkat(AT_FDCWD, "/data/2/test/2.8t-r.97.0", 0)
= 0 <1.357571>
1337941515.404257 newfstatat(AT_FDCWD, "/data/2/test/2.8t-r.98.0", {st_mode=S_IFREG|0600, st_size=1073741824, ...},
AT_SYMLINK_NOFOLLOW) = 0 <0.000072>
1337941515.404485 unlinkat(AT_FDCWD, "/data/2/test/2.8t-r.98.0", 0)
= 0 <1.608016>
1337941517.012706 newfstatat(AT_FDCWD, "/data/2/test/2.8t-r.99.0", {st_mode=S_IFREG|0600, st_size=1073741824, ...},
AT_SYMLINK_NOFOLLOW) = 0 <0.000082>
1337941517.012957 unlinkat(AT_FDCWD, "/data/2/test/2.8t-r.99.0", 0)
= 0 <1.133890>
1337941518.146983 newfstatat(AT_FDCWD, "/data/2/test/2.9.0", {st_mode=S_IFREG|0600, st_size=8589934592, ...},
AT_SYMLINK_NOFOLLOW) = 0 <0.000023>
1337941518.147145 unlinkat(AT_FDCWD, "/data/2/test/2.9.0", 0) = 0 <0.938754>

Quoted 6 lines
1337941519.086125 close(0)              = 0 <0.000102>
1337941519.086357 close(1)              = 0 <0.000061>
1337941519.086540 close(2)              = 0 <0.000021>
1337941519.086694 exit_group(0)         = ?

Anything obvious that we are doing wrong?

There are a couple recent fixes related to discard that are probably appropriate for 3.2-stable.

commit b1c770c273a4787069306fc82aab245e9ac72e9d

Author: Dave Chinner <[email protected]>
Date:   Wed Dec 21 00:07:42 2011 +0000

xfs: fix endian conversion issue in discard code

When finding the longest extent in an AG, we read the value directly out of the AGF buffer without endian conversion. This will give an incorrect length, resulting in FITRIM operations potentially not trimming everything that it should.

commit a66d636385d621e98a915233250356c394a437de

Author: Dave Chinner <[email protected]>
Date:   Thu Mar 22 05:15:12 2012 +0000

xfs: fix fstrim offset calculations

xfs_ioc_fstrim() doesn't treat the incoming offset and length correctly. It treats them as a filesystem block address, rather than a disk address. This is wrong because the range passed in is a linear representation, while the filesystem block address notation is a sparse representation. Hence we cannot convert the range direct to filesystem block units and then use that for calculating the range to trim.

While this sounds dangerous, the problem is limited to calculating what AGs need to be trimmed. The code that calcuates the actual ranges to trim gets the right result (i.e. only ever discards free space), even though it uses the wrong ranges to limit what is trimmed. Hence this is not a bug that endangers user data.

Fix this by treating the range as a disk address range and use the appropriate functions to convert the range into the desired formats for calculations.

Further, fix the first free extent lookup (the longest) to actually find the largest free extent. Currently this lookup uses a <= lookup, which results in finding the extent to the left of the largest because we can never get an exact match on the largest extent. This is due to the fact that while we know it's size, we don't know it's location and so the exact match fails and we move one record to the left to get the next largest extent. Instead, use a >= search so that the lookup returns the largest extent regardless of the fact we don't get an exact match on it.

I'm not saying that they'll fix your problem, but you should consider giving them a whirl.

Regards,
Ben

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

#5 lore raw
Quoted 1 line · Ben Myers

Hey Joe,

[...]

Quoted 2 lines

There are a couple recent fixes related to discard that are probably appropriate for 3.2-stable.

[...]

Quoted 2 lines

I'm not saying that they'll fix your problem, but you should consider giving them a whirl.

Ok, will do a respin over the weekend and try from there. Thanks!

Joe

Quoted 4 lines

Regards,
Ben

Signature · 9 lines
Joseph Landman, Ph.D
Founder and CEO
Scalable Informatics Inc.
email: [email protected]
web  : http://scalableinformatics.com
       http://scalableinformatics.com/sicluster
phone: +1 734 786 8423 x121
fax  : +1 866 888 3112
cell : +1 734 612 4615
#7 lore raw
Quoted 6 lines · Christoph Hellwig
Quoted 2 lines · Ben Myers

There are a couple recent fixes related to discard that are probably appropriate for 3.2-stable.

Discard is not enabled by default.

You would not want to enable discard if slow deletes are an issue - benchmarks (on ext4) show that enabling trim makes metadata operations, and delete in particular, much slower.

#8 lore raw
In reply to Joe Landman
Quoted 1 line · Joe Landman

Hi folks:

Hi Joe,

I may be all wet here, but this is the only thing that jumped out at me:

Quoted 3 lines

meta-data=/dev/md20

data     =                       sunit=8      swidth=56 blks
log      =internal               sunit=8 blks

8*56KB (or 7*64KB) = 448KB write out

Quoted 7 lines

[root@siFlash ~]# mdadm --detail /dev/md20
/dev/md20:

        Version : 1.2

Raid Devices : 8

Layout : left-symmetric
Chunk Size : 32K

7*32KB = 224KB stripe size

Quoted 3 lines

All this said, deletes from this unit are taking 1-2 seconds per file ...

Anything obvious that we are doing wrong?

Other than your XFS writeout being apparently twice the size of your RAID stripe, nothing else stands out that I can see. I'm not a block layer expert. And since mkfs.xfs came up with 448KB, apparently this should be fine. However, everything in the literature, and the experts on this list, tells us to always precisely align XFS to the RAID stripe.
That doesn't seem to be the case here.

Signature · 1 line
Stan
#9 lore raw
In reply to Joe Landman
Quoted 37 lines · Joe Landman

Hi folks:

Just ran into this (see posted output at bottom). 3.2.14 kernel,
MD RAID 5, xfs file system. Not sure (precisely) where the problem is, hence posting to both lists.

[root@siFlash ~]# cat /proc/mdstat
Personalities : [raid1] [raid6] [raid5] [raid4]
md22 : active raid5 sdl[0] sds[7] sdx[6] sdu[5] sdk[4] sdz[3] sdw[2] sdr[1]

      1641009216 blocks super 1.2 level 5, 32k chunk, algorithm 2

[8/8] [UUUUUUUU]

md20 : active raid5 sdh[0] sdf[7] sdm[6] sdd[5] sdc[4] sde[3] sdi[2] sdg[1]

      1641009216 blocks super 1.2 level 5, 32k chunk, algorithm 2

[8/8] [UUUUUUUU]

md21 : active raid5 sdy[0] sdq[7] sdp[6] sdo[5] sdn[4] sdj[3] sdv[2] sdt[1]

      1641009216 blocks super 1.2 level 5, 32k chunk, algorithm 2

[8/8] [UUUUUUUU]

md0 : active raid1 sdb1[1] sda1[0]

      93775800 blocks super 1.0 [2/2] [UU]
      bitmap: 1/1 pages [4KB], 65536KB chunk

md2* are SSD RAID5 arrays we are experimenting with. Xfs file systems atop them:

[root@siFlash ~]# mount | grep md2
/dev/md20 on /data/1 type xfs (rw)
/dev/md21 on /data/2 type xfs (rw)
/dev/md22 on /data/3 type xfs (rw)

vanilla mount options (following Dave Chinner's long standing advice)

meta-data=/dev/md20 isize=2048 agcount=32,
agsize=12820392 blks

Quoted 7 lines
         =                       sectsz=512   attr=2
data     =                       bsize=4096   blocks=410252304, imaxpct=5
         =                       sunit=8      swidth=56 blks
naming   =version 2              bsize=65536  ascii-ci=0
log      =internal               bsize=4096   blocks=30720, version=2
         =                       sectsz=512   sunit=8 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0

But you haven't followed my advice when it comes to using default mkfs options, have you? You're running 2k inodes and 64k directory block size, which is not exactly a common config

The question is, why do you have these options configured, and are they responsible for things being slow?

Quoted 1 line

All this said, deletes from this unit are taking 1-2 seconds per file ...

Sounds like you might be hitting the synchronous xattr removal problem that was recently fixed (as has been mentioned already), but even so 2 IOs don't take 1-2s to do, unless the MD RAID5 barrier implementation is really that bad. If you mount -o nobarrier, what happens?

CHeers,

Dave.

Signature · 7 lines
Dave Chinner
[email protected]

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs
#10 lore raw
Quoted 46 lines · Dave Chinner
Quoted 40 lines · Joe Landman

Hi folks:

Just ran into this (see posted output at bottom). 3.2.14 kernel,
MD RAID 5, xfs file system. Not sure (precisely) where the problem is, hence posting to both lists.

[root@siFlash ~]# cat /proc/mdstat
Personalities : [raid1] [raid6] [raid5] [raid4]
md22 : active raid5 sdl[0] sds[7] sdx[6] sdu[5] sdk[4] sdz[3] sdw[2] sdr[1]

       1641009216 blocks super 1.2 level 5, 32k chunk, algorithm 2

[8/8] [UUUUUUUU]

md20 : active raid5 sdh[0] sdf[7] sdm[6] sdd[5] sdc[4] sde[3] sdi[2] sdg[1]

       1641009216 blocks super 1.2 level 5, 32k chunk, algorithm 2

[8/8] [UUUUUUUU]

md21 : active raid5 sdy[0] sdq[7] sdp[6] sdo[5] sdn[4] sdj[3] sdv[2] sdt[1]

       1641009216 blocks super 1.2 level 5, 32k chunk, algorithm 2

[8/8] [UUUUUUUU]

md0 : active raid1 sdb1[1] sda1[0]

       93775800 blocks super 1.0 [2/2] [UU]
       bitmap: 1/1 pages [4KB], 65536KB chunk

md2* are SSD RAID5 arrays we are experimenting with. Xfs file systems atop them:

[root@siFlash ~]# mount | grep md2
/dev/md20 on /data/1 type xfs (rw)
/dev/md21 on /data/2 type xfs (rw)
/dev/md22 on /data/3 type xfs (rw)

vanilla mount options (following Dave Chinner's long standing advice)

meta-data=/dev/md20 isize=2048 agcount=32,
agsize=12820392 blks
= sectsz=512 attr=2
data = bsize=4096 blocks=410252304, imaxpct=5
= sunit=8 swidth=56 blks

Quoted 4 lines
naming   =version 2              bsize=65536  ascii-ci=0
log      =internal               bsize=4096   blocks=30720, version=2

= sectsz=512 sunit=8 blks, lazy-count=1
realtime =none extsz=4096 blocks=0, rtextents=0

Quoted 3 lines

But you haven't followed my advice when it comes to using default mkfs options, have you? You're running 2k inodes and 64k directory block size, which is not exactly a common config

We were experimenting. Easy to set it back and demonstrate the problem again.

Quoted 4 lines

The question is, why do you have these options configured, and are they responsible for things being slow?

We saw it before we experimented with some mkfs options. Will rebuild FS and demo it again.

Quoted 7 lines
Quoted 1 line

All this said, deletes from this unit are taking 1-2 seconds per file ...

Sounds like you might be hitting the synchronous xattr removal problem that was recently fixed (as has been mentioned already), but even so 2 IOs don't take 1-2s to do, unless the MD RAID5 barrier implementation is really that bad. If you mount -o nobarrier, what happens?

[root@siFlash test]# ls -alF | wc -l
59
[root@siFlash test]# /usr/bin/time rm -f *
^C0.00user 8.46system 0:09.55elapsed 88%CPU (0avgtext+0avgdata 2384maxresident)k 25352inputs+0outputs (0major+179minor)pagefaults 0swaps [root@siFlash test]# ls -alF | wc -l
48

Nope, still an issue:

1338074901.531554 ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0 <0.000021> 1338074901.531701 newfstatat(AT_FDCWD, "1.r.12.0", {st_mode=S_IFREG|0600, st_size=1073741824, ...}, AT_SYMLINK_NOFOLLOW) = 0 <0.000022> 1338074901.531840 unlinkat(AT_FDCWD, "1.r.12.0", 0) = 0 <2.586999>
1338074904.119032 newfstatat(AT_FDCWD, "1.r.13.0", {st_mode=S_IFREG|0600, st_size=1073741824, ...}, AT_SYMLINK_NOFOLLOW) = 0 <0.000033>

2.6 seconds for an unlink.

Rebuilding absolutely vanilla file system now, and will rerun checks.

Quoted 4 lines

CHeers,

Dave.

Signature · 9 lines
Joseph Landman, Ph.D
Founder and CEO
Scalable Informatics Inc.
email: [email protected]
web  : http://scalableinformatics.com
       http://scalableinformatics.com/sicluster
phone: +1 734 786 8423 x121
fax  : +1 866 888 3112
cell : +1 734 612 4615
#11 lore raw
Quoted 6 lines · Joe Landman

[root@siFlash test]# ls -alF | wc -l
59
[root@siFlash test]# /usr/bin/time rm -f * ^C0.00user 8.46system 0:09.55elapsed 88%CPU (0avgtext+0avgdata 2384maxresident)k
25352inputs+0outputs (0major+179minor)pagefaults 0swaps

It's burning an awful lot of CPU time during this remove.

Quoted 2 lines

[root@siFlash test]# ls -alF | wc -l
48

So, 48 files were removed, it was basically CPU bound and one took 2.6 seconds.

So, how big are the files, and does the one that took 2.6s have tens of thousands of extents ('xfs_bmap -vp *' will dump the extent maps for all the files)?

if not, can you use perf top to get an ida of the CPU usage profile duing the rm by doing:

# perf record rm -f *
.....

and capturing the profile via:

# perf report > profile.txt

And attaching te profile.txt file so we can see where all the CPU time is being spent? You can find perf in your kernel source tree under the tools subdir....

Cheers,

Dave.

Signature · 2 lines
Dave Chinner
[email protected]
#12 lore raw

Ok. Will do in a few hours

Sent from my iPad

Quoted 40 lines · Dave Chinner
Quoted 6 lines · Joe Landman

[root@siFlash test]# ls -alF | wc -l
59
[root@siFlash test]# /usr/bin/time rm -f * ^C0.00user 8.46system 0:09.55elapsed 88%CPU (0avgtext+0avgdata 2384maxresident)k
25352inputs+0outputs (0major+179minor)pagefaults 0swaps

It's burning an awful lot of CPU time during this remove.

Quoted 2 lines

[root@siFlash test]# ls -alF | wc -l
48

So, 48 files were removed, it was basically CPU bound and one took 2.6 seconds.

So, how big are the files, and does the one that took 2.6s have tens of thousands of extents ('xfs_bmap -vp *' will dump the extent maps for all the files)?

if not, can you use perf top to get an ida of the CPU usage profile duing the rm by doing:

# perf record rm -f *
.....

and capturing the profile via:

# perf report > profile.txt

And attaching te profile.txt file so we can see where all the CPU time is being spent? You can find perf in your kernel source tree under the tools subdir....

Cheers,

Dave.

Signature · 2 lines
Dave Chinner
[email protected]
#13 lore raw
In reply to Dave Chinner
Quoted 13 lines · Dave Chinner
Quoted 6 lines · Joe Landman

[root@siFlash test]# ls -alF | wc -l
59
[root@siFlash test]# /usr/bin/time rm -f * ^C0.00user 8.46system 0:09.55elapsed 88%CPU (0avgtext+0avgdata 2384maxresident)k
25352inputs+0outputs (0major+179minor)pagefaults 0swaps

It's burning an awful lot of CPU time during this remove.

Quoted 2 lines

[root@siFlash test]# ls -alF | wc -l
48

Quoted 6 lines

So, 48 files were removed, it was basically CPU bound and one took 2.6 seconds.

So, how big are the files, and does the one that took 2.6s have tens of thousands of extents ('xfs_bmap -vp *' will dump the extent maps for all the files)?

Getting some sort of out of memory error with bmap

[root@siFlash test]# ls -alF
total 50466476
drwxr-xr-x 2 root root 4096 May 26 21:40 ./
drwxr-xr-x 3 root root 17 May 26 19:32 ../
-rw------- 1 root root 1073741824 May 26 19:36 2.r.49.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.50.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.51.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.52.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.53.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.54.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.55.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.56.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.57.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.58.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.59.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.60.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.61.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.62.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.63.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.64.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.65.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.66.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.67.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.68.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.69.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.70.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.71.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.72.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.73.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.74.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.75.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.76.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.77.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.78.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.79.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.80.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.81.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.82.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.83.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.84.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.85.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.86.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.87.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.88.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.89.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.90.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.91.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.92.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.93.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.94.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.95.0 -rw------- 1 root root 1073741824 May 26 19:36 2.r.96.0
-rw-r--r-- 1 root root 0 May 26 21:40 x

[root@siFlash test]# ls -alF > x

[root@siFlash test]# xfs_bmap -vp x
x:
EXT: FILE-OFFSET BLOCK-RANGE AG AG-OFFSET TOTAL
FLAGS
0: [0..7]: 212681896..212681903 2 (7555752..7555759) 8
01111

[root@siFlash test]# xfs_bmap -vp 2.r.96.0
xfs_bmap: xfsctl(XFS_IOC_GETBMAPX) iflags=0x4 ["2.r.96.0"]: Cannot allocate memory

These are 3.1.8 from git (had same error with earlier version).

Quoted 18 lines

if not, can you use perf top to get an ida of the CPU usage profile duing the rm by doing:

# perf record rm -f *
.....

and capturing the profile via:

# perf report>  profile.txt

And attaching te profile.txt file so we can see where all the CPU time is being spent? You can find perf in your kernel source tree under the tools subdir....

Cheers,

Dave.

#14 lore raw
Quoted 28 lines · Joe Landman
Quoted 13 lines · Dave Chinner
Quoted 6 lines · Joe Landman

[root@siFlash test]# ls -alF | wc -l
59
[root@siFlash test]# /usr/bin/time rm -f * ^C0.00user 8.46system 0:09.55elapsed 88%CPU (0avgtext+0avgdata 2384maxresident)k
25352inputs+0outputs (0major+179minor)pagefaults 0swaps

It's burning an awful lot of CPU time during this remove.

Quoted 2 lines

[root@siFlash test]# ls -alF | wc -l
48

Quoted 6 lines

So, 48 files were removed, it was basically CPU bound and one took 2.6 seconds.

So, how big are the files, and does the one that took 2.6s have tens of thousands of extents ('xfs_bmap -vp *' will dump the extent maps for all the files)?

Getting some sort of out of memory error with bmap

[root@siFlash test]# ls -alF
total 50466476
drwxr-xr-x 2 root root 4096 May 26 21:40 ./
drwxr-xr-x 3 root root 17 May 26 19:32 ../
-rw------- 1 root root 1073741824 May 26 19:36 2.r.49.0

...

<snip>

Quoted 9 lines

[root@siFlash test]# ls -alF > x

[root@siFlash test]# xfs_bmap -vp x
x:
EXT: FILE-OFFSET BLOCK-RANGE AG AG-OFFSET TOTAL FLAGS
0: [0..7]: 212681896..212681903 2 (7555752..7555759) 8 01111

[root@siFlash test]# xfs_bmap -vp 2.r.96.0
xfs_bmap: xfsctl(XFS_IOC_GETBMAPX) iflags=0x4 ["2.r.96.0"]: Cannot allocate memory

Try filefrag -v maybe, if your e2fsprogs is new enough.

Trying to remember, ENOMEM in bmap rings a bell... but this is possibly indicative of an extremely fragmented file.

-Eric

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

#15 lore raw
Quoted 40 lines · Eric Sandeen
Quoted 28 lines · Joe Landman
Quoted 13 lines · Dave Chinner
Quoted 6 lines · Joe Landman

[root@siFlash test]# ls -alF | wc -l
59
[root@siFlash test]# /usr/bin/time rm -f * ^C0.00user 8.46system 0:09.55elapsed 88%CPU (0avgtext+0avgdata 2384maxresident)k
25352inputs+0outputs (0major+179minor)pagefaults 0swaps

It's burning an awful lot of CPU time during this remove.

Quoted 2 lines

[root@siFlash test]# ls -alF | wc -l
48

Quoted 6 lines

So, 48 files were removed, it was basically CPU bound and one took 2.6 seconds.

So, how big are the files, and does the one that took 2.6s have tens of thousands of extents ('xfs_bmap -vp *' will dump the extent maps for all the files)?

Getting some sort of out of memory error with bmap

[root@siFlash test]# ls -alF
total 50466476
drwxr-xr-x 2 root root 4096 May 26 21:40 ./
drwxr-xr-x 3 root root 17 May 26 19:32 ../
-rw------- 1 root root 1073741824 May 26 19:36 2.r.49.0

...

<snip>

Quoted 7 lines

[root@siFlash test]# ls -alF > x

[root@siFlash test]# xfs_bmap -vp x
x:
EXT: FILE-OFFSET BLOCK-RANGE AG AG-OFFSET TOTAL FLAGS
0: [0..7]: 212681896..212681903 2 (7555752..7555759) 8 01111

Quoted 6 lines
Quoted 2 lines

[root@siFlash test]# xfs_bmap -vp 2.r.96.0
xfs_bmap: xfsctl(XFS_IOC_GETBMAPX) iflags=0x4 ["2.r.96.0"]: Cannot allocate memory

Try filefrag -v maybe, if your e2fsprogs is new enough.

Trying to remember, ENOMEM in bmap rings a bell... but this is possibly indicative of an extremely fragmented file.

Ah.

f074211f xfs: fallback to vmalloc for large buffers in xfs_getbmap

fixed it in 3.4

-Eric

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

#16 lore raw
In reply to Eric Sandeen
Quoted 6 lines
Quoted 2 lines

[root@siFlash test]# xfs_bmap -vp 2.r.96.0
xfs_bmap: xfsctl(XFS_IOC_GETBMAPX) iflags=0x4 ["2.r.96.0"]: Cannot allocate memory

Try filefrag -v maybe, if your e2fsprogs is new enough.

Trying to remember, ENOMEM in bmap rings a bell... but this is possibly indicative of an extremely fragmented file.

True, I've had it happen with extremely fragmented files.

I've started playing around with discard myself only recently, but so far I like the approach of using fstrim a lot better than the discard
option: http://xfs.org/index.php/FITRIM/discard

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

#17 lore raw
Quoted 5 lines · Stefan Ring
Quoted 5 lines
Quoted 2 lines

[root@siFlash test]# xfs_bmap -vp 2.r.96.0
xfs_bmap: xfsctl(XFS_IOC_GETBMAPX) iflags=0x4 ["2.r.96.0"]: Cannot allocate memory

Try filefrag -v maybe, if your e2fsprogs is new enough.

Quoted 7 lines
Quoted 1 line

Trying to remember, ENOMEM in bmap rings a bell... but this is possibly indicative of an extremely fragmented file.

True, I've had it happen with extremely fragmented files.

I've started playing around with discard myself only recently, but so far I like the approach of using fstrim a lot better than the discard
option: http://xfs.org/index.php/FITRIM/discard

Check what blockdev --getra <md device> is set to. I used to have a several second deletes on large (4GB) fragmented files when ra was the default 256. Once I changed it to 4096 (best value will depend on your setup) the deletes became instant.

K

#18 lore raw

This is going to be a very fragmented file. I am guessing that this is the reason for the long duration delete. I'll do some more measurements before going to 3.4.x as per Eric's note.

Sent from my iPad

Quoted 21 lines · Krzysztof Adamski
Quoted 5 lines · Stefan Ring
Quoted 5 lines
Quoted 2 lines

[root@siFlash test]# xfs_bmap -vp 2.r.96.0
xfs_bmap: xfsctl(XFS_IOC_GETBMAPX) iflags=0x4 ["2.r.96.0"]: Cannot allocate memory

Try filefrag -v maybe, if your e2fsprogs is new enough.

Quoted 7 lines
Quoted 1 line

Trying to remember, ENOMEM in bmap rings a bell... but this is possibly indicative of an extremely fragmented file.

True, I've had it happen with extremely fragmented files.

I've started playing around with discard myself only recently, but so far I like the approach of using fstrim a lot better than the discard
option: http://xfs.org/index.php/FITRIM/discard

Check what blockdev --getra <md device> is set to. I used to have a several second deletes on large (4GB) fragmented files when ra was the default 256. Once I changed it to 4096 (best value will depend on your setup) the deletes became instant.

K

#19 lore raw
Quoted 3 lines · On 5/27/12 9:59 AM, [email protected] wrote:

This is going to be a very fragmented file. I am guessing that this
is the reason for the long duration delete. I'll do some more
measurements before going to 3.4.x as per Eric's note.

filefrag -v should also tell you how many fragments, and because it uses fiemap it probably won't run into the same problems.

But it sounds like we can just assume very high fragmentation.

It's not addressing the exact issue, but why are the files so fragmented? Are they very hole-y or is it just an issue with how they are written? Perhaps preallocation would help you here?

-Eric

#20 lore raw
Quoted 10 lines · Eric Sandeen
Quoted 3 lines · On 5/27/12 9:59 AM, [email protected] wrote:

This is going to be a very fragmented file. I am guessing that this
is the reason for the long duration delete. I'll do some more
measurements before going to 3.4.x as per Eric's note.

filefrag -v should also tell you how many fragments, and because it uses fiemap it probably won't run into the same problems.

But it sounds like we can just assume very high fragmentation.

[root@siFlash test]# filefrag 1.r.48.0
1.r.48.0: 1364 extents found

Quoted 3 lines

It's not addressing the exact issue, but why are the files so fragmented? Are they very hole-y or is it just an issue with how they are written? Perhaps preallocation would help you here?

Possibly. We are testing the system using fio, and doing random reads and writes. I'll see if we can do a preallocation scheme (before/during) for the files.

So to summarize, the delete performance will be (at least) in part a function of the fragmentation? A directory full of massively fragmented files will take longer to delete than a directory of contiguous and larger extents? And I did some experimentation using xfs_repair, and it seems to be the case there as well ... the higher level of fragmentation, the longer the repair seems to take.

Quoted 2 lines

-Eric

#21 lore raw

[ ... 2s CPU time to delete a file ... ]

Quoted 7 lines

[root@siFlash test]# filefrag 1.r.48.0
1.r.48.0: 1364 extents found

Quoted 4 lines

It's not addressing the exact issue, but why are the files so fragmented? Are they very hole-y or is it just an issue with how they are written? Perhaps preallocation would help you here?

That's not that fragmented, and I am a bit surprised that it takes 2s of CPU time to delete a bit over 1,000 extents (unless there is a repeated linear search). I have seen over 800,000 extents in a file created on XFS by someone who thought it was a fine idea to have sparse virtual disk images, especially for a rapidly growing Maildir archive...

[ ... ]

Quoted 4 lines

So to summarize, the delete performance will be (at least) in part a function of the fragmentation? [ ... ] A directory full of massively fragmented files will take longer to delete than a directory of contiguous and larger extents?

The list of extents is part of filesystem metadata. It's also what happens with traditional designs with block-tree based filesystem, deleting a large 3 level tree of blocks can take a very long time (but mostly seeks, not CPU).

Quoted 3 lines

And I did some experimentation using xfs_repair, and it seems to be the case there as well ... the higher level of fragmentation, the longer the repair seems to take.

That's expected too: more metadata to verify.

In some way a file over many extents behaves like a non-extent based file.

The special detail about many extents and XFS is that XFS loads and keeps in memory the entire extent table on filen open. This to me seems a reasonable design choice, as XFS tries pretty hard to ensure that files have few extents or offers applications ways (that probably few applications use) to improve the chances of that happening.

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

#22 lore raw
In reply to Eric Sandeen
Quoted 5 lines · Eric Sandeen
Quoted 3 lines · On 5/27/12 9:59 AM, [email protected] wrote:

This is going to be a very fragmented file. I am guessing that this
is the reason for the long duration delete. I'll do some more
measurements before going to 3.4.x as per Eric's note.

Quoted 8 lines

filefrag -v should also tell you how many fragments, and because it uses fiemap it probably won't run into the same problems.

But it sounds like we can just assume very high fragmentation.

It's not addressing the exact issue, but why are the files so fragmented? Are they very hole-y or is it just an issue with how they are written? Perhaps preallocation would help you here?

... and one pass with xfs_fsr seems to have "fixed" the problem

[root@siFlash test]# xfs_fsr
xfs_fsr -m /proc/mounts -t 7200 -f /var/tmp/.fsrlast_xfs ... /data/1 start inode=0
/data/2 start inode=0
/data/3 start inode=0
/data/1 start inode=0
/data/2 start inode=0
/data/3 start inode=0
/data/1 start inode=0
/data/2 start inode=0
/data/3 start inode=0
/data/1 start inode=0
/data/2 start inode=0
/data/3 start inode=0
/data/1 start inode=0
/data/2 start inode=0
/data/3 start inode=0
/data/1 start inode=0
/data/2 start inode=0
/data/3 start inode=0
/data/1 start inode=0
/data/2 start inode=0
/data/3 start inode=0
/data/1 start inode=0
/data/2 start inode=0
/data/3 start inode=0
/data/1 start inode=0
/data/2 start inode=0
/data/3 start inode=0
/data/1 start inode=0
/data/2 start inode=0
/data/3 start inode=0
Completed all 10 passes
[root@siFlash test]# filefrag 1.r.48.0
1.r.48.0: 1 extent found

[root@siFlash test]# rm -f 1.r.48.0

(very fast)

Signature · 9 lines
Joseph Landman, Ph.D
Founder and CEO
Scalable Informatics Inc.
email: [email protected]
web  : http://scalableinformatics.com
       http://scalableinformatics.com/sicluster
phone: +1 734 786 8423 x121
fax  : +1 866 888 3112
cell : +1 734 612 4615
#23 lore raw
In reply to Dave Chinner
Quoted 5 lines · Dave Chinner

Sounds like you might be hitting the synchronous xattr removal problem that was recently fixed (as has been mentioned already), but even so 2 IOs don't take 1-2s to do, unless the MD RAID5 barrier implementation is really that bad. If you mount -o nobarrier, what happens?

Pure vanilla mkfs

[root@siFlash ~]# mkfs.xfs -f /dev/md20

meta-data=/dev/md20              isize=256    agcount=32, agsize=12820384 blks
         =                       sectsz=512   attr=2, projid32bit=0
data     =                       bsize=4096   blocks=410252288, imaxpct=5
         =                       sunit=4      swidth=28 blks
naming   =version 2              bsize=4096   ascii-ci=0
log      =internal log           bsize=4096   blocks=200320, version=2
         =                       sectsz=512   sunit=4 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0
[root@siFlash ~]# mkfs.xfs -f /dev/md21
meta-data=/dev/md21              isize=256    agcount=32, agsize=12820384 blks
         =                       sectsz=512   attr=2, projid32bit=0
data     =                       bsize=4096   blocks=410252288, imaxpct=5
         =                       sunit=4      swidth=28 blks
naming   =version 2              bsize=4096   ascii-ci=0
log      =internal log           bsize=4096   blocks=200320, version=2
         =                       sectsz=512   sunit=4 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0
^[[A[root@siFlash ~]# mkfs.xfs -f /dev/md22
meta-data=/dev/md22              isize=256    agcount=32, agsize=12820384 blks
         =                       sectsz=512   attr=2, projid32bit=0
data     =                       bsize=4096   blocks=410252288, imaxpct=5
         =                       sunit=4      swidth=28 blks
naming   =version 2              bsize=4096   ascii-ci=0
log      =internal log           bsize=4096   blocks=200320, version=2
         =                       sectsz=512   sunit=4 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0

and mount

[root@siFlash ~]# mount /dev/md20 /data/1
[root@siFlash ~]# mount /dev/md21 /data/2
[root@siFlash ~]# mount /dev/md22 /data/3

Still an issue:

[root@siFlash test]# ls -l | wc -l
48
[root@siFlash test]# /usr/bin/time rm -f *
^C0.00user 5.02system 0:05.33elapsed 94%CPU (0avgtext+0avgdata 2368maxresident)k 24inputs+0outputs (0major+179minor)pagefaults 0swaps
[root@siFlash test]# ls -l | wc -l
46
[root@siFlash test]#

though now its 3.5 seconds per file delete

1338075592.450387 ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0 <0.000020> 1338075592.450541 newfstatat(AT_FDCWD, "1.r.12.0", {st_mode=S_IFREG|0600, st_size=1073741824, ...}, AT_SYMLINK_NOFOLLOW) = 0 <0.000020> 1338075592.450679 unlinkat(AT_FDCWD, "1.r.12.0", 0) = 0 <3.226394>
1338075595.677274 newfstatat(AT_FDCWD, "1.r.13.0", {st_mode=S_IFREG|0600, st_size=1073741824, ...}, AT_SYMLINK_NOFOLLOW) = 0 <0.000088> 1338075595.677515 unlinkat(AT_FDCWD, "1.r.13.0", 0) = 0 <3.564176>

Remounting with nobarrier

[root@siFlash test]# mount -o remount,nobarrier /data/1 [root@siFlash test]# mount -o remount,nobarrier /data/2 [root@siFlash test]# mount -o remount,nobarrier /data/3 [root@siFlash test]# mount | grep data /dev/md20 on /data/1 type xfs (rw,nobarrier) /dev/md21 on /data/2 type xfs (rw,nobarrier) /dev/md22 on /data/3 type xfs (rw,nobarrier)

doesn't look like this helped

1338075724.110941 newfstatat(AT_FDCWD, "1.r.15.0", {st_mode=S_IFREG|0600, st_size=1073741824, ...}, AT_SYMLINK_NOFOLLOW) = 0 <0.000035> 1338075724.111108 unlinkat(AT_FDCWD, "1.r.15.0", 0) = 0 <3.727094>
1338075727.838380 newfstatat(AT_FDCWD, "1.r.16.0", {st_mode=S_IFREG|0600, st_size=1073741824, ...}, AT_SYMLINK_NOFOLLOW) = 0 <0.000061> 1338075727.838600 unlinkat(AT_FDCWD, "1.r.16.0", 0) = 0 <2.611156>
1338075730.449949 newfstatat(AT_FDCWD, "1.r.17.0", {st_mode=S_IFREG|0600, st_size=1073741824, ...}, AT_SYMLINK_NOFOLLOW) = 0 <0.000104> 1338075730.450165 unlinkat(AT_FDCWD, "1.r.17.0", 0) = 0 <2.869917>

2.6-3.7 seconds per unlink.

FWIW: umount (which does flushes) seems to take a while (~15-20 seconds)

Raw (uncached) read/write speed to a single array is pretty good, so I don't think the array is a problem.

Run status group 0 (all jobs):
READ: io=81424MB, aggrb=2606.7MB/s, minb=2606.7MB/s,
maxb=2606.7MB/s, mint=31244msec, maxt=31244msec

Run status group 0 (all jobs):
WRITE: io=55025MB, aggrb=939053KB/s, minb=939053KB/s,
maxb=939053KB/s, mint=60002msec, maxt=60002msec

Signature · 9 lines
Joseph Landman, Ph.D
Founder and CEO
Scalable Informatics Inc.
email: [email protected]
web  : http://scalableinformatics.com
       http://scalableinformatics.com/sicluster
phone: +1 734 786 8423 x121
fax  : +1 866 888 3112
cell : +1 734 612 4615
#24 lore raw
Quoted 7 lines · Joe Landman
Quoted 5 lines · Dave Chinner

Sounds like you might be hitting the synchronous xattr removal problem that was recently fixed (as has been mentioned already), but even so 2 IOs don't take 1-2s to do, unless the MD RAID5 barrier implementation is really that bad. If you mount -o nobarrier, what happens?

Consider trying btrfs to eliminate the filesystem from the equation. It should auto-detect that it's on an SSD.

Signature · 1 line
Jon