xfs-trace-ilock-more

xfs-trace-ilock-more

[Christoph Hellwig]

Can you explain the story behid this patch in SLES11SP1?


---
From: Mark Fasheh <mfasheh@suse.de>
Date: Mon Oct  3 12:39:07 PDT 2011
Subject: xfs: add more ilock tracing
Patch-mainline: Never

Lets get a trace of the amount of time spent in xfs_ilock().

Signed-off-by: Mark Fasheh <mfasheh@suse.de>
Index: linux-2.6.32-xfs-tracing/fs/xfs/linux-2.6/xfs_trace.h
===================================================================
--- linux-2.6.32-xfs-tracing.orig/fs/xfs/linux-2.6/xfs_trace.h
+++ linux-2.6.32-xfs-tracing/fs/xfs/linux-2.6/xfs_trace.h
@@ -453,24 +453,27 @@ DEFINE_BUF_ITEM_EVENT(xfs_trans_binval);
 #define DEFINE_LOCK_EVENT(name) \
 TRACE_EVENT(name, \
 	TP_PROTO(struct xfs_inode *ip, unsigned lock_flags, \
-		 unsigned long caller_ip), \
-	TP_ARGS(ip,  lock_flags, caller_ip), \
+		 unsigned long start, unsigned long caller_ip), \
+	TP_ARGS(ip,  lock_flags, start, caller_ip),		\
 	TP_STRUCT__entry( \
 		__field(dev_t, dev) \
 		__field(xfs_ino_t, ino) \
 		__field(int, lock_flags) \
+		__field(unsigned long, start) \
 		__field(unsigned long, caller_ip) \
 	), \
 	TP_fast_assign( \
 		__entry->dev = VFS_I(ip)->i_sb->s_dev; \
 		__entry->ino = ip->i_ino; \
 		__entry->lock_flags = lock_flags; \
+		__entry->start = start;		  \
 		__entry->caller_ip = caller_ip; \
 	), \
-	TP_printk("dev %d:%d ino 0x%llx flags %s caller %pf", \
+	TP_printk("dev %d:%d ino 0x%llx flags %s wait %lu caller %pf", \
 		  MAJOR(__entry->dev), MINOR(__entry->dev), \
 		  __entry->ino, \
 		  __print_flags(__entry->lock_flags, "|", XFS_LOCK_FLAGS), \
+		  (jiffies - __entry->start), \
 		  (void *)__entry->caller_ip) \
 )
 
