Re: xfs trace in 4.4.2 / also in 4.3.3 WARNING fs/xfs/xfs_aops.c:1232 xfs_vm_releasepage

[Brian Foster <bfoster@redhat.com>]

Dropped non-XFS cc's, probably no need to spam other lists at this
point...

On Wed, May 11, 2016 at 04:03:16PM +0200, Stefan Priebe - Profihost AG wrote:
> 
> Am 11.05.2016 um 15:34 schrieb Brian Foster:
> > On Wed, May 11, 2016 at 02:26:48PM +0200, Stefan Priebe - Profihost AG wrote:
> >> Hi Brian,
> >>
> >> i'm still unable to grab anything to the trace file? Is there anything
> >> to check if it's working at all?
> >>
> > 
> > See my previous mail:
> > 
> > http://oss.sgi.com/pipermail/xfs/2016-March/047793.html
> > 
> > E.g., something like this should work after writing to and removing a
> > new file:
> > 
> > # trace-cmd start -e "xfs:xfs_releasepage"
> > # cat /sys/kernel/debug/tracing/trace_pipe
> > ...
> > rm-8198  [000] ....  9445.774070: xfs_releasepage: dev 253:4 ino 0x69 pgoff 0x9ff000 size 0xa00000 offset 0 length 0 delalloc 0 unwritten 0
> 
> arg sorry yes that's working but delalloc is always 0.
> 

Hrm, Ok. That is strange.

> May be i have to hook that into my initramfs to be fast enough?
> 

Not sure that would matter.. you said it occurs within 48 hours? I take
that to mean it doesn't occur immediately on boot. You should be able to
tell from the logs or dmesg if it happens before you get a chance to
start the tracing.

Well, the options I can think of are:

- Perhaps I botched matching up the line number to the warning, in which
  case we might want to try 'grep -v "delalloc 0 unwritten 0"' to catch
  any delalloc or unwritten blocks at releasepage() time.

- Perhaps there's a race that the tracepoint doesn't catch. The warnings
  are based on local vars, so we could instrument the code to print a
  warning[1] to try and get the inode number.

Brian

[1] - compile tested diff:

