* fstrim and strace considered harmful?
@ 2022-05-18 6:59 Chris Dunlop
2022-05-18 7:07 ` Chris Dunlop
0 siblings, 1 reply; 8+ messages in thread
From: Chris Dunlop @ 2022-05-18 6:59 UTC (permalink / raw)
To: linux-xfs
Hi,
I have an fstrim that's been running for over 48 hours on a 256T thin
provisioned XFS fs containing around 55T of actual data on a slow
subsystem (ceph 8,3 erasure-encoded rbd). I don't think there would be an
an enourmous amount of data to trim, maybe a few T, but I've no idea how
long how long it might be expected to take. In an attempt to see what the
what the fstrim was doing, I ran an strace on it. The strace has been
sitting there without output and unkillable since then, now 5+ hours ago.
Since the strace, on that same filesystem I now have 123 df processes and
615 rm processes -- and growing -- that are blocked in xfs_inodegc_flush,
e.g.:
May 18 15:31:52 d5 kernel: task:df state:D stack: 0 pid:31741 ppid: 1 flags:0x00004004
May 18 15:31:52 d5 kernel: Call Trace:
May 18 15:31:52 d5 kernel: <TASK>
May 18 15:31:52 d5 kernel: __schedule+0x241/0x740
May 18 15:31:52 d5 kernel: ? lock_is_held_type+0x97/0x100
May 18 15:31:52 d5 kernel: schedule+0x3a/0xa0
May 18 15:31:52 d5 kernel: schedule_timeout+0x271/0x310
May 18 15:31:52 d5 kernel: ? find_held_lock+0x2d/0x90
May 18 15:31:52 d5 kernel: ? sched_clock_cpu+0x9/0xa0
May 18 15:31:52 d5 kernel: ? lock_release+0x214/0x350
May 18 15:31:52 d5 kernel: wait_for_completion+0x7b/0xc0
May 18 15:31:52 d5 kernel: __flush_work+0x217/0x350
May 18 15:31:52 d5 kernel: ? flush_workqueue_prep_pwqs+0x120/0x120
May 18 15:31:52 d5 kernel: ? wait_for_completion+0x1c/0xc0
May 18 15:31:52 d5 kernel: xfs_inodegc_flush.part.24+0x62/0xc0 [xfs]
May 18 15:31:52 d5 kernel: xfs_fs_statfs+0x37/0x1a0 [xfs]
May 18 15:31:52 d5 kernel: statfs_by_dentry+0x3c/0x60
May 18 15:31:52 d5 kernel: vfs_statfs+0x16/0xd0
May 18 15:31:52 d5 kernel: user_statfs+0x44/0x80
May 18 15:31:52 d5 kernel: __do_sys_statfs+0x10/0x30
May 18 15:31:52 d5 kernel: do_syscall_64+0x34/0x80
May 18 15:31:52 d5 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xae
May 18 15:31:52 d5 kernel: RIP: 0033:0x7fe9e9db3c07
May 18 15:31:52 d5 kernel: RSP: 002b:00007ffe08f50178 EFLAGS: 00000246 ORIG_RAX: 0000000000000089
May 18 15:31:52 d5 kernel: RAX: ffffffffffffffda RBX: 0000555963fcae40 RCX: 00007fe9e9db3c07
May 18 15:31:52 d5 kernel: RDX: 00007ffe08f50400 RSI: 00007ffe08f50180 RDI: 0000555963fcae40
May 18 15:31:52 d5 kernel: RBP: 00007ffe08f50180 R08: 0000555963fcae80 R09: 0000000000000000
May 18 15:31:52 d5 kernel: R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffe08f50220
May 18 15:31:52 d5 kernel: R13: 0000000000000000 R14: 0000555963fcae80 R15: 0000555963fcae40
May 18 15:31:52 d5 kernel: </TASK>
Full 1.5M sysrq output at: https://file.io/bWOL8F7mzKI6
That stack trace is uncomfortably familiar:
Subject: Highly reflinked and fragmented considered harmful?
https://lore.kernel.org/linux-xfs/20220509024659.GA62606@onthe.net.au/
FYI:
# xfs_info /vol
meta-data=/dev/vg01/vol isize=512 agcount=257, agsize=268434432 blks
= sectsz=4096 attr=2, projid32bit=1
= crc=1 finobt=1, sparse=1, rmapbt=1
= reflink=1 bigtime=1 inobtcount=1
data = bsize=4096 blocks=68719475712, imaxpct=1
= sunit=1024 swidth=8192 blks
naming =version 2 bsize=4096 ascii-ci=0, ftype=1
log =internal log bsize=4096 blocks=521728, version=2
= sectsz=4096 sunit=1 blks, lazy-count=1
realtime =none extsz=4096 blocks=0, rtextents=0
Is there something I can do to "unstick" things, or is it time to hit the
reset, and hope the recovery on mount isn't onerous?
Aside from that immediate issue, what has gone wrong here?
Cheers,
Chris
^ permalink raw reply [flat|nested] 8+ messages in thread* Re: fstrim and strace considered harmful? 2022-05-18 6:59 fstrim and strace considered harmful? Chris Dunlop @ 2022-05-18 7:07 ` Chris Dunlop 2022-05-18 15:59 ` Darrick J. Wong 0 siblings, 1 reply; 8+ messages in thread From: Chris Dunlop @ 2022-05-18 7:07 UTC (permalink / raw) To: linux-xfs Oh, sorry... on linux v5.15.34 On Wed, May 18, 2022 at 04:59:49PM +1000, Chris Dunlop wrote: > Hi, > > I have an fstrim that's been running for over 48 hours on a 256T thin > provisioned XFS fs containing around 55T of actual data on a slow > subsystem (ceph 8,3 erasure-encoded rbd). I don't think there would be > an an enourmous amount of data to trim, maybe a few T, but I've no > idea how long how long it might be expected to take. In an attempt to > see what the what the fstrim was doing, I ran an strace on it. The > strace has been sitting there without output and unkillable since > then, now 5+ hours ago. Since the strace, on that same filesystem I > now have 123 df processes and 615 rm processes -- and growing -- that > are blocked in xfs_inodegc_flush, e.g.: > > May 18 15:31:52 d5 kernel: task:df state:D stack: 0 pid:31741 ppid: 1 flags:0x00004004 > May 18 15:31:52 d5 kernel: Call Trace: > May 18 15:31:52 d5 kernel: <TASK> > May 18 15:31:52 d5 kernel: __schedule+0x241/0x740 > May 18 15:31:52 d5 kernel: ? lock_is_held_type+0x97/0x100 > May 18 15:31:52 d5 kernel: schedule+0x3a/0xa0 > May 18 15:31:52 d5 kernel: schedule_timeout+0x271/0x310 > May 18 15:31:52 d5 kernel: ? find_held_lock+0x2d/0x90 > May 18 15:31:52 d5 kernel: ? sched_clock_cpu+0x9/0xa0 > May 18 15:31:52 d5 kernel: ? lock_release+0x214/0x350 > May 18 15:31:52 d5 kernel: wait_for_completion+0x7b/0xc0 > May 18 15:31:52 d5 kernel: __flush_work+0x217/0x350 > May 18 15:31:52 d5 kernel: ? flush_workqueue_prep_pwqs+0x120/0x120 > May 18 15:31:52 d5 kernel: ? wait_for_completion+0x1c/0xc0 > May 18 15:31:52 d5 kernel: xfs_inodegc_flush.part.24+0x62/0xc0 [xfs] > May 18 15:31:52 d5 kernel: xfs_fs_statfs+0x37/0x1a0 [xfs] > May 18 15:31:52 d5 kernel: statfs_by_dentry+0x3c/0x60 > May 18 15:31:52 d5 kernel: vfs_statfs+0x16/0xd0 > May 18 15:31:52 d5 kernel: user_statfs+0x44/0x80 > May 18 15:31:52 d5 kernel: __do_sys_statfs+0x10/0x30 > May 18 15:31:52 d5 kernel: do_syscall_64+0x34/0x80 > May 18 15:31:52 d5 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xae > May 18 15:31:52 d5 kernel: RIP: 0033:0x7fe9e9db3c07 > May 18 15:31:52 d5 kernel: RSP: 002b:00007ffe08f50178 EFLAGS: 00000246 ORIG_RAX: 0000000000000089 > May 18 15:31:52 d5 kernel: RAX: ffffffffffffffda RBX: 0000555963fcae40 RCX: 00007fe9e9db3c07 > May 18 15:31:52 d5 kernel: RDX: 00007ffe08f50400 RSI: 00007ffe08f50180 RDI: 0000555963fcae40 > May 18 15:31:52 d5 kernel: RBP: 00007ffe08f50180 R08: 0000555963fcae80 R09: 0000000000000000 > May 18 15:31:52 d5 kernel: R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffe08f50220 > May 18 15:31:52 d5 kernel: R13: 0000000000000000 R14: 0000555963fcae80 R15: 0000555963fcae40 > May 18 15:31:52 d5 kernel: </TASK> > > Full 1.5M sysrq output at: https://file.io/bWOL8F7mzKI6 > > That stack trace is uncomfortably familiar: > > Subject: Highly reflinked and fragmented considered harmful? > https://lore.kernel.org/linux-xfs/20220509024659.GA62606@onthe.net.au/ > > FYI: > > # xfs_info /vol > meta-data=/dev/vg01/vol isize=512 agcount=257, agsize=268434432 blks > = sectsz=4096 attr=2, projid32bit=1 > = crc=1 finobt=1, sparse=1, rmapbt=1 > = reflink=1 bigtime=1 inobtcount=1 > data = bsize=4096 blocks=68719475712, imaxpct=1 > = sunit=1024 swidth=8192 blks > naming =version 2 bsize=4096 ascii-ci=0, ftype=1 > log =internal log bsize=4096 blocks=521728, version=2 > = sectsz=4096 sunit=1 blks, lazy-count=1 > realtime =none extsz=4096 blocks=0, rtextents=0 > > Is there something I can do to "unstick" things, or is it time to hit > the reset, and hope the recovery on mount isn't onerous? > > Aside from that immediate issue, what has gone wrong here? > > Cheers, > > Chris ^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: fstrim and strace considered harmful? 2022-05-18 7:07 ` Chris Dunlop @ 2022-05-18 15:59 ` Darrick J. Wong 2022-05-18 22:36 ` Chris Dunlop 0 siblings, 1 reply; 8+ messages in thread From: Darrick J. Wong @ 2022-05-18 15:59 UTC (permalink / raw) To: Chris Dunlop; +Cc: linux-xfs On Wed, May 18, 2022 at 05:07:13PM +1000, Chris Dunlop wrote: > Oh, sorry... on linux v5.15.34 > > On Wed, May 18, 2022 at 04:59:49PM +1000, Chris Dunlop wrote: > > Hi, > > > > I have an fstrim that's been running for over 48 hours on a 256T thin > > provisioned XFS fs containing around 55T of actual data on a slow > > subsystem (ceph 8,3 erasure-encoded rbd). I don't think there would be > > an an enourmous amount of data to trim, maybe a few T, but I've no idea > > how long how long it might be expected to take. In an attempt to see > > what the what the fstrim was doing, I ran an strace on it. The strace > > has been sitting there without output and unkillable since then, now 5+ > > hours ago. Since the strace, on that same filesystem I now have 123 df > > processes and 615 rm processes -- and growing -- that are blocked in > > xfs_inodegc_flush, e.g.: > > > > May 18 15:31:52 d5 kernel: task:df state:D stack: 0 pid:31741 ppid: 1 flags:0x00004004 > > May 18 15:31:52 d5 kernel: Call Trace: > > May 18 15:31:52 d5 kernel: <TASK> > > May 18 15:31:52 d5 kernel: __schedule+0x241/0x740 > > May 18 15:31:52 d5 kernel: ? lock_is_held_type+0x97/0x100 > > May 18 15:31:52 d5 kernel: schedule+0x3a/0xa0 > > May 18 15:31:52 d5 kernel: schedule_timeout+0x271/0x310 > > May 18 15:31:52 d5 kernel: ? find_held_lock+0x2d/0x90 > > May 18 15:31:52 d5 kernel: ? sched_clock_cpu+0x9/0xa0 > > May 18 15:31:52 d5 kernel: ? lock_release+0x214/0x350 > > May 18 15:31:52 d5 kernel: wait_for_completion+0x7b/0xc0 > > May 18 15:31:52 d5 kernel: __flush_work+0x217/0x350 > > May 18 15:31:52 d5 kernel: ? flush_workqueue_prep_pwqs+0x120/0x120 > > May 18 15:31:52 d5 kernel: ? wait_for_completion+0x1c/0xc0 > > May 18 15:31:52 d5 kernel: xfs_inodegc_flush.part.24+0x62/0xc0 [xfs] > > May 18 15:31:52 d5 kernel: xfs_fs_statfs+0x37/0x1a0 [xfs] > > May 18 15:31:52 d5 kernel: statfs_by_dentry+0x3c/0x60 > > May 18 15:31:52 d5 kernel: vfs_statfs+0x16/0xd0 > > May 18 15:31:52 d5 kernel: user_statfs+0x44/0x80 > > May 18 15:31:52 d5 kernel: __do_sys_statfs+0x10/0x30 > > May 18 15:31:52 d5 kernel: do_syscall_64+0x34/0x80 > > May 18 15:31:52 d5 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xae > > May 18 15:31:52 d5 kernel: RIP: 0033:0x7fe9e9db3c07 > > May 18 15:31:52 d5 kernel: RSP: 002b:00007ffe08f50178 EFLAGS: 00000246 ORIG_RAX: 0000000000000089 > > May 18 15:31:52 d5 kernel: RAX: ffffffffffffffda RBX: 0000555963fcae40 RCX: 00007fe9e9db3c07 > > May 18 15:31:52 d5 kernel: RDX: 00007ffe08f50400 RSI: 00007ffe08f50180 RDI: 0000555963fcae40 > > May 18 15:31:52 d5 kernel: RBP: 00007ffe08f50180 R08: 0000555963fcae80 R09: 0000000000000000 > > May 18 15:31:52 d5 kernel: R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffe08f50220 > > May 18 15:31:52 d5 kernel: R13: 0000000000000000 R14: 0000555963fcae80 R15: 0000555963fcae40 > > May 18 15:31:52 d5 kernel: </TASK> > > > > Full 1.5M sysrq output at: https://file.io/bWOL8F7mzKI6 task:fstrim state:D stack: 0 pid: 3552 ppid: 2091 flags:0x00004006 Call Trace: <TASK> __schedule+0x241/0x740 schedule+0x3a/0xa0 schedule_timeout+0x1c9/0x310 ? del_timer_sync+0x90/0x90 io_schedule_timeout+0x19/0x40 wait_for_completion_io_timeout+0x75/0xd0 submit_bio_wait+0x63/0x90 ? wait_for_completion_io_timeout+0x1f/0xd0 blkdev_issue_discard+0x6a/0xa0 ? _raw_spin_unlock+0x1f/0x30 xfs_trim_extents+0x1a7/0x3d0 [xfs] xfs_ioc_trim+0x161/0x1e0 [xfs] xfs_file_ioctl+0x914/0xbf0 [xfs] ? __do_sys_newfstat+0x2d/0x40 __x64_sys_ioctl+0x71/0xb0 do_syscall_64+0x34/0x80 entry_SYSCALL_64_after_hwframe+0x44/0xae RIP: 0033:0x7fa84e61ae57 RSP: 002b:00007ffe90fa1da8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010 RAX: ffffffffffffffda RBX: 00007ffe90fa1f10 RCX: 00007fa84e61ae57 RDX: 00007ffe90fa1db0 RSI: 00000000c0185879 RDI: 0000000000000003 RBP: 0000000000000003 R08: 0000000000000000 R09: 0000000000000000 R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffe90fa3d10 R13: 00007ffe90fa3d10 R14: 0000000000000000 R15: 00007fa84e1fdff8 </TASK> It looks like the storage device is stalled on the discard, and most everything else is stuck waiting for buffer locks? The statfs threads are the same symptom as last time. --D > > > > That stack trace is uncomfortably familiar: > > > > Subject: Highly reflinked and fragmented considered harmful? > > https://lore.kernel.org/linux-xfs/20220509024659.GA62606@onthe.net.au/ > > > > FYI: > > > > # xfs_info /vol > > meta-data=/dev/vg01/vol isize=512 agcount=257, agsize=268434432 blks > > = sectsz=4096 attr=2, projid32bit=1 > > = crc=1 finobt=1, sparse=1, rmapbt=1 > > = reflink=1 bigtime=1 inobtcount=1 > > data = bsize=4096 blocks=68719475712, imaxpct=1 > > = sunit=1024 swidth=8192 blks > > naming =version 2 bsize=4096 ascii-ci=0, ftype=1 > > log =internal log bsize=4096 blocks=521728, version=2 > > = sectsz=4096 sunit=1 blks, lazy-count=1 > > realtime =none extsz=4096 blocks=0, rtextents=0 > > > > Is there something I can do to "unstick" things, or is it time to hit > > the reset, and hope the recovery on mount isn't onerous? > > > > Aside from that immediate issue, what has gone wrong here? > > > > Cheers, > > > > Chris ^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: fstrim and strace considered harmful? 2022-05-18 15:59 ` Darrick J. Wong @ 2022-05-18 22:36 ` Chris Dunlop 2022-05-19 0:50 ` Dave Chinner 0 siblings, 1 reply; 8+ messages in thread From: Chris Dunlop @ 2022-05-18 22:36 UTC (permalink / raw) To: Darrick J. Wong; +Cc: linux-xfs On Wed, May 18, 2022 at 08:59:00AM -0700, Darrick J. Wong wrote: > On Wed, May 18, 2022 at 05:07:13PM +1000, Chris Dunlop wrote: >> Oh, sorry... on linux v5.15.34 >> >> On Wed, May 18, 2022 at 04:59:49PM +1000, Chris Dunlop wrote: >>> I have an fstrim that's been running for over 48 hours on a 256T thin >>> provisioned XFS fs containing around 55T of actual data on a slow >>> subsystem (ceph 8,3 erasure-encoded rbd). I don't think there would be >>> an an enourmous amount of data to trim, maybe a few T, but I've no idea >>> how long how long it might be expected to take. In an attempt to see >>> what the what the fstrim was doing, I ran an strace on it. The strace >>> has been sitting there without output and unkillable since then, now 5+ >>> hours ago. Since the strace, on that same filesystem I now have 123 df >>> processes and 615 rm processes -- and growing -- that are blocked in >>> xfs_inodegc_flush, e.g.: ... > It looks like the storage device is stalled on the discard, and most > everything else is stuck waiting for buffer locks? The statfs threads > are the same symptom as last time. Note: the box has been rebooted and it's back to normal after an anxious 30 minutes waiting for the mount recovery. (Not an entirely wasted 30 minutes - what a thrilling stage of the Giro d'Italia!) I'm not sure if the fstrim was stalled, unless the strace had stalled it somehow: it had been running for ~48 hours without apparent issues before the strace was attached, and then it was another hour before the first process stuck on xfs_inodegc_flush appeared. The open question is what caused the stuck processes? It's possible the strace was involved: the stuck process with the earliest start time, a "df", was started an hour after the strace and it's entirely plausible that was the very first df or rm issued after the strace. However it's also plausible that was a coincidence and the strace had nothing to do with it. Indeed it's even plausible the fstrim had nothing to do with the stuck processes and there's something else entirely going on: I don't know if there's a ticking time bomb somewhere in the system It's now no mystery to me why the fstrim was taking so long, nor why the strace didn't produce any output: it turns out fstrim, without an explicit --offset --length range, issues a single ioctl() to trim from the start of the device to the end, and without an explicit --minimum, uses /sys/block/xxx/queue/discard_granularity as the minimum block size to discard, in this case 64kB. So it would have been issuing a metric shit-ton of discard requests to the underlying storage, something close to: (fs-size - fs-used) / discard-size 256T - 26T / 64k 3,858,759,680 requests It was after figuring out all that that I hit the reset. Note: it turns out the actual used space per the filesystem is 26T, whilst the underlying storage shows 55T used, i.e. there's 29T of real discards to process. With this ceph rbd storage I don't know if a "real" discard takes any more or less time than a discard to already-unoccupied storage. Next time I'll issue the fstrim in much smaller increments, e.g. starting with perhaps 128G (at least at first), and use a --minimum that matches the underlying object size (4MB). Then play around and monitor it to work out what parameters work best for this system. Cheers, Chris - older, wiser, a little more sleep deprived ^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: fstrim and strace considered harmful? 2022-05-18 22:36 ` Chris Dunlop @ 2022-05-19 0:50 ` Dave Chinner 2022-05-19 2:33 ` Chris Dunlop 2022-05-19 15:25 ` Chris Murphy 0 siblings, 2 replies; 8+ messages in thread From: Dave Chinner @ 2022-05-19 0:50 UTC (permalink / raw) To: Chris Dunlop; +Cc: Darrick J. Wong, linux-xfs On Thu, May 19, 2022 at 08:36:06AM +1000, Chris Dunlop wrote: > On Wed, May 18, 2022 at 08:59:00AM -0700, Darrick J. Wong wrote: > > On Wed, May 18, 2022 at 05:07:13PM +1000, Chris Dunlop wrote: > > > Oh, sorry... on linux v5.15.34 > > > > > > On Wed, May 18, 2022 at 04:59:49PM +1000, Chris Dunlop wrote: > > > > I have an fstrim that's been running for over 48 hours on a 256T thin > > > > provisioned XFS fs containing around 55T of actual data on a slow > > > > subsystem (ceph 8,3 erasure-encoded rbd). I don't think there would be > > > > an an enourmous amount of data to trim, maybe a few T, but I've no idea > > > > how long how long it might be expected to take. In an attempt to see > > > > what the what the fstrim was doing, I ran an strace on it. The strace > > > > has been sitting there without output and unkillable since then, now 5+ > > > > hours ago. Since the strace, on that same filesystem I now have 123 df > > > > processes and 615 rm processes -- and growing -- that are blocked in > > > > xfs_inodegc_flush, e.g.: > ... > > It looks like the storage device is stalled on the discard, and most > > everything else is stuck waiting for buffer locks? The statfs threads > > are the same symptom as last time. > > Note: the box has been rebooted and it's back to normal after an anxious 30 > minutes waiting for the mount recovery. (Not an entirely wasted 30 minutes - > what a thrilling stage of the Giro d'Italia!) > > I'm not sure if the fstrim was stalled, unless the strace had stalled it > somehow: it had been running for ~48 hours without apparent issues before > the strace was attached, and then it was another hour before the first > process stuck on xfs_inodegc_flush appeared. I suspect that it's just that your storage device is really slow at small trims. If you didn't set a minimum trim size, XFS will issue discards on every free space in it's trees. If you have fragmented free space (quite possible if you're using reflink and removing files that have been reflinked and modified) then you could have millions of tiny free spaces that XFS is now asking the storage to free. Dumping the free space histogram of the filesystem will tell us just how much work you asked the storage to do. e.g: # xfs_spaceman -c "freesp" / from to extents blocks pct 1 1 20406 20406 0.03 2 3 14974 35666 0.06 4 7 11773 61576 0.10 8 15 11935 131561 0.22 16 31 15428 359009 0.60 32 63 13594 620194 1.04 64 127 15354 1415541 2.38 128 255 19269 3560215 5.98 256 511 975 355811 0.60 512 1023 831 610381 1.02 1024 2047 398 580983 0.98 2048 4095 275 827636 1.39 4096 8191 156 911802 1.53 8192 16383 90 1051443 1.77 16384 32767 54 1257999 2.11 32768 65535 17 813203 1.37 65536 131071 13 1331349 2.24 131072 262143 18 3501547 5.88 262144 524287 8 2834877 4.76 524288 1048575 8 5722448 9.61 1048576 2097151 6 9189190 15.43 2097152 4194303 4 14026658 23.55 4194304 8388607 2 10348013 17.37 # So on this 1TB filesystem, there's ~125,000 free space extents and the vast majority of them are less than 255 blocks in length (1MB). Hence I run fstrim on this filesystem without a minium size limit, it will issue roughly 125,000 discard requests. If I set a 1MB minimum size, it will issue discards on all free spaces 256 blocks or larger. i.e. it will only issue ~2000 discards and that will cover ~92% of the free space in the filesystem.... > The open question is what caused the stuck processes? Oh, that's easy the easy bit to explain: discard runs with the AGF locked because it is iterating the free space tree directly. Hence operations on that AG are blocked until all the free space in that AG have been discarded. Could be smarter, never needed to be smarter. Now inodegc comes along, and tries to free an inode in that AG, and blocks getting the AGF lock during the inode free operation (likely inode chunk freeing of finobt block allocation). Everythign then backs up on inodegc flushes, which is backed up on discard operations.... > It's now no mystery to me why the fstrim was taking so long, nor why the > strace didn't produce any output: it turns out fstrim, without an explicit > --offset --length range, issues a single ioctl() to trim from the start of > the device to the end, and without an explicit --minimum, uses > /sys/block/xxx/queue/discard_granularity as the minimum block size to > discard, in this case 64kB. So it would have been issuing a metric shit-ton > of discard requests to the underlying storage, something close to: > > (fs-size - fs-used) / discard-size > 256T - 26T / 64k > 3,858,759,680 requests Won't be anywhere near that number - free space in a 256TB filesystem with only 29TB used will have lots of really large contiguous free spaces. Those will get broken down into max discard length chunks, not minimum. Of course, if the bdev is setting a really small max discard size, then that's going to be just a big a problem for you.... > It was after figuring out all that that I hit the reset. Yup, see above for how to actually determine what minimum size to set for a trim.... Cheers, Dave. -- Dave Chinner david@fromorbit.com ^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: fstrim and strace considered harmful? 2022-05-19 0:50 ` Dave Chinner @ 2022-05-19 2:33 ` Chris Dunlop 2022-05-19 6:33 ` Dave Chinner 2022-05-19 15:25 ` Chris Murphy 1 sibling, 1 reply; 8+ messages in thread From: Chris Dunlop @ 2022-05-19 2:33 UTC (permalink / raw) To: Dave Chinner; +Cc: Darrick J. Wong, linux-xfs On Thu, May 19, 2022 at 10:50:14AM +1000, Dave Chinner wrote: > On Thu, May 19, 2022 at 08:36:06AM +1000, Chris Dunlop wrote: >> On Wed, May 18, 2022 at 08:59:00AM -0700, Darrick J. Wong wrote: >>> On Wed, May 18, 2022 at 05:07:13PM +1000, Chris Dunlop wrote: >>>> Oh, sorry... on linux v5.15.34 >>>> >>>> On Wed, May 18, 2022 at 04:59:49PM +1000, Chris Dunlop wrote: >>>>> I have an fstrim that's been running for over 48 hours on a 256T thin >>>>> provisioned XFS fs containing around 55T of actual data on a slow >>>>> subsystem (ceph 8,3 erasure-encoded rbd). I don't think there would be >>>>> an an enourmous amount of data to trim, maybe a few T, but I've no idea >>>>> how long how long it might be expected to take. In an attempt to see >>>>> what the what the fstrim was doing, I ran an strace on it. The strace >>>>> has been sitting there without output and unkillable since then, now 5+ >>>>> hours ago. Since the strace, on that same filesystem I now have 123 df >>>>> processes and 615 rm processes -- and growing -- that are blocked in >>>>> xfs_inodegc_flush, e.g.: ... > I suspect that it's just that your storage device is really slow at > small trims. If you didn't set a minimum trim size, XFS will issue > discards on every free space in it's trees. If you have fragmented > free space (quite possible if you're using reflink and removing > files that have been reflinked and modified) then you could have > millions of tiny free spaces that XFS is now asking the storage to > free. > > Dumping the free space histogram of the filesystem will tell us just > how much work you asked the storage to do. e.g: # xfs_spaceman -c freesp /vol from to extents blocks pct 1 1 2368 2368 0.00 2 3 4493 11211 0.00 4 7 6827 38214 0.00 8 15 12656 144036 0.00 16 31 35988 878969 0.00 32 63 163747 8091729 0.01 64 127 248625 22572336 0.04 128 255 367889 71796010 0.11 256 511 135012 48176856 0.08 512 1023 92534 74126716 0.12 1024 2047 13464 18608536 0.03 2048 4095 3873 10930189 0.02 4096 8191 1374 7886168 0.01 8192 16383 598 6875977 0.01 16384 32767 340 7729264 0.01 32768 65535 146 6745043 0.01 65536 131071 48 4419901 0.01 131072 262143 12 2380800 0.00 262144 524287 5 1887092 0.00 524288 1048575 2 1105184 0.00 1048576 2097151 4 5316211 0.01 2097152 4194303 3 8747030 0.01 4194304 8388607 65 522142416 0.83 8388608 16777215 2 21411858 0.03 67108864 134217727 4 379247828 0.60 134217728 268434432 236 62042143854 98.05 I guess from/to are in units of filesystem blocks, 4kB in this case? Not that it makes much difference here, but the sake of accuracy... does the default fstrim without range/size args issue discard requests for *all* the extents, or, if I'm reading this right: fs/xfs/xfs_discard.c -- xfs_ioc_trim( struct xfs_mount *mp, struct fstrim_range __user *urange) { struct request_queue *q = bdev_get_queue(mp->m_ddev_targp->bt_bdev); unsigned int granularity = q->limits.discard_granularity; ... if (copy_from_user(&range, urange, sizeof(range))) return -EFAULT; range.minlen = max_t(u64, granularity, range.minlen); ... } ...does it take into account /sys/block/xxx/queue/discard_granularity, in this case 64kB, or 16 blocks @ 4kB, so issuing discards only for extents >= 16 blocks? >> The open question is what caused the stuck processes? > > Oh, that's easy the easy bit to explain: discard runs with the AGF > locked because it is iterating the free space tree directly. Hence > operations on that AG are blocked until all the free space in that > AG have been discarded. Could be smarter, never needed to be > smarter. > > Now inodegc comes along, and tries to free an inode in that AG, and > blocks getting the AGF lock during the inode free operation (likely > inode chunk freeing of finobt block allocation). Everythign then > backs up on inodegc flushes, which is backed up on discard > operations.... I'm not sure that explains how the first stuck process only appeared >48 hours after initiating the fstrim. Unless that's because it may have finally got to the AG(s) with a lot of free extents? # # AGs w/ at least 400 free extents: only 31 out of 256 AGs # d5# xfs_spaceman -c "freesp -gs" /chroot | awk '$2>=400 {print}' AG extents blocks 43 69435 29436263 47 14984 5623982 48 42482 166285283 49 56284 218913822 50 10354 240969820 { sequential range... 54 60416 11292928 55 72742 15344807 56 88455 17204239 57 81594 15218624 58 126731 27719558 59 64525 10047593 60 37324 8591083 61 57267 113745589 62 36501 18360912 63 3998 255040699 64 2684 258737072 65 2047 263904736 66 1503 265467595 67 920 263457328 68 1393 264277701 } 70 1150 266485834 72 406 267609078 77 429 267479272 79 911 267625473 80 1182 267354313 { sequential range... 105 39345 151535709 106 69512 57950504 107 46464 10236142 108 40795 8666966 109 14431 208027543 110 15800 258264227 } total free extents 1090313 total free blocks 63273250933 average free extent size 58032.2 The number of free space extents per AG seems oddly "lumpy", e.g. the sequential cluster ranges beginning with AGs 54 and 105 with a large number of extents. Is that simply due to the pattern of frees in this specific case or is there some underlying design to that? >> (fs-size - fs-used) / discard-size >> 256T - 26T / 64k >> 3,858,759,680 requests > > Won't be anywhere near that number - free space in a 256TB > filesystem with only 29TB used will have lots of really large > contiguous free spaces. Those will get broken down into max discard > length chunks, not minimum. Of course, if the bdev is setting a > really small max discard size, then that's going to be just a big a > problem for you.... Is this the bdev's max discard size? # cat /sys/block/dm-0/queue/discard_max_bytes 4194304 And does that mean, for instance, these 236 extents will be split into somewhere between 131072 and 262143 individual discard requests (i.e. size of extent in bytes divided by discard_max_bytes) being sent to the underlying "device" (ceph rbd)? # xfs_spaceman -c freesp /vol from to extents blocks pct ... 134217728 268434432 236 62042143854 98.05 Cheers, Chris ^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: fstrim and strace considered harmful? 2022-05-19 2:33 ` Chris Dunlop @ 2022-05-19 6:33 ` Dave Chinner 0 siblings, 0 replies; 8+ messages in thread From: Dave Chinner @ 2022-05-19 6:33 UTC (permalink / raw) To: Chris Dunlop; +Cc: Darrick J. Wong, linux-xfs On Thu, May 19, 2022 at 12:33:51PM +1000, Chris Dunlop wrote: > On Thu, May 19, 2022 at 10:50:14AM +1000, Dave Chinner wrote: > > On Thu, May 19, 2022 at 08:36:06AM +1000, Chris Dunlop wrote: > > > On Wed, May 18, 2022 at 08:59:00AM -0700, Darrick J. Wong wrote: > > > > On Wed, May 18, 2022 at 05:07:13PM +1000, Chris Dunlop wrote: > > > > > Oh, sorry... on linux v5.15.34 > > > > > > > > > > On Wed, May 18, 2022 at 04:59:49PM +1000, Chris Dunlop wrote: > > > > > > I have an fstrim that's been running for over 48 hours on a 256T thin > > > > > > provisioned XFS fs containing around 55T of actual data on a slow > > > > > > subsystem (ceph 8,3 erasure-encoded rbd). I don't think there would be > > > > > > an an enourmous amount of data to trim, maybe a few T, but I've no idea > > > > > > how long how long it might be expected to take. In an attempt to see > > > > > > what the what the fstrim was doing, I ran an strace on it. The strace > > > > > > has been sitting there without output and unkillable since then, now 5+ And now I sort of understand why strace appeared hung. read below.... > > > > > > hours ago. Since the strace, on that same filesystem I now have 123 df > > > > > > processes and 615 rm processes -- and growing -- that are blocked in > > > > > > xfs_inodegc_flush, e.g.: > ... > > I suspect that it's just that your storage device is really slow at > > small trims. If you didn't set a minimum trim size, XFS will issue > > discards on every free space in it's trees. If you have fragmented > > free space (quite possible if you're using reflink and removing > > files that have been reflinked and modified) then you could have > > millions of tiny free spaces that XFS is now asking the storage to > > free. > > > > Dumping the free space histogram of the filesystem will tell us just > > how much work you asked the storage to do. e.g: > > # xfs_spaceman -c freesp /vol > from to extents blocks pct > 1 1 2368 2368 0.00 > 2 3 4493 11211 0.00 > 4 7 6827 38214 0.00 > 8 15 12656 144036 0.00 > 16 31 35988 878969 0.00 > 32 63 163747 8091729 0.01 > 64 127 248625 22572336 0.04 > 128 255 367889 71796010 0.11 > 256 511 135012 48176856 0.08 > 512 1023 92534 74126716 0.12 > 1024 2047 13464 18608536 0.03 > 2048 4095 3873 10930189 0.02 > 4096 8191 1374 7886168 0.01 > 8192 16383 598 6875977 0.01 > 16384 32767 340 7729264 0.01 > 32768 65535 146 6745043 0.01 > 65536 131071 48 4419901 0.01 > 131072 262143 12 2380800 0.00 > 262144 524287 5 1887092 0.00 > 524288 1048575 2 1105184 0.00 > 1048576 2097151 4 5316211 0.01 > 2097152 4194303 3 8747030 0.01 > 4194304 8388607 65 522142416 0.83 > 8388608 16777215 2 21411858 0.03 > 67108864 134217727 4 379247828 0.60 > 134217728 268434432 236 62042143854 98.05 > > I guess from/to are in units of filesystem blocks, 4kB in this case? Yes. > > Not that it makes much difference here, but the sake of accuracy... does the > default fstrim without range/size args issue discard requests for *all* the > extents, or, if I'm reading this right: > > fs/xfs/xfs_discard.c > -- > xfs_ioc_trim( > struct xfs_mount *mp, > struct fstrim_range __user *urange) > { > struct request_queue *q = bdev_get_queue(mp->m_ddev_targp->bt_bdev); > unsigned int granularity = q->limits.discard_granularity; > ... > if (copy_from_user(&range, urange, sizeof(range))) > return -EFAULT; > > range.minlen = max_t(u64, granularity, range.minlen); > ... > } > > ...does it take into account /sys/block/xxx/queue/discard_granularity, in Yes, that's the sysfs file that exports the current value of q->limits.discard_granularity. > this case 64kB, or 16 blocks @ 4kB, so issuing discards only for extents > > = 16 blocks? Yes. But that's not the same on every device. My local nvme SSDs give: $ cat /sys/block/nvme0n1/queue/discard_granularity 512 $ So the disk has a granualrity of 1 sector or 512 bytes. Hence fstrim will try to trim right down to single filsystem block free spaces by default. > > > > The open question is what caused the stuck processes? > > > > Oh, that's easy the easy bit to explain: discard runs with the AGF > > locked because it is iterating the free space tree directly. Hence > > operations on that AG are blocked until all the free space in that > > AG have been discarded. Could be smarter, never needed to be > > smarter. > > > > Now inodegc comes along, and tries to free an inode in that AG, and > > blocks getting the AGF lock during the inode free operation (likely > > inode chunk freeing of finobt block allocation). Everythign then > > backs up on inodegc flushes, which is backed up on discard > > operations.... > > I'm not sure that explains how the first stuck process only appeared >48 > hours after initiating the fstrim. Unless that's because it may have finally > got to the AG(s) with a lot of free extents? I know why now - see below. It's the same reason the strace is hung. It took 2 days for fstrim to progress to an AG that had active inode freeing going on in it. > # AGs w/ at least 400 free extents: only 31 out of 256 AGs > # > d5# xfs_spaceman -c "freesp -gs" /chroot | awk '$2>=400 {print}' AG > extents blocks > 43 69435 29436263 > 47 14984 5623982 > 48 42482 166285283 > 49 56284 218913822 > 50 10354 240969820 > { sequential range... > 54 60416 11292928 > 55 72742 15344807 > 56 88455 17204239 > 57 81594 15218624 > 58 126731 27719558 > 59 64525 10047593 > 60 37324 8591083 > 61 57267 113745589 > 62 36501 18360912 > 63 3998 255040699 > 64 2684 258737072 > 65 2047 263904736 > 66 1503 265467595 > 67 920 263457328 > 68 1393 264277701 > } > 70 1150 266485834 > 72 406 267609078 > 77 429 267479272 > 79 911 267625473 > 80 1182 267354313 > { sequential range... > 105 39345 151535709 > 106 69512 57950504 > 107 46464 10236142 > 108 40795 8666966 > 109 14431 208027543 > 110 15800 258264227 > } > total free extents 1090313 > total free blocks 63273250933 That's 250GB of free space in 1 million extents spread across 31 AG btrees. Not a huge deal for the filesystem, but for trim on a really slow block device.... > average free extent size 58032.2 > > The number of free space extents per AG seems oddly "lumpy", e.g. the > sequential cluster ranges beginning with AGs 54 and 105 with a large number > of extents. Is that simply due to the pattern of frees in this specific case > or is there some underlying design to that? That's likely showing how the allocator uses locality for related inodes. The underlying locality algorithm will give files in the same directory the same target AG. So if you have a directory with 100 100GB files in them, they will largely all be allocated from AGs target to target + 10. When you reflink and overwrite, the overwrite allocations will also get targetted to the same locality, and so you'll get lots of small extents allocated across the same AGs, too. When you then remove one of the reflinked files, only the overwrites unique to that copy are freed, and now you get new small free spaces in amongst largely full AGs. DO taht often enough, and you get a significant number of small free spaces occurring. IIRC, you last problem was one directory with 50 highly reflinked files totalling 29TB of capacity - the above is pretty much the sort of allocation and free space patterns I'd expect to see for that pattern of data storage.... > > Won't be anywhere near that number - free space in a 256TB > > filesystem with only 29TB used will have lots of really large > > contiguous free spaces. Those will get broken down into max discard > > length chunks, not minimum. Of course, if the bdev is setting a > > really small max discard size, then that's going to be just a big a > > problem for you.... > > Is this the bdev's max discard size? Yup. > # cat /sys/block/dm-0/queue/discard_max_bytes > 4194304 And that's the problem right there. What is the value for the underlying ceph rbds? That will tell us if this number comes from the ceph rbds or the dm layers you have above the ceph rbds. What are you using for thin provisioning? Is that the dm layer (dm-thin) or something you are getting from the ceph rbds? FWIW, the 1TB nvme drive I mentioned above? $ cat /sys/block/nvme0n1/queue/discard_max_bytes 2199023255040 $ echo $(((2**32 - 1 ) * 512)) 2199023255040 $ That can handle one sector short of 2TB per discard, which I think is the maximum the nvme protocol allows in a single discard operation. IOWs, I can issue a single discard request to free the entire device. > And does that mean, for instance, these 236 extents will be split into > somewhere between 131072 and 262143 individual discard requests (i.e. size > of extent in bytes divided by discard_max_bytes) being sent to the > underlying "device" (ceph rbd)? > > # xfs_spaceman -c freesp /vol > from to extents blocks pct > ... > 134217728 268434432 236 62042143854 98.05 Yes. these are largely empty AGs - most of them have more than half their space in one large contiguous free extent. And this will be why the strace appears hung - discarding a single AG full of free space (1TB) will be done as 250,000+ individual discard operations. So that's something like 55 million discards for the ~220TB of free space you have in that filesystem.... As to the strace that has hung - the discard loop has this in it: if (fatal_signal_pending(current)) { error = -ERESTARTSYS; goto out_del_cursor; } So if you ctrl-c the fstrim and we are doing discards on small free spaces, it should abort almost straight away. However, if we've issued a single discard for an entirely empty AG - we've called blkdev_issue_discard() with a 1TB length. blkdev_issue_discard() does the slice and dice into device length and aligned discards, and it has no checks for signals in it's main loop. So strace/fstrim are stuck until those 250,000+ discards are issued and completed - however many hours that will take. I suspect that we should push a signal check into blkdev_issue_discard() and friends. If you've got a recent iostat on your system: $ iostat -dxyzm 5 <trimmed read/write output for reability> Device d/s dMB/s drqm/s %drqm d_await dareq-sz f/s f_await aqu-sz %util nvme0n1 0 0.00 0.00 0.00 0.00 0.00 0.00 5.60 1.21 0.01 2.56 nvme0n1 0 367.60 204.51 0.00 0.00 2.58 569.69 0.80 8.75 0.96 97.04 nvme0n1 0 362.20 579.89 0.00 0.00 2.71 1639.44 3.60 1.89 1.00 100.00 nvme0n1 0 376.20 2070.96 0.00 0.00 2.59 5637.08 0.60 0.67 0.98 99.44 .... You can see what sort of progress the discards are making. Cheers, Dave. -- Dave Chinner david@fromorbit.com ^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: fstrim and strace considered harmful? 2022-05-19 0:50 ` Dave Chinner 2022-05-19 2:33 ` Chris Dunlop @ 2022-05-19 15:25 ` Chris Murphy 1 sibling, 0 replies; 8+ messages in thread From: Chris Murphy @ 2022-05-19 15:25 UTC (permalink / raw) To: Dave Chinner; +Cc: Chris Dunlop, Darrick J. Wong, xfs list On Wed, May 18, 2022 at 8:50 PM Dave Chinner <david@fromorbit.com> wrote: > I suspect that it's just that your storage device is really slow at > small trims. If you didn't set a minimum trim size, XFS will issue > discards on every free space in it's trees. If you have fragmented > free space (quite possible if you're using reflink and removing > files that have been reflinked and modified) then you could have > millions of tiny free spaces that XFS is now asking the storage to > free. Yeah, fstrim man page says minimum-size default is 0, so it'll trim every filesystem free block. I asked about it a while ago in linux-block@ list and didn't get a reply, maybe it's the wrong list. https://lore.kernel.org/linux-block/CAJCQCtRM4Gn_EY_A0Da7qz=MFfmw08+oD=syQEQt=9DrE8_gFw@mail.gmail.com/ If the context includes trim down to SSD hardware, and if the workload involves lots of small files, and many/most of the mixed used+free portions of the filesystem blocks look like swiss cheese, then I suppose 1M granularity means quite a lot isn't trimmed, and ends up getting needlessly moved around by the firmware's wear leveling? But oh well? Maybe in that case the discard mount option makes more sense. But if context is only LVM thin provisioning, and not pass through to an SSD, then a 4M granularity is adequate (match the LVM logical extent size). I'm offhand not imagining a benefit to trimming thin provisioning less than LE size. -- Chris Murphy ^ permalink raw reply [flat|nested] 8+ messages in thread
end of thread, other threads:[~2022-05-19 15:28 UTC | newest] Thread overview: 8+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2022-05-18 6:59 fstrim and strace considered harmful? Chris Dunlop 2022-05-18 7:07 ` Chris Dunlop 2022-05-18 15:59 ` Darrick J. Wong 2022-05-18 22:36 ` Chris Dunlop 2022-05-19 0:50 ` Dave Chinner 2022-05-19 2:33 ` Chris Dunlop 2022-05-19 6:33 ` Dave Chinner 2022-05-19 15:25 ` Chris Murphy
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.