Index: linux-2.6.32-xfs-tracing/fs/xfs/xfs_iget.c
===================================================================
--- linux-2.6.32-xfs-tracing.orig/fs/xfs/xfs_iget.c
+++ linux-2.6.32-xfs-tracing/fs/xfs/xfs_iget.c
@@ -590,6 +590,8 @@ xfs_ilock(
 	xfs_inode_t		*ip,
 	uint			lock_flags)
 {
+	unsigned long start = jiffies;
+
 	/*
 	 * You can't set both SHARED and EXCL for the same lock,
 	 * and only XFS_IOLOCK_SHARED, XFS_IOLOCK_EXCL, XFS_ILOCK_SHARED,
@@ -611,7 +613,7 @@ xfs_ilock(
 	else if (lock_flags & XFS_ILOCK_SHARED)
 		mraccess_nested(&ip->i_lock, XFS_ILOCK_DEP(lock_flags));
 
-	trace_xfs_ilock(ip, lock_flags, _RET_IP_);
+	trace_xfs_ilock(ip, lock_flags, start, _RET_IP_);
 }
 
 /*
@@ -631,6 +633,8 @@ xfs_ilock_nowait(
 	xfs_inode_t		*ip,
 	uint			lock_flags)
 {
+	unsigned long start = jiffies;
+
 	/*
 	 * You can't set both SHARED and EXCL for the same lock,
 	 * and only XFS_IOLOCK_SHARED, XFS_IOLOCK_EXCL, XFS_ILOCK_SHARED,
@@ -656,7 +660,7 @@ xfs_ilock_nowait(
 		if (!mrtryaccess(&ip->i_lock))
 			goto out_undo_iolock;
 	}
-	trace_xfs_ilock_nowait(ip, lock_flags, _RET_IP_);
+	trace_xfs_ilock_nowait(ip, lock_flags, start, _RET_IP_);
 	return 1;
 
  out_undo_iolock:
@@ -684,7 +688,10 @@ void
 xfs_iunlock(
 	xfs_inode_t		*ip,
 	uint			lock_flags)
+
 {
+	unsigned long start = jiffies;
+
 	/*
 	 * You can't set both SHARED and EXCL for the same lock,
 	 * and only XFS_IOLOCK_SHARED, XFS_IOLOCK_EXCL, XFS_ILOCK_SHARED,
@@ -718,7 +725,7 @@ xfs_iunlock(
 		xfs_trans_unlocked_item(ip->i_itemp->ili_item.li_ailp,
 					(xfs_log_item_t*)(ip->i_itemp));
 	}
-	trace_xfs_iunlock(ip, lock_flags, _RET_IP_);
+	trace_xfs_iunlock(ip, lock_flags, start, _RET_IP_);
 }
 
 /*
@@ -730,6 +737,8 @@ xfs_ilock_demote(
 	xfs_inode_t		*ip,
 	uint			lock_flags)
 {
+	unsigned long start = jiffies;
+
 	ASSERT(lock_flags & (XFS_IOLOCK_EXCL|XFS_ILOCK_EXCL));
 	ASSERT((lock_flags & ~(XFS_IOLOCK_EXCL|XFS_ILOCK_EXCL)) == 0);
 
@@ -738,7 +747,7 @@ xfs_ilock_demote(
 	if (lock_flags & XFS_IOLOCK_EXCL)
 		mrdemote(&ip->i_iolock);
 
-	trace_xfs_ilock_demote(ip, lock_flags, _RET_IP_);
+	trace_xfs_ilock_demote(ip, lock_flags, start, _RET_IP_);
 }
 
 #ifdef DEBUG

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

Re: xfs-trace-ilock-more

[Mark Fasheh]

Hey Christoph,

On Tue, Dec 13, 2011 at 09:40:40PM -0500, Christoph Hellwig wrote:
> Can you explain the story behid this patch in SLES11SP1?

We were looking at some performance issues and needed a bit more information
on the amount of time spent in ilock. I can give you more specifics if you
want, I just have to dig up the e-mails (it's been a while).

Regards, Mark

--
Mark Fasheh

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

Re: xfs-trace-ilock-more

[Jeff Mahoney]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 12/14/2011 01:27 PM, Mark Fasheh wrote:
> Hey Christoph,
> 
> On Tue, Dec 13, 2011 at 09:40:40PM -0500, Christoph Hellwig wrote:
>> Can you explain the story behid this patch in SLES11SP1?
> 
> We were looking at some performance issues and needed a bit more
> information on the amount of time spent in ilock. I can give you
> more specifics if you want, I just have to dig up the e-mails (it's
> been a while).

That's pretty much the explanation. With heavy reader load, buffered
writes were stalling for 80 ms and sometimes longer. I suspected it
was contention on the ilock and the tracing with that patch
demonstrated a delay there. Since we were chasing a similar issue at
another site, it seemed worthwhile to just keep it around. We're still
tracking down the cause. I'm not sure if more recent kernels have the
same issue as there's been quite a lot of churn.

- -Jeff

- -- 
Jeff Mahoney
SUSE Labs
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.18 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iQIcBAEBAgAGBQJO6PfwAAoJEB57S2MheeWyE+MQAIeh/VUfWExpjsgdBbkSj4jv
7sJQW2WweYpHHZdLnGx5Pn4cDO6/2YyqNXfwAGZk2yoXTcycykR7ZVHLGEyyNDLV
BrKUvcDG/5XYTx3B64yPge8rNY9YIiy2e/c+pbwPeSnDPMY9976igqbrC5qaJ31a
1a/REm/MpDkGV7NcS4XYjbZwl0bP6BBJib0fnCrvkmWo7mtuzwz1XMpORGLWltOg
EhRTTgh+HRc1zlqknz5+ceMghky+GTp56/3YPslbco61uI9XmKzLc/bi1iNgda24
gy6wAIRk0EwPd9o2Wl+Jvvm79YvTE2SvkjDzHz3exOAX3JTMVnF//7bjVfPg7A9f
xyHQ7GQJRWQwIXuGVqi7JciN5/5IKOdkrGILIIC1osFjr7z894xGgQejNhqxuXNE
B06WUJ2PLYEOCKLCnH75OwCsDRqdj7N+yPbxGJIZeAjdiH6r2tanAAtYAtqdn+3T
J7sdsm/Kvod4wgKBLJWk/rvTI/i1pjoqNaeF0rdXsQbqGI7C9OKeNfIjilt0HT8h
9EIaoy3KjnGmAU1pouHZro2hR1Ec8Ni09DM5GMQeGTIAPvgTgP8oHB/MPFIM9Jnl
QxfLJ5o3bxvB3u2aDJQta3+V/9TQPfELtokjjk34GjAcaxBZT7mTy8lVOHVL1Srg
86cHVs6PDRXQf7CeoX+N
=Cjlo
-----END PGP SIGNATURE-----

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

Re: xfs-trace-ilock-more

[Dave Chinner]

On Wed, Dec 14, 2011 at 02:24:32PM -0500, Jeff Mahoney wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA1
> 
> On 12/14/2011 01:27 PM, Mark Fasheh wrote:
> > Hey Christoph,
> > 
> > On Tue, Dec 13, 2011 at 09:40:40PM -0500, Christoph Hellwig wrote:
> >> Can you explain the story behid this patch in SLES11SP1?
> > 
> > We were looking at some performance issues and needed a bit more
> > information on the amount of time spent in ilock. I can give you
> > more specifics if you want, I just have to dig up the e-mails (it's
> > been a while).
> 
> That's pretty much the explanation. With heavy reader load, buffered
> writes were stalling for 80 ms and sometimes longer. I suspected it
> was contention on the ilock and the tracing with that patch
> demonstrated a delay there. Since we were chasing a similar issue at
> another site, it seemed worthwhile to just keep it around. We're still
> tracking down the cause. I'm not sure if more recent kernels have the
> same issue as there's been quite a lot of churn.

I'm not surprised - there's nothing really guaranteeing bound shared
vs exclusive access to the ilock. It's all down to the read/write
bias of the rwsem - readers will hold off the writer for some time.
Still, it would be nice to see a trace from such a holdoff to
confirm this is actually the case...

FWIW, if you have an app that requires concurrent, low latency reads
and writes to the same file, that's what the XFS Direct IO was
designed for - in most cases the iolock is taken in shared mode for
both read and write, and so such hold-offs don't generally happen...

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

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

Re: xfs-trace-ilock-more

[Jeff Mahoney]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 12/14/2011 03:32 PM, Dave Chinner wrote:
> On Wed, Dec 14, 2011 at 02:24:32PM -0500, Jeff Mahoney wrote:
>> -----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
>> 
>> On 12/14/2011 01:27 PM, Mark Fasheh wrote:
>>> Hey Christoph,
>>> 
>>> On Tue, Dec 13, 2011 at 09:40:40PM -0500, Christoph Hellwig
>>> wrote:
>>>> Can you explain the story behid this patch in SLES11SP1?
>>> 
>>> We were looking at some performance issues and needed a bit
>>> more information on the amount of time spent in ilock. I can
>>> give you more specifics if you want, I just have to dig up the
>>> e-mails (it's been a while).
>> 
>> That's pretty much the explanation. With heavy reader load,
>> buffered writes were stalling for 80 ms and sometimes longer. I
>> suspected it was contention on the ilock and the tracing with
>> that patch demonstrated a delay there. Since we were chasing a
>> similar issue at another site, it seemed worthwhile to just keep
>> it around. We're still tracking down the cause. I'm not sure if
>> more recent kernels have the same issue as there's been quite a
>> lot of churn.
> 
> I'm not surprised - there's nothing really guaranteeing bound
> shared vs exclusive access to the ilock. It's all down to the
> read/write bias of the rwsem - readers will hold off the writer for
> some time. Still, it would be nice to see a trace from such a
> holdoff to confirm this is actually the case...

Sure, let me dig it up. We do actually have real results from this
workload with the trace running.

> FWIW, if you have an app that requires concurrent, low latency
> reads and writes to the same file, that's what the XFS Direct IO
> was designed for - in most cases the iolock is taken in shared mode
> for both read and write, and so such hold-offs don't generally
> happen...

You don't need to convince me. I agree with you. :)

- -Jeff

- -- 
Jeff Mahoney
SUSE Labs
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.18 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iQIcBAEBAgAGBQJO6SZeAAoJEB57S2MheeWyzfgP/3gbX++mlm3pY8iRlWkqEcy4
77OBJyMn0jxUqQkLw3nmrCcIMVJxKREJhtBoNl93mBdN8HZvx1X7nTUst769Ksf/
NsjQd3NMyv/pymjuJBB81APnyc2diM/fz/t5f1gh4xHljKG9rUJS8ogRQ65QBbMG
kDbwtgaXYMZpUpf/GAF7Q0jxefNZbs82BfSsGqDH6e+fdymqD9/GWewyIFCl3tVR
yOk80v4izDwlgtwtm/anq18nqePZl8M3ktwtucpAR/cxZ79nOryGxuqaD5r7GOam
bo/29A5x0UKptsxHKnEvf6JIlznVWR6RzheyV/A6d3gPFkMa8550NBFMmWObjh7h
DA/fcsZFhzD1LZI9BXU58ib6nT3kmtQMHmdsuwPsX5XPLzdymMNFD/yUDP7vhMWC
OR1kkLPBSGeCFK7m0IeScO+jCnVsadhzkeS3rMjbUYCSw3+4OGf21sAJnfsMasPb
Z2ZbbSZdUGItb8bK1lx7WEwST8KC5UYe2n3LIoH8CJ8qH+FrzX0pQKx+Gm2SVoMK
nZZKDbtwN9+ZWRs2p3tEuT34sb/XGFV1XnEBPAv272XAjZKvjwBD8JZF92fQxl8a
e2yjy7+EsqmZXNguTcs+KhLJ69QkKkg6J0rozPgUNHmA+KGhSDCgRI2kMCPDL3MO
uKZ2umow6YYTofS6mBp8
=zmC1
-----END PGP SIGNATURE-----

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

Re: xfs-trace-ilock-more

[Christoph Hellwig]

On Wed, Dec 14, 2011 at 02:24:32PM -0500, Jeff Mahoney wrote:
> That's pretty much the explanation. With heavy reader load, buffered
> writes were stalling for 80 ms and sometimes longer. I suspected it
> was contention on the ilock and the tracing with that patch
> demonstrated a delay there. Since we were chasing a similar issue at
> another site, it seemed worthwhile to just keep it around. We're still
> tracking down the cause. I'm not sure if more recent kernels have the
> same issue as there's been quite a lot of churn.

Ok.  I was a bit surprised that it was one out of only two XFS updates
that went into a recent SLES security errata, and I never heard about it
before.

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

Re: xfs-trace-ilock-more

[Christoph Hellwig]

On Wed, Dec 14, 2011 at 10:27:50AM -0800, Mark Fasheh wrote:
> Hey Christoph,
> 
> On Tue, Dec 13, 2011 at 09:40:40PM -0500, Christoph Hellwig wrote:
> > Can you explain the story behid this patch in SLES11SP1?
> 
> We were looking at some performance issues and needed a bit more information
> on the amount of time spent in ilock. I can give you more specifics if you
> want, I just have to dig up the e-mails (it's been a while).

Given that the patch is fairly clean can you send it to us for
inclusion?

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

Re: xfs-trace-ilock-more

[Mark Fasheh]

On Sun, Dec 18, 2011 at 03:27:34PM -0500, Christoph Hellwig wrote:
> Given that the patch is fairly clean can you send it to us for
> inclusion?

Here goes. I updated the patch for 3.2 and of course gave it a quick test.
	--Mark

--
Mark Fasheh

From: Mark Fasheh <mfasheh@suse.com>

[PATCH] xfs: add more ilock tracing

Let's get a trace of the amount of time spent in xfs_ilock(). This has
helped us (SUSE) in investigating read/write performance issues in the past
when ilock() contention has come up as a possibile issue.

Signed-off-by: Mark Fasheh <mfasheh@suse.de>
---
 fs/xfs/xfs_iget.c  |   16 ++++++++++++----
 fs/xfs/xfs_trace.h |   13 ++++++++-----
 2 files changed, 20 insertions(+), 9 deletions(-)

diff --git a/fs/xfs/xfs_iget.c b/fs/xfs/xfs_iget.c
index 0fa98b1..b83108b 100644
--- a/fs/xfs/xfs_iget.c
+++ b/fs/xfs/xfs_iget.c
@@ -543,6 +543,8 @@ xfs_ilock(
 	xfs_inode_t		*ip,
 	uint			lock_flags)
 {
+	unsigned long start = jiffies;
+
 	/*
 	 * You can't set both SHARED and EXCL for the same lock,
 	 * and only XFS_IOLOCK_SHARED, XFS_IOLOCK_EXCL, XFS_ILOCK_SHARED,
@@ -564,7 +566,7 @@ xfs_ilock(
 	else if (lock_flags & XFS_ILOCK_SHARED)
 		mraccess_nested(&ip->i_lock, XFS_ILOCK_DEP(lock_flags));
 
-	trace_xfs_ilock(ip, lock_flags, _RET_IP_);
+	trace_xfs_ilock(ip, lock_flags, start, _RET_IP_);
 }
 
 /*
@@ -584,6 +586,8 @@ xfs_ilock_nowait(
 	xfs_inode_t		*ip,
 	uint			lock_flags)
 {
+	unsigned long start = jiffies;
+
 	/*
 	 * You can't set both SHARED and EXCL for the same lock,
 	 * and only XFS_IOLOCK_SHARED, XFS_IOLOCK_EXCL, XFS_ILOCK_SHARED,
@@ -609,7 +613,7 @@ xfs_ilock_nowait(
 		if (!mrtryaccess(&ip->i_lock))
 			goto out_undo_iolock;
 	}
-	trace_xfs_ilock_nowait(ip, lock_flags, _RET_IP_);
+	trace_xfs_ilock_nowait(ip, lock_flags, start, _RET_IP_);
 	return 1;
 
  out_undo_iolock:
@@ -638,6 +642,8 @@ xfs_iunlock(
 	xfs_inode_t		*ip,
 	uint			lock_flags)
 {
+	unsigned long start = jiffies;
+
 	/*
 	 * You can't set both SHARED and EXCL for the same lock,
 	 * and only XFS_IOLOCK_SHARED, XFS_IOLOCK_EXCL, XFS_ILOCK_SHARED,
@@ -671,7 +677,7 @@ xfs_iunlock(
 		xfs_trans_unlocked_item(ip->i_itemp->ili_item.li_ailp,
 					(xfs_log_item_t*)(ip->i_itemp));
 	}
-	trace_xfs_iunlock(ip, lock_flags, _RET_IP_);
+	trace_xfs_iunlock(ip, lock_flags, start, _RET_IP_);
 }
 
 /*
@@ -683,6 +689,8 @@ xfs_ilock_demote(
 	xfs_inode_t		*ip,
 	uint			lock_flags)
 {
+	unsigned long start = jiffies;
+
 	ASSERT(lock_flags & (XFS_IOLOCK_EXCL|XFS_ILOCK_EXCL));
 	ASSERT((lock_flags & ~(XFS_IOLOCK_EXCL|XFS_ILOCK_EXCL)) == 0);
 
@@ -691,7 +699,7 @@ xfs_ilock_demote(
 	if (lock_flags & XFS_IOLOCK_EXCL)
 		mrdemote(&ip->i_iolock);
 
-	trace_xfs_ilock_demote(ip, lock_flags, _RET_IP_);
+	trace_xfs_ilock_demote(ip, lock_flags, start, _RET_IP_);
 }
 
 #ifdef DEBUG
diff --git a/fs/xfs/xfs_trace.h b/fs/xfs/xfs_trace.h
index 4940357..ef5523a 100644
--- a/fs/xfs/xfs_trace.h
+++ b/fs/xfs/xfs_trace.h
@@ -507,32 +507,35 @@ DEFINE_BUF_ITEM_EVENT(xfs_trans_binval);
 
 DECLARE_EVENT_CLASS(xfs_lock_class,
 	TP_PROTO(struct xfs_inode *ip, unsigned lock_flags,
-		 unsigned long caller_ip),
-	TP_ARGS(ip,  lock_flags, caller_ip),
+		 unsigned long start, unsigned long caller_ip),
+	TP_ARGS(ip,lock_flags, start, caller_ip),
 	TP_STRUCT__entry(
 		__field(dev_t, dev)
 		__field(xfs_ino_t, ino)
 		__field(int, lock_flags)
+		__field(unsigned long, start)
 		__field(unsigned long, caller_ip)
 	),
 	TP_fast_assign(
 		__entry->dev = VFS_I(ip)->i_sb->s_dev;
 		__entry->ino = ip->i_ino;
 		__entry->lock_flags = lock_flags;
+		__entry->start = start;
 		__entry->caller_ip = caller_ip;
 	),
-	TP_printk("dev %d:%d ino 0x%llx flags %s caller %pf",
+	TP_printk("dev %d:%d ino 0x%llx flags %s wait %lu caller %pf",
 		  MAJOR(__entry->dev), MINOR(__entry->dev),
 		  __entry->ino,
 		  __print_flags(__entry->lock_flags, "|", XFS_LOCK_FLAGS),
+		  (jiffies - __entry->start),
 		  (void *)__entry->caller_ip)
 )
 
 #define DEFINE_LOCK_EVENT(name) \
 DEFINE_EVENT(xfs_lock_class, name, \
 	TP_PROTO(struct xfs_inode *ip, unsigned lock_flags, \
-		 unsigned long caller_ip), \
-	TP_ARGS(ip,  lock_flags, caller_ip))
+		 unsigned long start, unsigned long caller_ip),	\
+	TP_ARGS(ip,  lock_flags, start, caller_ip))
 DEFINE_LOCK_EVENT(xfs_ilock);
 DEFINE_LOCK_EVENT(xfs_ilock_nowait);
 DEFINE_LOCK_EVENT(xfs_ilock_demote);
-- 
1.7.6

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

Re: xfs-trace-ilock-more

[Dave Chinner]

On Thu, Jan 05, 2012 at 02:38:59PM -0800, Mark Fasheh wrote:
> On Sun, Dec 18, 2011 at 03:27:34PM -0500, Christoph Hellwig wrote:
> > Given that the patch is fairly clean can you send it to us for
> > inclusion?
> 
> Here goes. I updated the patch for 3.2 and of course gave it a quick test.
> 	--Mark
> 
> --
> Mark Fasheh
> 
> From: Mark Fasheh <mfasheh@suse.com>
> 
> [PATCH] xfs: add more ilock tracing
> 
> Let's get a trace of the amount of time spent in xfs_ilock(). This has
> helped us (SUSE) in investigating read/write performance issues in the past
> when ilock() contention has come up as a possibile issue.
> 
> Signed-off-by: Mark Fasheh <mfasheh@suse.de>

....

> --- a/fs/xfs/xfs_trace.h
> +++ b/fs/xfs/xfs_trace.h
> @@ -507,32 +507,35 @@ DEFINE_BUF_ITEM_EVENT(xfs_trans_binval);
>  
>  DECLARE_EVENT_CLASS(xfs_lock_class,
>  	TP_PROTO(struct xfs_inode *ip, unsigned lock_flags,
> -		 unsigned long caller_ip),
> -	TP_ARGS(ip,  lock_flags, caller_ip),
> +		 unsigned long start, unsigned long caller_ip),
> +	TP_ARGS(ip,lock_flags, start, caller_ip),
>  	TP_STRUCT__entry(
>  		__field(dev_t, dev)
>  		__field(xfs_ino_t, ino)
>  		__field(int, lock_flags)
> +		__field(unsigned long, start)
>  		__field(unsigned long, caller_ip)
>  	),
>  	TP_fast_assign(
>  		__entry->dev = VFS_I(ip)->i_sb->s_dev;
>  		__entry->ino = ip->i_ino;
>  		__entry->lock_flags = lock_flags;
> +		__entry->start = start;
>  		__entry->caller_ip = caller_ip;
>  	),
> -	TP_printk("dev %d:%d ino 0x%llx flags %s caller %pf",
> +	TP_printk("dev %d:%d ino 0x%llx flags %s wait %lu caller %pf",
>  		  MAJOR(__entry->dev), MINOR(__entry->dev),
>  		  __entry->ino,
>  		  __print_flags(__entry->lock_flags, "|", XFS_LOCK_FLAGS),
> +		  (jiffies - __entry->start),

I'm not sure this is valid - the printk format can be used by tools
outside the kernel at a later time (e.g. they read from the kernel
in binary format). If you want this to be done, the it needs to be
calculated in the TP_fast_assign() macro.

Indeed, you are printing is the time delta between the start of
the operation and the completion. in that case, the delta should be
what is recorded in the trace point, not calculated implicitly
inside the format string of the trace point. i.e callers do:

	trace_xfs_iunlock(ip, lock_flags, jiffies - start, _RET_IP_);

to pass an explicit delta value to the trace point...

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

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