diff --git a/fs/xfs/xfs_aops.c b/fs/xfs/xfs_aops.c
index 40645a4..94738ea 100644
--- a/fs/xfs/xfs_aops.c
+++ b/fs/xfs/xfs_aops.c
@@ -1038,11 +1038,18 @@ xfs_vm_releasepage(
 	gfp_t			gfp_mask)
 {
 	int			delalloc, unwritten;
+	struct xfs_inode	*ip = XFS_I(page->mapping->host);
 
 	trace_xfs_releasepage(page->mapping->host, page, 0, 0);
 
 	xfs_count_page_state(page, &delalloc, &unwritten);
 
+	if (delalloc || unwritten)
+		xfs_warn(ip->i_mount,
+		"ino 0x%llx delalloc %d unwritten %d pgoff 0x%llx size 0x%llx",
+			 ip->i_ino, delalloc, unwritten, page_offset(page),
+			 i_size_read(page->mapping->host));
+
 	if (WARN_ON_ONCE(delalloc))
 		return 0;
 	if (WARN_ON_ONCE(unwritten))

> Stefan
> 
> > Once that is working, add the grep command to filter out "delalloc 0"
> > instances, etc. For example:
> > 
> > 	cat .../trace_pipe | grep -v "delalloc 0" > ~/trace.out
> > 
> > Brian
> > 
> >> This still happens in the first 48 hours after a fresh reboot.
> >>
> >> Stefan
> >>
> >> Am 24.03.2016 um 13:24 schrieb Brian Foster:
> >>> On Thu, Mar 24, 2016 at 01:17:15PM +0100, Stefan Priebe - Profihost AG wrote:
> >>>>
> >>>> Am 24.03.2016 um 12:17 schrieb Brian Foster:
> >>>>> On Thu, Mar 24, 2016 at 09:15:15AM +0100, Stefan Priebe - Profihost AG wrote:
> >>>>>>
> >>>>>> Am 24.03.2016 um 09:10 schrieb Stefan Priebe - Profihost AG:
> >>>>>>>
> >>>>>>> Am 23.03.2016 um 15:07 schrieb Brian Foster:
> >>>>>>>> On Wed, Mar 23, 2016 at 02:28:03PM +0100, Stefan Priebe - Profihost AG wrote:
> >>>>>>>>> sorry new one the last one got mangled. Comments inside.
> >>>>>>>>>
> >>>>>>>>> Am 05.03.2016 um 23:48 schrieb Dave Chinner:
> >>>>>>>>>> On Fri, Mar 04, 2016 at 04:03:42PM -0500, Brian Foster wrote:
> >>>>>>>>>>> On Fri, Mar 04, 2016 at 09:02:06PM +0100, Stefan Priebe wrote:
> >>>>>>>>>>>> Am 04.03.2016 um 20:13 schrieb Brian Foster:
> >>>>>>>>>>>>> On Fri, Mar 04, 2016 at 07:47:16PM +0100, Stefan Priebe wrote:
> >>>>>>>>>>>>>> Am 20.02.2016 um 19:02 schrieb Stefan Priebe - Profihost AG:
> >>>>>>>>>>>>>>>
> >>>>>>>>>>>>>>>> Am 20.02.2016 um 15:45 schrieb Brian Foster <bfoster@redhat.com>:
> >>>>>>>>>>>>>>>>
> >>>>>>>>>>>>>>>>> On Sat, Feb 20, 2016 at 09:02:28AM +0100, Stefan Priebe wrote:
> >>>>>>>> ...
> >>>>>>>>>
> >>>>>>>>> This has happened again on 8 different hosts in the last 24 hours
> >>>>>>>>> running 4.4.6.
> >>>>>>>>>
> >>>>>>>>> All of those are KVM / Qemu hosts and are doing NO I/O except the normal
> >>>>>>>>> OS stuff as the VMs have remote storage. So no database, no rsync on
> >>>>>>>>> those hosts - just the OS doing nearly nothing.
> >>>>>>>>>
> >>>>>>>>> All those show:
> >>>>>>>>> [153360.287040] WARNING: CPU: 0 PID: 109 at fs/xfs/xfs_aops.c:1234
> >>>>>>>>> xfs_vm_releasepage+0xe2/0xf0()
> >>>>>>>>>
> >>>>>>>>
> >>>>>>>> Ok, well at this point the warning isn't telling us anything beyond
> >>>>>>>> you're reproducing the problem. We can't really make progress without
> >>>>>>>> more information. We don't necessarily know what application or
> >>>>>>>> operations caused this by the time it occurs, but perhaps knowing what
> >>>>>>>> file is affected could give us a hint.
> >>>>>>>>
> >>>>>>>> We have the xfs_releasepage tracepoint, but that's unconditional and so
> >>>>>>>> might generate a lot of noise by default. Could you enable the
> >>>>>>>> xfs_releasepage tracepoint and hunt for instances where delalloc != 0?
> >>>>>>>> E.g., we could leave a long running 'trace-cmd record -e
> >>>>>>>> "xfs:xfs_releasepage" <cmd>' command on several boxes and wait for the
> >>>>>>>> problem to occur. Alternatively (and maybe easier), run 'trace-cmd start
> >>>>>>>> -e "xfs:xfs_releasepage"' and leave something like 'cat
> >>>>>>>> /sys/kernel/debug/tracing/trace_pipe | grep -v "delalloc 0" >
> >>>>>>>> ~/trace.out' running to capture instances.
> >>>>>>
> >>>>>> Isn't the trace a WARN_ONCE? So it does not reoccur or can i check the
> >>>>>> it in the trace.out even the WARN_ONCE was already triggered?
> >>>>>>
> >>>>>
> >>>>> The tracepoint is independent from the warning (see
> >>>>> xfs_vm_releasepage()), so the tracepoint will fire every invocation of
> >>>>> the function regardless of whether delalloc blocks still exist at that
> >>>>> point. That creates the need to filter the entries.
> >>>>>
> >>>>> With regard to performance, I believe the tracepoints are intended to be
> >>>>> pretty lightweight. I don't think it should hurt to try it on a box,
> >>>>> observe for a bit and make sure there isn't a huge impact. Note that the
> >>>>> 'trace-cmd record' approach will save everything to file, so that's
> >>>>> something to consider I suppose.
> >>>>
> >>>> Tests / cat is running. Is there any way to test if it works? Or is it
> >>>> enough that cat prints stuff from time to time but does not match -v
> >>>> delalloc 0
> >>>>
> >>>
> >>> What is it printing where delalloc != 0? You could always just cat
> >>> trace_pipe and make sure the event is firing, it's just that I suspect
> >>> most entries will have delalloc == unwritten == 0.
> >>>
> >>> Also, while the tracepoint fires independent of the warning, it might
> >>> not be a bad idea to restart a system that has already seen the warning
> >>> since boot, just to provide some correlation or additional notification
> >>> when the problem occurs.
> >>>
> >>> Brian
> >>>
> >>>> Stefan
> >>>>
> >>>> _______________________________________________
> >>>> xfs mailing list
> >>>> xfs@oss.sgi.com
> >>>> http://oss.sgi.com/mailman/listinfo/xfs
> >>
> >> _______________________________________________
> >> xfs mailing list
> >> xfs@oss.sgi.com
> >> http://oss.sgi.com/mailman/listinfo/xfs
> 
> _______________________________________________
> xfs mailing list
> xfs@oss.sgi.com
> http://oss.sgi.com/mailman/listinfo/xfs

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs