Re: [patch, rfc] autofs4: add trace points to the mount and unmount paths

Re: [patch, rfc] autofs4: add trace points to the mount and unmount paths

[Steve Dickson]

Hey,

Comments in-line...

On 06/30/2009 01:08 PM, Jeff Moyer wrote:
> Hi, Ian,
> 
> I got a fairly simply request from a customer.  They wanted to use
> systemtap to track automounter mount and unmount activity.
> Unfortunately, the compiler inlined the expire functions I wanted to
> instrument, so I needed to add a tracepoint to get at useful
> information.
> 
> This patch, then, adds a few trace points so that we don't have to worry
> about compiler inlining.  I have an example script using these trace
> points that I'll be sending along to the systemtap mailing list
> shortly.  Let me know what you think.  If you're interested in trying it
> out, I've made my systemtap patch available at:
>   http://people.redhat.com/jmoyer/systemtap
> 
> You can try running testsuite/systemtap.examples/general/autofs.stp.  It
> should run with or without the below patch applied, though the results
> are not as accurate (can't get full paths for unmounts) without the
> tracepoint in autofs4_do_expire_multi.
> 
> Cheers,
> Jeff
> 
> Signed-off-by: Jeff Moyer <jmoyer@redhat.com>
> 
> diff --git a/fs/autofs4/expire.c b/fs/autofs4/expire.c
> index aa39ae8..6c86df9 100644
> --- a/fs/autofs4/expire.c
> +++ b/fs/autofs4/expire.c
> @@ -13,6 +13,7 @@
>   * ------------------------------------------------------------------------- */
>  
>  #include "autofs_i.h"
> +#include <trace/events/autofs4.h>
>  
>  static unsigned long now;
>  
> @@ -496,6 +497,7 @@ int autofs4_do_expire_multi(struct super_block *sb, struct vfsmount *mnt,
>  		/* This is synchronous because it makes the daemon a
>                     little easier */
>  		ret = autofs4_wait(sbi, dentry, NFY_EXPIRE);
> +		trace_autofs4_do_expire_multi(mnt, dentry, ret);
>  
>  		spin_lock(&sbi->fs_lock);
>  		if (ino->flags & AUTOFS_INF_MOUNTPOINT) {
> diff --git a/fs/autofs4/root.c b/fs/autofs4/root.c
> index b96a3c5..cbb17b7 100644
> --- a/fs/autofs4/root.c
> +++ b/fs/autofs4/root.c
> @@ -19,6 +19,9 @@
>  #include <linux/time.h>
>  #include "autofs_i.h"
>  
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/autofs4.h>
> +
>  static int autofs4_dir_symlink(struct inode *,struct dentry *,const char *);
>  static int autofs4_dir_unlink(struct inode *,struct dentry *);
>  static int autofs4_dir_rmdir(struct inode *,struct dentry *);
> @@ -216,6 +219,7 @@ static void *autofs4_follow_link(struct dentry *dentry, struct nameidata *nd)
>  	    (!d_mountpoint(dentry) && __simple_empty(dentry))) {
>  		spin_unlock(&dcache_lock);
>  
> +		trace_autofs4_follow_link(nd, dentry);
>  		status = try_to_fill_dentry(dentry, 0);
Would it make sense to put the trace point after the 
try_to_fill_dentry() so the status could be recorded in the 
trace point? Similar to the trace point above?

>  		if (status)
>  			goto out_error;
> @@ -540,6 +544,8 @@ static struct dentry *autofs4_lookup(struct inode *dir, struct dentry *dentry, s
>  			dput(expiring);
>  		}
>  
> +		trace_autofs4_lookup(nd, dentry);
Same kinda idea here... would it make sense to move this
trace point some where so the status can be recorded?

The main point with these two question is I have found it 
very handy to write system tap scripts that only fire 
when there is a non-zero status.... Which means instead 
of getting pages and pages of info scrolling off the 
screen, I get one (or few) lines of error conditions that
generally have a bit more meaning... 

Just a suggestion...  

steved.

Re: [patch, rfc] autofs4: add trace points to the mount and unmount paths

[Jeff Moyer]

Steve Dickson <SteveD@redhat.com> writes:

> Hey,
>
> Comments in-line...
>
> On 06/30/2009 01:08 PM, Jeff Moyer wrote:
>> Hi, Ian,
>> 
>> I got a fairly simply request from a customer.  They wanted to use
>> systemtap to track automounter mount and unmount activity.
>> Unfortunately, the compiler inlined the expire functions I wanted to
>> instrument, so I needed to add a tracepoint to get at useful
>> information.
>> 
>> This patch, then, adds a few trace points so that we don't have to worry
>> about compiler inlining.  I have an example script using these trace
>> points that I'll be sending along to the systemtap mailing list
>> shortly.  Let me know what you think.  If you're interested in trying it
>> out, I've made my systemtap patch available at:
>>   http://people.redhat.com/jmoyer/systemtap
>> 
>> You can try running testsuite/systemtap.examples/general/autofs.stp.  It
>> should run with or without the below patch applied, though the results
>> are not as accurate (can't get full paths for unmounts) without the
>> tracepoint in autofs4_do_expire_multi.
>> 
>> Cheers,
>> Jeff
>> 
>> Signed-off-by: Jeff Moyer <jmoyer@redhat.com>
>> 
>> diff --git a/fs/autofs4/expire.c b/fs/autofs4/expire.c
>> index aa39ae8..6c86df9 100644
>> --- a/fs/autofs4/expire.c
>> +++ b/fs/autofs4/expire.c
>> @@ -13,6 +13,7 @@
>>   * ------------------------------------------------------------------------- */
>>  
>>  #include "autofs_i.h"
>> +#include <trace/events/autofs4.h>
>>  
>>  static unsigned long now;
>>  
>> @@ -496,6 +497,7 @@ int autofs4_do_expire_multi(struct super_block *sb, struct vfsmount *mnt,
>>  		/* This is synchronous because it makes the daemon a
>>                     little easier */
>>  		ret = autofs4_wait(sbi, dentry, NFY_EXPIRE);
>> +		trace_autofs4_do_expire_multi(mnt, dentry, ret);
>>  
>>  		spin_lock(&sbi->fs_lock);
>>  		if (ino->flags & AUTOFS_INF_MOUNTPOINT) {
>> diff --git a/fs/autofs4/root.c b/fs/autofs4/root.c
>> index b96a3c5..cbb17b7 100644
>> --- a/fs/autofs4/root.c
>> +++ b/fs/autofs4/root.c
>> @@ -19,6 +19,9 @@
>>  #include <linux/time.h>
>>  #include "autofs_i.h"
>>  
>> +#define CREATE_TRACE_POINTS
>> +#include <trace/events/autofs4.h>
>> +
>>  static int autofs4_dir_symlink(struct inode *,struct dentry *,const char *);
>>  static int autofs4_dir_unlink(struct inode *,struct dentry *);
>>  static int autofs4_dir_rmdir(struct inode *,struct dentry *);
>> @@ -216,6 +219,7 @@ static void *autofs4_follow_link(struct dentry *dentry, struct nameidata *nd)
>>  	    (!d_mountpoint(dentry) && __simple_empty(dentry))) {
>>  		spin_unlock(&dcache_lock);
>>  
>> +		trace_autofs4_follow_link(nd, dentry);
>>  		status = try_to_fill_dentry(dentry, 0);
> Would it make sense to put the trace point after the 
> try_to_fill_dentry() so the status could be recorded in the 
> trace point? Similar to the trace point above?
>
>>  		if (status)
>>  			goto out_error;
>> @@ -540,6 +544,8 @@ static struct dentry *autofs4_lookup(struct inode *dir, struct dentry *dentry, s
>>  			dput(expiring);
>>  		}
>>  
>> +		trace_autofs4_lookup(nd, dentry);
> Same kinda idea here... would it make sense to move this
> trace point some where so the status can be recorded?
>
> The main point with these two question is I have found it 
> very handy to write system tap scripts that only fire 
> when there is a non-zero status.... Which means instead 
> of getting pages and pages of info scrolling off the 
> screen, I get one (or few) lines of error conditions that
> generally have a bit more meaning... 
>
> Just a suggestion...  

Yeah, that's a good suggestion, thanks!  I'll respin with that changed after
I've heard from Ian.

Cheers,
Jeff

Re: [patch, rfc] autofs4: add trace points to the mount and unmount paths

[Ian Kent]

Steve Dickson wrote:
> Hey,
> 
> Comments in-line...
> 
> On 06/30/2009 01:08 PM, Jeff Moyer wrote:
>> Hi, Ian,
>>
>> I got a fairly simply request from a customer.  They wanted to use
>> systemtap to track automounter mount and unmount activity.
>> Unfortunately, the compiler inlined the expire functions I wanted to
>> instrument, so I needed to add a tracepoint to get at useful
>> information.
>>
>> This patch, then, adds a few trace points so that we don't have to worry
>> about compiler inlining.  I have an example script using these trace
>> points that I'll be sending along to the systemtap mailing list
>> shortly.  Let me know what you think.  If you're interested in trying it
>> out, I've made my systemtap patch available at:
>>   http://people.redhat.com/jmoyer/systemtap
>>
>> You can try running testsuite/systemtap.examples/general/autofs.stp.  It
>> should run with or without the below patch applied, though the results
>> are not as accurate (can't get full paths for unmounts) without the
>> tracepoint in autofs4_do_expire_multi.
>>
>> Cheers,
>> Jeff
>>
>> Signed-off-by: Jeff Moyer <jmoyer@redhat.com>
>>
>> diff --git a/fs/autofs4/expire.c b/fs/autofs4/expire.c
>> index aa39ae8..6c86df9 100644
>> --- a/fs/autofs4/expire.c
>> +++ b/fs/autofs4/expire.c
>> @@ -13,6 +13,7 @@
>>   * ------------------------------------------------------------------------- */
>>  
>>  #include "autofs_i.h"
>> +#include <trace/events/autofs4.h>
>>  
>>  static unsigned long now;
>>  
>> @@ -496,6 +497,7 @@ int autofs4_do_expire_multi(struct super_block *sb, struct vfsmount *mnt,
>>  		/* This is synchronous because it makes the daemon a
>>                     little easier */
>>  		ret = autofs4_wait(sbi, dentry, NFY_EXPIRE);
>> +		trace_autofs4_do_expire_multi(mnt, dentry, ret);

Probably should be before the wait because if it expires away we
probably won't be able to retrieve the path.

>>  
>>  		spin_lock(&sbi->fs_lock);
>>  		if (ino->flags & AUTOFS_INF_MOUNTPOINT) {
>> diff --git a/fs/autofs4/root.c b/fs/autofs4/root.c
>> index b96a3c5..cbb17b7 100644
>> --- a/fs/autofs4/root.c
>> +++ b/fs/autofs4/root.c
>> @@ -19,6 +19,9 @@
>>  #include <linux/time.h>
>>  #include "autofs_i.h"
>>  
>> +#define CREATE_TRACE_POINTS
>> +#include <trace/events/autofs4.h>
>> +
>>  static int autofs4_dir_symlink(struct inode *,struct dentry *,const char *);
>>  static int autofs4_dir_unlink(struct inode *,struct dentry *);
>>  static int autofs4_dir_rmdir(struct inode *,struct dentry *);
>> @@ -216,6 +219,7 @@ static void *autofs4_follow_link(struct dentry *dentry, struct nameidata *nd)
>>  	    (!d_mountpoint(dentry) && __simple_empty(dentry))) {
>>  		spin_unlock(&dcache_lock);
>>  
>> +		trace_autofs4_follow_link(nd, dentry);
>>  		status = try_to_fill_dentry(dentry, 0);
> Would it make sense to put the trace point after the 
> try_to_fill_dentry() so the status could be recorded in the 
> trace point? Similar to the trace point above?

I suspect that's likely not going to be the most interesting case for
us. People are likely to want to know when mounting and expiring is
happening but and know when a fail return occurrs, of course, that still
leaves the issue of being swamped with output.

> 
>>  		if (status)
>>  			goto out_error;
>> @@ -540,6 +544,8 @@ static struct dentry *autofs4_lookup(struct inode *dir, struct dentry *dentry, s
>>  			dput(expiring);
>>  		}
>>  
>> +		trace_autofs4_lookup(nd, dentry);
> Same kinda idea here... would it make sense to move this
> trace point some where so the status can be recorded?
> 
> The main point with these two question is I have found it 
> very handy to write system tap scripts that only fire 
> when there is a non-zero status.... Which means instead 
> of getting pages and pages of info scrolling off the 
> screen, I get one (or few) lines of error conditions that
> generally have a bit more meaning... 
> 
> Just a suggestion...  
> 
> steved.

Re: [patch, rfc] autofs4: add trace points to the mount and unmount paths

[Jeff Moyer]

Ian Kent <raven@themaw.net> writes:

> Steve Dickson wrote:

>> The main point with these two question is I have found it 
>> very handy to write system tap scripts that only fire 
>> when there is a non-zero status.... Which means instead 
>> of getting pages and pages of info scrolling off the 
>> screen, I get one (or few) lines of error conditions that
>> generally have a bit more meaning... 

Given Ian's point about logging entire paths, this updated patch will
still log before determining the final status of a request.  If you
want, you could cache that in systemtap until the status is received and
try to correlate the two events (which would address your request of
logging only on failures).  For the lookup routine, you need to check if
dentry is -ENOENT.  for follow_link etc, there's a status code.  The
associated systemtap patch can be found here:
  http://people.redhat.com/jmoyer/systemtap

Ian, let me know what you think.

Cheers,
Jeff

Signed-off-by: Jeff Moyer <jmoyer@redhat.com>

diff --git a/fs/autofs4/expire.c b/fs/autofs4/expire.c
index aa39ae8..6c86df9 100644
--- a/fs/autofs4/expire.c
+++ b/fs/autofs4/expire.c
@@ -13,6 +13,7 @@
  * ------------------------------------------------------------------------- */
 
 #include "autofs_i.h"
+#include <trace/events/autofs4.h>
 
 static unsigned long now;
 
@@ -496,6 +497,7 @@ int autofs4_do_expire_multi(struct super_block *sb, struct vfsmount *mnt,
 		/* This is synchronous because it makes the daemon a
                    little easier */
 		ret = autofs4_wait(sbi, dentry, NFY_EXPIRE);
+		trace_autofs4_do_expire_multi(mnt, dentry, ret);
 
 		spin_lock(&sbi->fs_lock);
 		if (ino->flags & AUTOFS_INF_MOUNTPOINT) {
diff --git a/fs/autofs4/root.c b/fs/autofs4/root.c
index b96a3c5..7cefdad 100644
--- a/fs/autofs4/root.c
+++ b/fs/autofs4/root.c
@@ -19,6 +19,9 @@
 #include <linux/time.h>
 #include "autofs_i.h"
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/autofs4.h>
+
 static int autofs4_dir_symlink(struct inode *,struct dentry *,const char *);
 static int autofs4_dir_unlink(struct inode *,struct dentry *);
 static int autofs4_dir_rmdir(struct inode *,struct dentry *);
@@ -216,6 +219,7 @@ static void *autofs4_follow_link(struct dentry *dentry, struct nameidata *nd)
 	    (!d_mountpoint(dentry) && __simple_empty(dentry))) {
 		spin_unlock(&dcache_lock);
 
+		trace_autofs4_follow_link(nd, dentry);
 		status = try_to_fill_dentry(dentry, 0);
 		if (status)
 			goto out_error;
@@ -237,9 +241,11 @@ follow:
 	}
 
 done:
+	trace_autofs4_follow_link_status(dentry, 0);
 	return NULL;
 
 out_error:
+	trace_autofs4_follow_link_status(dentry, status);
 	path_put(&nd->path);
 	return ERR_PTR(status);
 }
@@ -540,6 +546,8 @@ static struct dentry *autofs4_lookup(struct inode *dir, struct dentry *dentry, s
 			dput(expiring);
 		}
 
+		trace_autofs4_lookup(nd, dentry);
+
 		spin_lock(&dentry->d_lock);
 		dentry->d_flags |= DCACHE_AUTOFS_PENDING;
 		spin_unlock(&dentry->d_lock);
@@ -595,12 +603,16 @@ static struct dentry *autofs4_lookup(struct inode *dir, struct dentry *dentry, s
 		if (unhashed)
 			dput(unhashed);
 
+		trace_autofs4_lookup_status(dentry);
 		return dentry;
 	}
 
-	if (unhashed)
+	if (unhashed) {
+		trace_autofs4_lookup_status(unhashed);
 		return unhashed;
+	}
 
+	trace_autofs4_lookup_status(NULL);
 	return NULL;
 }
 
diff --git a/include/trace/events/autofs4.h b/include/trace/events/autofs4.h
index 39f04c9..6feae79 100644
--- a/include/trace/events/autofs4.h
+++ b/include/trace/events/autofs4.h
@@ -1,26 +1,115 @@
 #if !defined(_TRACE_AUTOFS4_H) || defined(TRACE_HEADER_MULTI_READ)
 #define _TRACE_AUTOFS4_H
 
+#include <linux/dcache.h>
+#include <linux/mount.h>
+#include <linux/limits.h>
 #include <linux/tracepoint.h>
 
 #undef TRACE_SYSTEM
 #define TRACE_SYSTEM autofs4
 
 TRACE_EVENT(autofs4_do_expire_multi,
-	    TP_PROTO(struct vfsmount *mnt, struct dentry *dentry),
-	    TP_ARGS(mnt, dentry),
+	    TP_PROTO(struct vfsmount *mnt, struct dentry *dentry, int status),
+	    TP_ARGS(mnt, dentry, status),
 	    TP_STRUCT__entry(
 		    __array(char, comm, TASK_COMM_LEN)
 		    __field(pid_t, pid)
+		    __array(char, path, MAX_FILTER_STR_VAL)
+		    __field(int, status)
 	    ),
 	    TP_fast_assign(
 		    __entry->pid = current->pid;
 		    memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
+		    snprintf(__entry->path,
+			     dentry->d_name.len < MAX_FILTER_STR_VAL ?
+			     dentry->d_name.len : MAX_FILTER_STR_VAL,
+			     "%s", dentry->d_name.name);
+		    __entry->status = status;
 	    ),
-	    TP_printk("%s[%d]: expiring %.*s", __entry->comm, __entry->pid,
-		      dentry->d_name.len, dentry->d_name.name);
+	    TP_printk("%s[%d]: expiry of %s %s",
+		      __entry->comm, __entry->pid, __entry->path,
+		      __entry->status == 0 ? "succeeded" : "failed")
 );
 
 TRACE_EVENT(autofs4_lookup,
-	    TP_PROTO(
+	    TP_PROTO(struct nameidata *nd, struct dentry *dentry),
+	    TP_ARGS(nd, dentry),
+	    TP_STRUCT__entry(
+		    __array(char, comm, TASK_COMM_LEN)
+		    __array(char, path, MAX_FILTER_STR_VAL)
+		    __field(char *, pathptr)
+		    __field(pid_t, pid)
+	    ),
+	    TP_fast_assign(
+		    __entry->pid = current->pid;
+		    memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
+		    __entry->pathptr = d_path(&nd->path,
+					     __entry->path, MAX_FILTER_STR_VAL);
+	    ),
+	    TP_printk("%s[%d]: looking up %s",
+		      __entry->comm, __entry->pid, __entry->pathptr)
+);
+
+TRACE_EVENT(autofs4_lookup_status,
+	    TP_PROTO(struct dentry *dentry),
+	    TP_ARGS(dentry),
+	    TP_STRUCT__entry(
+		    __array(char, comm, TASK_COMM_LEN)
+		    __field(void *, dentry)
+		    __field(pid_t, pid)
+	    ),
+	    TP_fast_assign(
+		    __entry->dentry = dentry;
+		    memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
+		    __entry->pid = current->pid;
+	    ),
+	    TP_printk("%s[%d]: lookup %s",
+		      __entry->comm, __entry->pid,
+		      __entry->dentry ? "succeeded" : "failed")
+);
+
+TRACE_EVENT(autofs4_follow_link,
+	    TP_PROTO(struct nameidata *nd, struct dentry *dentry),
+	    TP_ARGS(nd, dentry),
+	    TP_STRUCT__entry(
+		    __array(char, comm, TASK_COMM_LEN)
+		    __array(char, path, MAX_FILTER_STR_VAL)
+		    __field(char *, pathptr)
+		    __field(pid_t, pid)
+	    ),
+	    TP_fast_assign(
+		    __entry->pid = current->pid;
+		    memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
+		    __entry->pathptr = d_path(&nd->path,
+					     __entry->path, MAX_FILTER_STR_VAL);
+	    ),
+	    TP_printk("%s[%d]: looking up trigger %s",
+		      __entry->comm, __entry->pid, __entry->pathptr)
+);
+
+TRACE_EVENT(autofs4_follow_link_status,
+	    TP_PROTO(struct dentry *dentry, int status),
+	    TP_ARGS(dentry, status),
+	    TP_STRUCT__entry(
+		    __array(char, comm, TASK_COMM_LEN)
+		    __array(char, linkname, MAX_FILTER_STR_VAL)
+		    __field(int, status)
+		    __field(pid_t, pid)
+	    ),
+	    TP_fast_assign(
+		    __entry->status = status;
+		    snprintf(__entry->linkname, dentry->d_name.len, "%s",
+			     dentry->d_name.name);
+		    memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
+		    __entry->pid = current->pid;
+	    ),
+	    TP_printk("%s[%d]: lookup for trigger %s %s",
+		      __entry->comm, __entry->pid, __entry->linkname,
+		      __entry->status == 0 ? "succeeded" : "failed")
+);
+
 #endif /* _TRACE_AUTOFS4_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>

Re: [patch, rfc] autofs4: add trace points to the mount and unmount paths

[Ian Kent]

Jeff Moyer wrote:
> Ian Kent <raven@themaw.net> writes:
> 
>> Steve Dickson wrote:
> 
>>> The main point with these two question is I have found it 
>>> very handy to write system tap scripts that only fire 
>>> when there is a non-zero status.... Which means instead 
>>> of getting pages and pages of info scrolling off the 
>>> screen, I get one (or few) lines of error conditions that
>>> generally have a bit more meaning... 
> 
> Given Ian's point about logging entire paths, this updated patch will
> still log before determining the final status of a request.  If you
> want, you could cache that in systemtap until the status is received and
> try to correlate the two events (which would address your request of
> logging only on failures).  For the lookup routine, you need to check if
> dentry is -ENOENT.  for follow_link etc, there's a status code.  The
> associated systemtap patch can be found here:
>   http://people.redhat.com/jmoyer/systemtap

One thing to be wary of is the status return in "autofs4_lookup_status".
With the new ioctl implementation we are now able to pass the actual
status return back to kernel space (although the daemon hasn't been
updated to take advantage of this yet).

So this (please excuse the line wrap):

+probe kernel.trace("autofs4_lookup_status")
+{
+	if (!isinstr(execname(), "automount")) {
+		printf("%s process %s[%d] lookup %s\n",
+		       ctime(gettimeofday_s()), execname(), pid(),
+		       $dentry == -2 /* ENOENT */ ? "failed" : "succeeded")
+	}
+}
+

should probably be something like (or however we use IS_ERR() in these
scripts):

+probe kernel.trace("autofs4_lookup_status")
+{
+	if (!isinstr(execname(), "automount")) {
+		printf("%s process %s[%d] lookup %s\n",
+		       ctime(gettimeofday_s()), execname(), pid(),
+		       IS_ERR($dentry) ? "failed" : "succeeded")
+	}
+}
+

> 
> Ian, let me know what you think.
> 
> Cheers,
> Jeff
> 
> Signed-off-by: Jeff Moyer <jmoyer@redhat.com>
> 
> diff --git a/fs/autofs4/expire.c b/fs/autofs4/expire.c
> index aa39ae8..6c86df9 100644
> --- a/fs/autofs4/expire.c
> +++ b/fs/autofs4/expire.c
> @@ -13,6 +13,7 @@
>   * ------------------------------------------------------------------------- */
>  
>  #include "autofs_i.h"
> +#include <trace/events/autofs4.h>
>  
>  static unsigned long now;
>  
> @@ -496,6 +497,7 @@ int autofs4_do_expire_multi(struct super_block *sb, struct vfsmount *mnt,
>  		/* This is synchronous because it makes the daemon a
>                     little easier */
>  		ret = autofs4_wait(sbi, dentry, NFY_EXPIRE);
> +		trace_autofs4_do_expire_multi(mnt, dentry, ret);

Is this what we want?
I'm not sure what we are trying to do here but I thought the trace
should occur before the expire. If we wanted to get a path after the
expire that probably can't be done as the mount should have been
detached from the tree once the expire is complete.

>  
>  		spin_lock(&sbi->fs_lock);
>  		if (ino->flags & AUTOFS_INF_MOUNTPOINT) {
> diff --git a/fs/autofs4/root.c b/fs/autofs4/root.c
> index b96a3c5..7cefdad 100644
> --- a/fs/autofs4/root.c
> +++ b/fs/autofs4/root.c
> @@ -19,6 +19,9 @@
>  #include <linux/time.h>
>  #include "autofs_i.h"
>  
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/autofs4.h>
> +
>  static int autofs4_dir_symlink(struct inode *,struct dentry *,const char *);
>  static int autofs4_dir_unlink(struct inode *,struct dentry *);
>  static int autofs4_dir_rmdir(struct inode *,struct dentry *);
> @@ -216,6 +219,7 @@ static void *autofs4_follow_link(struct dentry *dentry, struct nameidata *nd)
>  	    (!d_mountpoint(dentry) && __simple_empty(dentry))) {
>  		spin_unlock(&dcache_lock);
>  
> +		trace_autofs4_follow_link(nd, dentry);
>  		status = try_to_fill_dentry(dentry, 0);
>  		if (status)
>  			goto out_error;
> @@ -237,9 +241,11 @@ follow:
>  	}
>  
>  done:
> +	trace_autofs4_follow_link_status(dentry, 0);
>  	return NULL;
>  
>  out_error:
> +	trace_autofs4_follow_link_status(dentry, status);
>  	path_put(&nd->path);
>  	return ERR_PTR(status);
>  }
> @@ -540,6 +546,8 @@ static struct dentry *autofs4_lookup(struct inode *dir, struct dentry *dentry, s
>  			dput(expiring);
>  		}
>  
> +		trace_autofs4_lookup(nd, dentry);
> +
>  		spin_lock(&dentry->d_lock);
>  		dentry->d_flags |= DCACHE_AUTOFS_PENDING;
>  		spin_unlock(&dentry->d_lock);
> @@ -595,12 +603,16 @@ static struct dentry *autofs4_lookup(struct inode *dir, struct dentry *dentry, s
>  		if (unhashed)
>  			dput(unhashed);
>  
> +		trace_autofs4_lookup_status(dentry);
>  		return dentry;
>  	}
>  
> -	if (unhashed)
> +	if (unhashed) {
> +		trace_autofs4_lookup_status(unhashed);
>  		return unhashed;
> +	}
>  
> +	trace_autofs4_lookup_status(NULL);
>  	return NULL;
>  }
>  
> diff --git a/include/trace/events/autofs4.h b/include/trace/events/autofs4.h
> index 39f04c9..6feae79 100644
> --- a/include/trace/events/autofs4.h
> +++ b/include/trace/events/autofs4.h
> @@ -1,26 +1,115 @@
>  #if !defined(_TRACE_AUTOFS4_H) || defined(TRACE_HEADER_MULTI_READ)
>  #define _TRACE_AUTOFS4_H
>  
> +#include <linux/dcache.h>
> +#include <linux/mount.h>
> +#include <linux/limits.h>
>  #include <linux/tracepoint.h>
>  
>  #undef TRACE_SYSTEM
>  #define TRACE_SYSTEM autofs4
>  
>  TRACE_EVENT(autofs4_do_expire_multi,
> -	    TP_PROTO(struct vfsmount *mnt, struct dentry *dentry),
> -	    TP_ARGS(mnt, dentry),
> +	    TP_PROTO(struct vfsmount *mnt, struct dentry *dentry, int status),
> +	    TP_ARGS(mnt, dentry, status),
>  	    TP_STRUCT__entry(
>  		    __array(char, comm, TASK_COMM_LEN)
>  		    __field(pid_t, pid)
> +		    __array(char, path, MAX_FILTER_STR_VAL)
> +		    __field(int, status)
>  	    ),
>  	    TP_fast_assign(
>  		    __entry->pid = current->pid;
>  		    memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
> +		    snprintf(__entry->path,
> +			     dentry->d_name.len < MAX_FILTER_STR_VAL ?
> +			     dentry->d_name.len : MAX_FILTER_STR_VAL,
> +			     "%s", dentry->d_name.name);
> +		    __entry->status = status;
>  	    ),
> -	    TP_printk("%s[%d]: expiring %.*s", __entry->comm, __entry->pid,
> -		      dentry->d_name.len, dentry->d_name.name);
> +	    TP_printk("%s[%d]: expiry of %s %s",
> +		      __entry->comm, __entry->pid, __entry->path,
> +		      __entry->status == 0 ? "succeeded" : "failed")
>  );
>  
>  TRACE_EVENT(autofs4_lookup,
> -	    TP_PROTO(
> +	    TP_PROTO(struct nameidata *nd, struct dentry *dentry),
> +	    TP_ARGS(nd, dentry),
> +	    TP_STRUCT__entry(
> +		    __array(char, comm, TASK_COMM_LEN)
> +		    __array(char, path, MAX_FILTER_STR_VAL)
> +		    __field(char *, pathptr)
> +		    __field(pid_t, pid)
> +	    ),
> +	    TP_fast_assign(
> +		    __entry->pid = current->pid;
> +		    memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
> +		    __entry->pathptr = d_path(&nd->path,
> +					     __entry->path, MAX_FILTER_STR_VAL);
> +	    ),
> +	    TP_printk("%s[%d]: looking up %s",
> +		      __entry->comm, __entry->pid, __entry->pathptr)
> +);
> +
> +TRACE_EVENT(autofs4_lookup_status,
> +	    TP_PROTO(struct dentry *dentry),
> +	    TP_ARGS(dentry),
> +	    TP_STRUCT__entry(
> +		    __array(char, comm, TASK_COMM_LEN)
> +		    __field(void *, dentry)
> +		    __field(pid_t, pid)
> +	    ),
> +	    TP_fast_assign(
> +		    __entry->dentry = dentry;
> +		    memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
> +		    __entry->pid = current->pid;
> +	    ),
> +	    TP_printk("%s[%d]: lookup %s",
> +		      __entry->comm, __entry->pid,
> +		      __entry->dentry ? "succeeded" : "failed")
> +);
> +
> +TRACE_EVENT(autofs4_follow_link,
> +	    TP_PROTO(struct nameidata *nd, struct dentry *dentry),
> +	    TP_ARGS(nd, dentry),
> +	    TP_STRUCT__entry(
> +		    __array(char, comm, TASK_COMM_LEN)
> +		    __array(char, path, MAX_FILTER_STR_VAL)
> +		    __field(char *, pathptr)
> +		    __field(pid_t, pid)
> +	    ),
> +	    TP_fast_assign(
> +		    __entry->pid = current->pid;
> +		    memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
> +		    __entry->pathptr = d_path(&nd->path,
> +					     __entry->path, MAX_FILTER_STR_VAL);
> +	    ),
> +	    TP_printk("%s[%d]: looking up trigger %s",
> +		      __entry->comm, __entry->pid, __entry->pathptr)
> +);
> +
> +TRACE_EVENT(autofs4_follow_link_status,
> +	    TP_PROTO(struct dentry *dentry, int status),
> +	    TP_ARGS(dentry, status),
> +	    TP_STRUCT__entry(
> +		    __array(char, comm, TASK_COMM_LEN)
> +		    __array(char, linkname, MAX_FILTER_STR_VAL)
> +		    __field(int, status)
> +		    __field(pid_t, pid)
> +	    ),
> +	    TP_fast_assign(
> +		    __entry->status = status;
> +		    snprintf(__entry->linkname, dentry->d_name.len, "%s",
> +			     dentry->d_name.name);
> +		    memcpy(__entry->comm, current->comm, TASK_COMM_LEN);
> +		    __entry->pid = current->pid;
> +	    ),
> +	    TP_printk("%s[%d]: lookup for trigger %s %s",
> +		      __entry->comm, __entry->pid, __entry->linkname,
> +		      __entry->status == 0 ? "succeeded" : "failed")
> +);
> +
>  #endif /* _TRACE_AUTOFS4_H */
> +
> +/* This part must be outside protection */
> +#include <trace/define_trace.h>