diff mbox

[V9fs-developer] net/9p: Convert net/9p protocol dumps to tracepoints

Message ID 87r54u92ok.fsf@skywalker.in.ibm.com (mailing list archive)
State Superseded, archived
Delegated to: Eric Van Hensbergen
Headers show

Commit Message

Aneesh Kumar K.V Aug. 9, 2011, 12:42 p.m. UTC 
On Tue, 9 Aug 2011 14:58:55 +0300, Pekka Enberg <penberg@kernel.org> wrote:
> On Tue, Aug 9, 2011 at 2:52 PM, Aneesh Kumar K.V
> <aneesh.kumar@linux.vnet.ibm.com> wrote:
> > This helps in more control over debugging.
> >
> > root@qemu-img-64:~# ls -al /pass/1234
> > ls: cannot access /pass/1234: No such file or directory
> > root@qemu-img-64:~# cat /sys/kernel/debug/tracing/trace
> > # tracer: nop
> > #
> > #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
> > #              | |       |          |         |
> >              ls-1585  [001]   152.525239: 9p_protocol_dump: clnt 18446612132802834432 P9_TWALK(tag = 1)
> > 00000000: 17 00 00 00 6e 01 00 01 00 00
> > 00000020: 00 04 00 31 32 33 34 00 00 ff
> >
> >              ls-1585  [001]   152.525244: <stack trace>
> >  => trace_9p_protocol_dump
> >  => p9pdu_finalize
> >  => p9_client_rpc
> >  => p9_client_walk
> >  => v9fs_vfs_lookup
> >  => d_alloc_and_lookup
> >  => walk_component
> >  => path_lookupat
> >              ls-1585  [000]   152.526272: 9p_protocol_dump: clnt 18446612132802834432 P9_RLERROR(tag = 1)
> > 00000000: 0b 00 00 00 07 01 00 02 00 00
> > 00000020: 00 00 00 00 03 00 02 00 00 00
> >
> >              ls-1585  [000]   152.526275: <stack trace>
> >  => trace_9p_protocol_dump
> >  => p9_client_rpc
> >  => p9_client_walk
> >  => v9fs_vfs_lookup
> >  => d_alloc_and_lookup
> >  => walk_component
> >  => path_lookupat
> >  => do_path_lookup
> >
> >
> > Signed-off-by: Aneesh Kumar K.V <aneesh.kumar@linux.vnet.ibm.com>
> 
> Wow, cool!
> 
> Acked-by: Pekka Enberg <penberg@kernel.org>
> 
> I'm CC'ing Ingo and Steven in case they want to review how you used
> tracepoints here.
> 

I did a version 2 . attaching below.

commit 159b1640350af72cdea3043feaf17f089f38d407
Author: Aneesh Kumar K.V <aneesh.kumar@linux.vnet.ibm.com>
Date:   Sun Aug 7 00:46:59 2011 +0530

    net/9p: Convert net/9p protocol dumps to tracepoints
    
    This helps in more control over debugging.
    
    root@qemu-img-64:~# mount -t 9p -oversion=9p2000.L,trans=virtio,cache=loose v_tmp  /pass/
    root@qemu-img-64:~# cat /sys/kernel/debug/tracing/trace_pipe
               mount-1549  [000]   111.746149: 9p_protocol_dump: clnt 18446612132812210176 P9_TVERSION(tag = 65535)
    00000000: 15 00 00 00 64 ff ff 00 20 00 00 08 00 39 50 32  ....d... ....9P2
    00000010: 30 30 30 2e 4c 00 00 00 d9 82 a9 1d 00 88 ff ff  000.L...........
    
               mount-1549  [000]   111.746154: <stack trace>
     => trace_9p_protocol_dump
     => p9pdu_finalize
     => p9_client_rpc
     => p9_client_create
     => v9fs_session_init
     => v9fs_mount
     => mount_fs
     => vfs_kern_mount
               mount-1549  [000]   111.746318: 9p_protocol_dump: clnt 18446612132812210176 P9_RVERSION(tag = 65535)
    00000000: 15 00 00 00 65 ff ff 00 20 00 00 08 00 39 50 32  ....e... ....9P2
    00000010: 30 30 30 2e 4c 00 02 00 00 00 00 00 ff 43 00 00  000.L........C..
    
               mount-1549  [000]   111.746320: <stack trace>
     => trace_9p_protocol_dump
     => p9_client_rpc
     => p9_client_create
     => v9fs_session_init
     => v9fs_mount
     => mount_fs
     => vfs_kern_mount
     => do_kern_mount
               mount-1549  [000]   111.746368: 9p_protocol_dump: clnt 18446612132812210176 P9_TATTACH(tag = 1)
    00000000: 1d 00 00 00 68 01 00 00 00 00 00 ff ff ff ff 06  ....h...........
    00000010: 00 6e 6f 62 6f 64 79 00 00 ff ff ff ff ff ff ff  .nobody.........
    
    Signed-off-by: Aneesh Kumar K.V <aneesh.kumar@linux.vnet.ibm.com>



------------------------------------------------------------------------------
uberSVN's rich system and user administration capabilities and model 
configuration take the hassle out of deploying and managing Subversion and 
the tools developers use with it. Learn more about uberSVN and get a free 
download at:  http://p.sf.net/sfu/wandisco-dev2dev

Comments

Steven Rostedt Aug. 9, 2011, 12:53 p.m. UTC | #1 
On Tue, 2011-08-09 at 18:12 +0530, Aneesh Kumar K.V wrote:

> +#define P9_PROTO_DUMP_SZ (16 * 3 + 2 + 16 + 1)

Wow, you're making your event have 67 byte arrays, two of them.

> +TRACE_EVENT(9p_protocol_dump,
> +	    TP_PROTO(struct p9_client *clnt, struct p9_fcall *pdu),
> +
> +	    TP_ARGS(clnt, pdu),
> +
> +	    TP_STRUCT__entry(
> +		    __field(	__u64,		clnt				)
> +		    __field(	__u8,		type				)
> +		    __field(	__u16,		tag				)
> +		    __array(	unsigned char,	line1,	P9_PROTO_DUMP_SZ	)
> +		    __array(	unsigned char,	line2,	P9_PROTO_DUMP_SZ	)
> +		    ),

Wouldn't it be better to put this as two unsigned char arrays of 16
bytes?

> +
> +	    TP_fast_assign(
> +		    const u8 *ptr   =  pdu->sdata;
> +		    __entry->clnt   =  (__u64)clnt;
> +		    __entry->type   =  pdu->id;
> +		    __entry->tag    =  pdu->tag;
> +		    hex_dump_to_buffer(ptr, 16, 16,
> +				       1, __entry->line1, P9_PROTO_DUMP_SZ, true);
> +		    hex_dump_to_buffer(ptr + 16, 16, 16,
> +				       1, __entry->line2, P9_PROTO_DUMP_SZ, true);
> +		    ),
> +
> +	    TP_printk("clnt %lu %s(tag = %d)\n%.8x: %s\n%.8x: %s\n",
> +		      (long)__entry->clnt, show_9p_op(__entry->type),
> +		      __entry->tag, 0, __entry->line1, 16 , __entry->line2)

Yeah, you would need to make the above ugly to print out the array, but
it's not that hard. And you will be saving 102 bytes per event in the
ring buffer, which is very expensive real-estate. Not to mention the
time it takes to copy all that.

-- Steve



------------------------------------------------------------------------------
uberSVN's rich system and user administration capabilities and model 
configuration take the hassle out of deploying and managing Subversion and 
the tools developers use with it. Learn more about uberSVN and get a free 
download at:  http://p.sf.net/sfu/wandisco-dev2dev
Aneesh Kumar K.V Aug. 9, 2011, 2:28 p.m. UTC | #2 
On Tue, 09 Aug 2011 08:53:15 -0400, Steven Rostedt <srostedt@redhat.com> wrote:
> On Tue, 2011-08-09 at 18:12 +0530, Aneesh Kumar K.V wrote:
> 
> > +#define P9_PROTO_DUMP_SZ (16 * 3 + 2 + 16 + 1)
> 
> Wow, you're making your event have 67 byte arrays, two of them.
> 
> > +TRACE_EVENT(9p_protocol_dump,
> > +	    TP_PROTO(struct p9_client *clnt, struct p9_fcall *pdu),
> > +
> > +	    TP_ARGS(clnt, pdu),
> > +
> > +	    TP_STRUCT__entry(
> > +		    __field(	__u64,		clnt				)
> > +		    __field(	__u8,		type				)
> > +		    __field(	__u16,		tag				)
> > +		    __array(	unsigned char,	line1,	P9_PROTO_DUMP_SZ	)
> > +		    __array(	unsigned char,	line2,	P9_PROTO_DUMP_SZ	)
> > +		    ),
> 
> Wouldn't it be better to put this as two unsigned char arrays of 16
> bytes?
> 
> > +
> > +	    TP_fast_assign(
> > +		    const u8 *ptr   =  pdu->sdata;
> > +		    __entry->clnt   =  (__u64)clnt;
> > +		    __entry->type   =  pdu->id;
> > +		    __entry->tag    =  pdu->tag;
> > +		    hex_dump_to_buffer(ptr, 16, 16,
> > +				       1, __entry->line1, P9_PROTO_DUMP_SZ, true);
> > +		    hex_dump_to_buffer(ptr + 16, 16, 16,
> > +				       1, __entry->line2, P9_PROTO_DUMP_SZ, true);
> > +		    ),
> > +
> > +	    TP_printk("clnt %lu %s(tag = %d)\n%.8x: %s\n%.8x: %s\n",
> > +		      (long)__entry->clnt, show_9p_op(__entry->type),
> > +		      __entry->tag, 0, __entry->line1, 16 , __entry->line2)
> 
> Yeah, you would need to make the above ugly to print out the array, but
> it's not that hard. And you will be saving 102 bytes per event in the
> ring buffer, which is very expensive real-estate. Not to mention the
> time it takes to copy all that.
> 

Any suggestion on how to get this pretty printing of the hex data. I can
update print_hex_dump_bytes to dump the hex data to a buffer. But not
sure where i can free the buffer after using that in TP_printk. 

-aneesh

------------------------------------------------------------------------------
uberSVN's rich system and user administration capabilities and model 
configuration take the hassle out of deploying and managing Subversion and 
the tools developers use with it. Learn more about uberSVN and get a free 
download at:  http://p.sf.net/sfu/wandisco-dev2dev
Steven Rostedt Aug. 9, 2011, 2:39 p.m. UTC | #3 
On Tue, 2011-08-09 at 19:58 +0530, Aneesh Kumar K.V wrote:
> On Tue, 09 Aug 2011 08:53:15 -0400, Steven Rostedt <srostedt@redhat.com> wrote:

> > > +	    TP_printk("clnt %lu %s(tag = %d)\n%.8x: %s\n%.8x: %s\n",
> > > +		      (long)__entry->clnt, show_9p_op(__entry->type),
> > > +		      __entry->tag, 0, __entry->line1, 16 , __entry->line2)
> > 
> > Yeah, you would need to make the above ugly to print out the array, but
> > it's not that hard. And you will be saving 102 bytes per event in the
> > ring buffer, which is very expensive real-estate. Not to mention the
> > time it takes to copy all that.
> > 
> 
> Any suggestion on how to get this pretty printing of the hex data. I can
> update print_hex_dump_bytes to dump the hex data to a buffer. But not
> sure where i can free the buffer after using that in TP_printk. 

By making it very ugly :)

	TP_printk("clnt %lu %s(tag = %d)\n%.8x: "
		"%02x %02x %02x %02x %02x %02x %02x %02x %02x "
		"%02x %02x %02x %02x %02x %02x %02x %02x %02x\n"
		"%.8x: "
		"%02x %02x %02x %02x %02x %02x %02x %02x %02x "
		"%02x %02x %02x %02x %02x %02x %02x %02x %02x\n",
		(long)__entry->clnt, show_9p_op(__entry->type),
		__entry->tag, 0,
		__entry->line1[0], __entry->line1[1],
		__entry->line1[2], __entry->line1[3],
		__entry->line1[4], __entry->line1[5],
		__entry->line1[6], __entry->line1[7],
		__entry->line1[8], __entry->line1[9],
		__entry->line1[10], __entry->line1[11],
		__entry->line1[12], __entry->line1[13],
		__entry->line1[14], __entry->line1[15],
		16,
		__entry->line2[0], __entry->line2[1],
		__entry->line2[2], __entry->line2[3],
		__entry->line2[4], __entry->line2[5],
		__entry->line2[6], __entry->line2[7],
		__entry->line2[8], __entry->line2[9],
		__entry->line2[10], __entry->line2[11],
		__entry->line2[12], __entry->line2[13],
		__entry->line2[14], __entry->line2[15])


Like I said, it's not pretty, but it saves buffer space and moves the
slow copy out of the fast path.

-- Steve




------------------------------------------------------------------------------
uberSVN's rich system and user administration capabilities and model 
configuration take the hassle out of deploying and managing Subversion and 
the tools developers use with it. Learn more about uberSVN and get a free 
download at:  http://p.sf.net/sfu/wandisco-dev2dev
diff mbox

Patch

diff --git a/fs/9p/vfs_dir.c b/fs/9p/vfs_dir.c
index ce6600f..598fff1 100644
--- a/fs/9p/vfs_dir.c
+++ b/fs/9p/vfs_dir.c
@@ -165,9 +165,8 @@  static int v9fs_dir_readdir(struct file *filp, void *dirent, filldir_t filldir)
 		}
 		while (rdir->head < rdir->tail) {
 			p9stat_init(&st);
-			err = p9stat_read(rdir->buf + rdir->head,
-						rdir->tail - rdir->head, &st,
-						fid->clnt->proto_version);
+			err = p9stat_read(fid->clnt, rdir->buf + rdir->head,
+					  rdir->tail - rdir->head, &st);
 			if (err) {
 				P9_DPRINTK(P9_DEBUG_VFS, "returned %d\n", err);
 				err = -EIO;
@@ -241,10 +240,9 @@  static int v9fs_dir_readdir_dotl(struct file *filp, void *dirent,
 
 		while (rdir->head < rdir->tail) {
 
-			err = p9dirent_read(rdir->buf + rdir->head,
-						rdir->tail - rdir->head,
-						&curdirent,
-						fid->clnt->proto_version);
+			err = p9dirent_read(fid->clnt, rdir->buf + rdir->head,
+					    rdir->tail - rdir->head,
+					    &curdirent);
 			if (err < 0) {
 				P9_DPRINTK(P9_DEBUG_VFS, "returned %d\n", err);
 				err = -EIO;
diff --git a/include/net/9p/9p.h b/include/net/9p/9p.h
index 2063a34..289b0ec 100644
--- a/include/net/9p/9p.h
+++ b/include/net/9p/9p.h
@@ -76,11 +76,8 @@  do {  \
 	} \
 } while (0)
 
-#define P9_DUMP_PKT(way, pdu) p9pdu_dump(way, pdu)
-
 #else
 #define P9_DPRINTK(level, format, arg...)  do { } while (0)
-#define P9_DUMP_PKT(way, pdu) do { } while (0)
 #endif
 
 
diff --git a/include/net/9p/client.h b/include/net/9p/client.h
index 55ce72c..5d07e53 100644
--- a/include/net/9p/client.h
+++ b/include/net/9p/client.h
@@ -240,8 +240,8 @@  int p9_client_read(struct p9_fid *fid, char *data, char __user *udata,
 int p9_client_write(struct p9_fid *fid, char *data, const char __user *udata,
 							u64 offset, u32 count);
 int p9_client_readdir(struct p9_fid *fid, char *data, u32 count, u64 offset);
-int p9dirent_read(char *buf, int len, struct p9_dirent *dirent,
-							int proto_version);
+int p9dirent_read(struct p9_client *clnt, char *buf, int len,
+		  struct p9_dirent *dirent);
 struct p9_wstat *p9_client_stat(struct p9_fid *fid);
 int p9_client_wstat(struct p9_fid *fid, struct p9_wstat *wst);
 int p9_client_setattr(struct p9_fid *fid, struct p9_iattr_dotl *attr);
@@ -259,7 +259,7 @@  struct p9_req_t *p9_tag_lookup(struct p9_client *, u16);
 void p9_client_cb(struct p9_client *c, struct p9_req_t *req);
 
 int p9_parse_header(struct p9_fcall *, int32_t *, int8_t *, int16_t *, int);
-int p9stat_read(char *, int, struct p9_wstat *, int);
+int p9stat_read(struct p9_client *, char *, int, struct p9_wstat *);
 void p9stat_free(struct p9_wstat *);
 
 int p9_is_proto_dotu(struct p9_client *clnt);
diff --git a/include/trace/events/9p.h b/include/trace/events/9p.h
new file mode 100644
index 0000000..380e561
--- /dev/null
+++ b/include/trace/events/9p.h
@@ -0,0 +1,169 @@ 
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM 9p
+
+#if !defined(_TRACE_9P_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_9P_H
+
+#include <linux/tracepoint.h>
+
+#define show_9p_op(type)						\
+	__print_symbolic(type,						\
+			 { P9_TLERROR,		"P9_TLERROR" },		\
+			 { P9_RLERROR,		"P9_RLERROR" },		\
+			 { P9_TSTATFS,		"P9_TSTATFS" },		\
+			 { P9_RSTATFS,		"P9_RSTATFS" },		\
+			 { P9_TLOPEN,		"P9_TLOPEN" },		\
+			 { P9_RLOPEN,		"P9_RLOPEN" },		\
+			 { P9_TLCREATE,		"P9_TLCREATE" },	\
+			 { P9_RLCREATE,		"P9_RLCREATE" },	\
+			 { P9_TSYMLINK,		"P9_TSYMLINK" },	\
+			 { P9_RSYMLINK,		"P9_RSYMLINK" },	\
+			 { P9_TMKNOD,		"P9_TMKNOD" },		\
+			 { P9_RMKNOD,		"P9_RMKNOD" },		\
+			 { P9_TRENAME,		"P9_TRENAME" },		\
+			 { P9_RRENAME,		"P9_RRENAME" },		\
+			 { P9_TREADLINK,	"P9_TREADLINK" },	\
+			 { P9_RREADLINK,	"P9_RREADLINK" },	\
+			 { P9_TGETATTR,		"P9_TGETATTR" },	\
+			 { P9_RGETATTR,		"P9_RGETATTR" },	\
+			 { P9_TSETATTR,		"P9_TSETATTR" },	\
+			 { P9_RSETATTR,		"P9_RSETATTR" },	\
+			 { P9_TXATTRWALK,	"P9_TXATTRWALK" },	\
+			 { P9_RXATTRWALK,	"P9_RXATTRWALK" },	\
+			 { P9_TXATTRCREATE,	"P9_TXATTRCREATE" },	\
+			 { P9_RXATTRCREATE,	"P9_RXATTRCREATE" },	\
+			 { P9_TREADDIR,		"P9_TREADDIR" },	\
+			 { P9_RREADDIR,		"P9_RREADDIR" },	\
+			 { P9_TFSYNC,		"P9_TFSYNC" },		\
+			 { P9_RFSYNC,		"P9_RFSYNC" },		\
+			 { P9_TLOCK,		"P9_TLOCK" },		\
+			 { P9_RLOCK,		"P9_RLOCK" },		\
+			 { P9_TGETLOCK,		"P9_TGETLOCK" },	\
+			 { P9_RGETLOCK,		"P9_RGETLOCK" },	\
+			 { P9_TLINK,		"P9_TLINK" },		\
+			 { P9_RLINK,		"P9_RLINK" },		\
+			 { P9_TMKDIR,		"P9_TMKDIR" },		\
+			 { P9_RMKDIR,		"P9_RMKDIR" },		\
+			 { P9_TRENAMEAT,	"P9_TRENAMEAT" },	\
+			 { P9_RRENAMEAT,	"P9_RRENAMEAT" },	\
+			 { P9_TUNLINKAT,	"P9_TUNLINKAT" },	\
+			 { P9_RUNLINKAT,	"P9_RUNLINKAT" },	\
+			 { P9_TVERSION,		"P9_TVERSION" },	\
+			 { P9_RVERSION,		"P9_RVERSION" },	\
+			 { P9_TAUTH,		"P9_TAUTH" },		\
+			 { P9_RAUTH,		"P9_RAUTH" },		\
+			 { P9_TATTACH,		"P9_TATTACH" },		\
+			 { P9_RATTACH,		"P9_RATTACH" },		\
+			 { P9_TERROR,		"P9_TERROR" },		\
+			 { P9_RERROR,		"P9_RERROR" },		\
+			 { P9_TFLUSH,		"P9_TFLUSH" },		\
+			 { P9_RFLUSH,		"P9_RFLUSH" },		\
+			 { P9_TWALK,		"P9_TWALK" },		\
+			 { P9_RWALK,		"P9_RWALK" },		\
+			 { P9_TOPEN,		"P9_TOPEN" },		\
+			 { P9_ROPEN,		"P9_ROPEN" },		\
+			 { P9_TCREATE,		"P9_TCREATE" },		\
+			 { P9_RCREATE,		"P9_RCREATE" },		\
+			 { P9_TREAD,		"P9_TREAD" },		\
+			 { P9_RREAD,		"P9_RREAD" },		\
+			 { P9_TWRITE,		"P9_TWRITE" },		\
+			 { P9_RWRITE,		"P9_RWRITE" },		\
+			 { P9_TCLUNK,		"P9_TCLUNK" },		\
+			 { P9_RCLUNK,		"P9_RCLUNK" },		\
+			 { P9_TREMOVE,		"P9_TREMOVE" },		\
+			 { P9_RREMOVE,		"P9_RREMOVE" },		\
+			 { P9_TSTAT,		"P9_TSTAT" },		\
+			 { P9_RSTAT,		"P9_RSTAT" },		\
+			 { P9_TWSTAT,		"P9_TWSTAT" },		\
+			 { P9_RWSTAT,		"P9_RWSTAT" })
+
+TRACE_EVENT(9p_client_req,
+	    TP_PROTO(struct p9_client *clnt, int8_t type, int tag),
+
+	    TP_ARGS(clnt, type, tag),
+
+	    TP_STRUCT__entry(
+		    /*
+		     * FIXME can i have void * as type. If so will it
+		     * cause issue when i read trace from a 64 bit machine
+		     * on a 32 bit machine.
+		     */
+		    __field(	__u64,		clnt			     )
+		    __field(	__u8,		type			     )
+		    __field(	__u32,		tag			     )
+		    ),
+
+	    TP_fast_assign(
+		    __entry->clnt    =  (__u64)clnt;
+		    __entry->type    =  type;
+		    __entry->tag     =  tag;
+		    ),
+
+	    TP_printk("client %lu request %s tag  %d",
+		    (long)__entry->clnt, show_9p_op(__entry->type),
+		    __entry->tag)
+ );
+
+TRACE_EVENT(9p_client_res,
+	    TP_PROTO(struct p9_client *clnt, int8_t type, int tag, int err),
+
+	    TP_ARGS(clnt, type, tag, err),
+
+	    TP_STRUCT__entry(
+		    /*
+		     * FIXME can i have void * as type. If so will it
+		     * cause issue when i read trace from a 64 bit machine
+		     * on a 32 bit machine.
+		     */
+		    __field(	__u64,		clnt			     )
+		    __field(	__u8,		type			     )
+		    __field(	__u32,		tag			     )
+		    __field(	__u32,		err			     )
+		    ),
+
+	    TP_fast_assign(
+		    __entry->clnt    =  (__u64)clnt;
+		    __entry->type    =  type;
+		    __entry->tag     =  tag;
+		    __entry->err     =  err;
+		    ),
+
+	    TP_printk("client %lu response %s tag  %d err %d",
+		      (long)__entry->clnt, show_9p_op(__entry->type),
+		      __entry->tag, __entry->err)
+);
+
+#define P9_PROTO_DUMP_SZ (16 * 3 + 2 + 16 + 1)
+TRACE_EVENT(9p_protocol_dump,
+	    TP_PROTO(struct p9_client *clnt, struct p9_fcall *pdu),
+
+	    TP_ARGS(clnt, pdu),
+
+	    TP_STRUCT__entry(
+		    __field(	__u64,		clnt				)
+		    __field(	__u8,		type				)
+		    __field(	__u16,		tag				)
+		    __array(	unsigned char,	line1,	P9_PROTO_DUMP_SZ	)
+		    __array(	unsigned char,	line2,	P9_PROTO_DUMP_SZ	)
+		    ),
+
+	    TP_fast_assign(
+		    const u8 *ptr   =  pdu->sdata;
+		    __entry->clnt   =  (__u64)clnt;
+		    __entry->type   =  pdu->id;
+		    __entry->tag    =  pdu->tag;
+		    hex_dump_to_buffer(ptr, 16, 16,
+				       1, __entry->line1, P9_PROTO_DUMP_SZ, true);
+		    hex_dump_to_buffer(ptr + 16, 16, 16,
+				       1, __entry->line2, P9_PROTO_DUMP_SZ, true);
+		    ),
+
+	    TP_printk("clnt %lu %s(tag = %d)\n%.8x: %s\n%.8x: %s\n",
+		      (long)__entry->clnt, show_9p_op(__entry->type),
+		      __entry->tag, 0, __entry->line1, 16 , __entry->line2)
+ );
+
+#endif /* _TRACE_9P_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
diff --git a/net/9p/client.c b/net/9p/client.c
index d094ce9..ad1ab84 100644
--- a/net/9p/client.c
+++ b/net/9p/client.c
@@ -38,6 +38,9 @@ 
 #include <net/9p/transport.h>
 #include "protocol.h"
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/9p.h>
+
 /*
   * Client Option Parsing (code inspired by NFS code)
   *  - a little lazy - parse all client options
@@ -703,8 +706,9 @@  p9_client_rpc(struct p9_client *c, int8_t type, const char *fmt, ...)
 	va_end(ap);
 	if (err)
 		goto reterr;
-	p9pdu_finalize(req->tc);
+	p9pdu_finalize(c, req->tc);
 
+	trace_9p_client_req(c, type, tag);
 	err = c->trans_mod->request(c, req);
 	if (err < 0) {
 		if (err != -ERESTARTSYS && err != -EFAULT)
@@ -746,14 +750,17 @@  p9_client_rpc(struct p9_client *c, int8_t type, const char *fmt, ...)
 		goto reterr;
 
 	err = p9_check_errors(c, req);
+	/*
+	 * dump the response from server
+	 * This should be after check errors which poplulate pdu_fcall.
+	 */
+	trace_9p_protocol_dump(c, req->rc);
+	trace_9p_client_res(c, type, tag, err);
 	if (!err) {
 		P9_DPRINTK(P9_DEBUG_MUX, "exit: client %p op %d\n", c, type);
 		return req;
 	}
-
 reterr:
-	P9_DPRINTK(P9_DEBUG_MUX, "exit: client %p op %d error: %d\n", c, type,
-									err);
 	p9_free_req(c, req);
 	return ERR_PTR(err);
 }
@@ -823,7 +830,7 @@  static struct p9_req_t *p9_client_zc_rpc(struct p9_client *c, int8_t type,
 	va_end(ap);
 	if (err)
 		goto reterr;
-	p9pdu_finalize(req->tc);
+	p9pdu_finalize(c, req->tc);
 
 	err = c->trans_mod->zc_request(c, req, uidata, uodata,
 				       inlen, olen, in_hdrlen, kern_buf);
@@ -857,10 +864,17 @@  static struct p9_req_t *p9_client_zc_rpc(struct p9_client *c, int8_t type,
 		goto reterr;
 
 	err = p9_check_zc_errors(c, req, uidata, in_hdrlen, kern_buf);
+	/*
+	 * dump the response from server
+	 * This should be after check errors which poplulate pdu_fcall.
+	 */
+	trace_9p_protocol_dump(c, req->rc);
+	trace_9p_client_res(c, type, tag, err);
 	if (!err) {
 		P9_DPRINTK(P9_DEBUG_MUX, "exit: client %p op %d\n", c, type);
 		return req;
 	}
+
 reterr:
 	P9_DPRINTK(P9_DEBUG_MUX, "exit: client %p op %d error: %d\n", c, type,
 									err);
@@ -951,7 +965,7 @@  static int p9_client_version(struct p9_client *c)
 	err = p9pdu_readf(req->rc, c->proto_version, "ds", &msize, &version);
 	if (err) {
 		P9_DPRINTK(P9_DEBUG_9P, "version error %d\n", err);
-		P9_DUMP_PKT(1, req->rc);
+		trace_9p_protocol_dump(c, req->rc);
 		goto error;
 	}
 
@@ -1088,15 +1102,14 @@  EXPORT_SYMBOL(p9_client_begin_disconnect);
 struct p9_fid *p9_client_attach(struct p9_client *clnt, struct p9_fid *afid,
 	char *uname, u32 n_uname, char *aname)
 {
-	int err;
+	int err = 0;
 	struct p9_req_t *req;
 	struct p9_fid *fid;
 	struct p9_qid qid;
 
-	P9_DPRINTK(P9_DEBUG_9P, ">>> TATTACH afid %d uname %s aname %s\n",
-					afid ? afid->fid : -1, uname, aname);
-	err = 0;
 
+	P9_DPRINTK(P9_DEBUG_9P, ">>> TATTACH afid %d uname %s aname %s\n",
+		   afid ? afid->fid : -1, uname, aname);
 	fid = p9_fid_create(clnt);
 	if (IS_ERR(fid)) {
 		err = PTR_ERR(fid);
@@ -1113,7 +1126,7 @@  struct p9_fid *p9_client_attach(struct p9_client *clnt, struct p9_fid *afid,
 
 	err = p9pdu_readf(req->rc, clnt->proto_version, "Q", &qid);
 	if (err) {
-		P9_DUMP_PKT(1, req->rc);
+		trace_9p_protocol_dump(clnt, req->rc);
 		p9_free_req(clnt, req);
 		goto error;
 	}
@@ -1173,7 +1186,7 @@  struct p9_fid *p9_client_walk(struct p9_fid *oldfid, uint16_t nwname,
 
 	err = p9pdu_readf(req->rc, clnt->proto_version, "R", &nwqids, &wqids);
 	if (err) {
-		P9_DUMP_PKT(1, req->rc);
+		trace_9p_protocol_dump(clnt, req->rc);
 		p9_free_req(clnt, req);
 		goto clunk_fid;
 	}
@@ -1240,7 +1253,7 @@  int p9_client_open(struct p9_fid *fid, int mode)
 
 	err = p9pdu_readf(req->rc, clnt->proto_version, "Qd", &qid, &iounit);
 	if (err) {
-		P9_DUMP_PKT(1, req->rc);
+		trace_9p_protocol_dump(clnt, req->rc);
 		goto free_and_error;
 	}
 
@@ -1283,7 +1296,7 @@  int p9_client_create_dotl(struct p9_fid *ofid, char *name, u32 flags, u32 mode,
 
 	err = p9pdu_readf(req->rc, clnt->proto_version, "Qd", qid, &iounit);
 	if (err) {
-		P9_DUMP_PKT(1, req->rc);
+		trace_9p_protocol_dump(clnt, req->rc);
 		goto free_and_error;
 	}
 
@@ -1328,7 +1341,7 @@  int p9_client_fcreate(struct p9_fid *fid, char *name, u32 perm, int mode,
 
 	err = p9pdu_readf(req->rc, clnt->proto_version, "Qd", &qid, &iounit);
 	if (err) {
-		P9_DUMP_PKT(1, req->rc);
+		trace_9p_protocol_dump(clnt, req->rc);
 		goto free_and_error;
 	}
 
@@ -1367,7 +1380,7 @@  int p9_client_symlink(struct p9_fid *dfid, char *name, char *symtgt, gid_t gid,
 
 	err = p9pdu_readf(req->rc, clnt->proto_version, "Q", qid);
 	if (err) {
-		P9_DUMP_PKT(1, req->rc);
+		trace_9p_protocol_dump(clnt, req->rc);
 		goto free_and_error;
 	}
 
@@ -1558,12 +1571,11 @@  p9_client_read(struct p9_fid *fid, char *data, char __user *udata, u64 offset,
 
 	err = p9pdu_readf(req->rc, clnt->proto_version, "D", &count, &dataptr);
 	if (err) {
-		P9_DUMP_PKT(1, req->rc);
+		trace_9p_protocol_dump(clnt, req->rc);
 		goto free_and_error;
 	}
 
 	P9_DPRINTK(P9_DEBUG_9P, "<<< RREAD count %d\n", count);
-	P9_DUMP_PKT(1, req->rc);
 
 	if (non_zc) {
 		if (data) {
@@ -1633,7 +1645,7 @@  p9_client_write(struct p9_fid *fid, char *data, const char __user *udata,
 
 	err = p9pdu_readf(req->rc, clnt->proto_version, "d", &count);
 	if (err) {
-		P9_DUMP_PKT(1, req->rc);
+		trace_9p_protocol_dump(clnt, req->rc);
 		goto free_and_error;
 	}
 
@@ -1673,7 +1685,7 @@  struct p9_wstat *p9_client_stat(struct p9_fid *fid)
 
 	err = p9pdu_readf(req->rc, clnt->proto_version, "wS", &ignored, ret);
 	if (err) {
-		P9_DUMP_PKT(1, req->rc);
+		trace_9p_protocol_dump(clnt, req->rc);
 		p9_free_req(clnt, req);
 		goto error;
 	}
@@ -1724,7 +1736,7 @@  struct p9_stat_dotl *p9_client_getattr_dotl(struct p9_fid *fid,
 
 	err = p9pdu_readf(req->rc, clnt->proto_version, "A", ret);
 	if (err) {
-		P9_DUMP_PKT(1, req->rc);
+		trace_9p_protocol_dump(clnt, req->rc);
 		p9_free_req(clnt, req);
 		goto error;
 	}
@@ -1872,7 +1884,7 @@  int p9_client_statfs(struct p9_fid *fid, struct p9_rstatfs *sb)
 		&sb->bsize, &sb->blocks, &sb->bfree, &sb->bavail,
 		&sb->files, &sb->ffree, &sb->fsid, &sb->namelen);
 	if (err) {
-		P9_DUMP_PKT(1, req->rc);
+		trace_9p_protocol_dump(clnt, req->rc);
 		p9_free_req(clnt, req);
 		goto error;
 	}
@@ -1979,7 +1991,7 @@  struct p9_fid *p9_client_xattrwalk(struct p9_fid *file_fid,
 	}
 	err = p9pdu_readf(req->rc, clnt->proto_version, "q", attr_size);
 	if (err) {
-		P9_DUMP_PKT(1, req->rc);
+		trace_9p_protocol_dump(clnt, req->rc);
 		p9_free_req(clnt, req);
 		goto clunk_fid;
 	}
@@ -2063,7 +2075,7 @@  int p9_client_readdir(struct p9_fid *fid, char *data, u32 count, u64 offset)
 
 	err = p9pdu_readf(req->rc, clnt->proto_version, "D", &count, &dataptr);
 	if (err) {
-		P9_DUMP_PKT(1, req->rc);
+		trace_9p_protocol_dump(clnt, req->rc);
 		goto free_and_error;
 	}
 
@@ -2100,7 +2112,7 @@  int p9_client_mknod_dotl(struct p9_fid *fid, char *name, int mode,
 
 	err = p9pdu_readf(req->rc, clnt->proto_version, "Q", qid);
 	if (err) {
-		P9_DUMP_PKT(1, req->rc);
+		trace_9p_protocol_dump(clnt, req->rc);
 		goto error;
 	}
 	P9_DPRINTK(P9_DEBUG_9P, "<<< RMKNOD qid %x.%llx.%x\n", qid->type,
@@ -2131,7 +2143,7 @@  int p9_client_mkdir_dotl(struct p9_fid *fid, char *name, int mode,
 
 	err = p9pdu_readf(req->rc, clnt->proto_version, "Q", qid);
 	if (err) {
-		P9_DUMP_PKT(1, req->rc);
+		trace_9p_protocol_dump(clnt, req->rc);
 		goto error;
 	}
 	P9_DPRINTK(P9_DEBUG_9P, "<<< RMKDIR qid %x.%llx.%x\n", qid->type,
@@ -2166,7 +2178,7 @@  int p9_client_lock_dotl(struct p9_fid *fid, struct p9_flock *flock, u8 *status)
 
 	err = p9pdu_readf(req->rc, clnt->proto_version, "b", status);
 	if (err) {
-		P9_DUMP_PKT(1, req->rc);
+		trace_9p_protocol_dump(clnt, req->rc);
 		goto error;
 	}
 	P9_DPRINTK(P9_DEBUG_9P, "<<< RLOCK status %i\n", *status);
@@ -2199,7 +2211,7 @@  int p9_client_getlock_dotl(struct p9_fid *fid, struct p9_getlock *glock)
 			&glock->start, &glock->length, &glock->proc_id,
 			&glock->client_id);
 	if (err) {
-		P9_DUMP_PKT(1, req->rc);
+		trace_9p_protocol_dump(clnt, req->rc);
 		goto error;
 	}
 	P9_DPRINTK(P9_DEBUG_9P, "<<< RGETLOCK type %i start %lld length %lld "
@@ -2227,7 +2239,7 @@  int p9_client_readlink(struct p9_fid *fid, char **target)
 
 	err = p9pdu_readf(req->rc, clnt->proto_version, "s", target);
 	if (err) {
-		P9_DUMP_PKT(1, req->rc);
+		trace_9p_protocol_dump(clnt, req->rc);
 		goto error;
 	}
 	P9_DPRINTK(P9_DEBUG_9P, "<<< RREADLINK target %s\n", *target);
diff --git a/net/9p/protocol.c b/net/9p/protocol.c
index b7d4e8a..55e10a9 100644
--- a/net/9p/protocol.c
+++ b/net/9p/protocol.c
@@ -37,40 +37,11 @@ 
 #include <net/9p/client.h>
 #include "protocol.h"
 
+#include <trace/events/9p.h>
+
 static int
 p9pdu_writef(struct p9_fcall *pdu, int proto_version, const char *fmt, ...);
 
-#ifdef CONFIG_NET_9P_DEBUG
-void
-p9pdu_dump(int way, struct p9_fcall *pdu)
-{
-	int len = pdu->size;
-
-	if ((p9_debug_level & P9_DEBUG_VPKT) != P9_DEBUG_VPKT) {
-		if ((p9_debug_level & P9_DEBUG_PKT) == P9_DEBUG_PKT) {
-			if (len > 32)
-				len = 32;
-		} else {
-			/* shouldn't happen */
-			return;
-		}
-	}
-
-	if (way)
-		print_hex_dump_bytes("[9P] ", DUMP_PREFIX_OFFSET, pdu->sdata,
-									len);
-	else
-		print_hex_dump_bytes("]9P[ ", DUMP_PREFIX_OFFSET, pdu->sdata,
-									len);
-}
-#else
-void
-p9pdu_dump(int way, struct p9_fcall *pdu)
-{
-}
-#endif
-EXPORT_SYMBOL(p9pdu_dump);
-
 void p9stat_free(struct p9_wstat *stbuf)
 {
 	kfree(stbuf->name);
@@ -551,7 +522,7 @@  p9pdu_writef(struct p9_fcall *pdu, int proto_version, const char *fmt, ...)
 	return ret;
 }
 
-int p9stat_read(char *buf, int len, struct p9_wstat *st, int proto_version)
+int p9stat_read(struct p9_client *clnt, char *buf, int len, struct p9_wstat *st)
 {
 	struct p9_fcall fake_pdu;
 	int ret;
@@ -561,10 +532,10 @@  int p9stat_read(char *buf, int len, struct p9_wstat *st, int proto_version)
 	fake_pdu.sdata = buf;
 	fake_pdu.offset = 0;
 
-	ret = p9pdu_readf(&fake_pdu, proto_version, "S", st);
+	ret = p9pdu_readf(&fake_pdu, clnt->proto_version, "S", st);
 	if (ret) {
 		P9_DPRINTK(P9_DEBUG_9P, "<<< p9stat_read failed: %d\n", ret);
-		P9_DUMP_PKT(0, &fake_pdu);
+		trace_9p_protocol_dump(clnt, &fake_pdu);
 	}
 
 	return ret;
@@ -577,7 +548,7 @@  int p9pdu_prepare(struct p9_fcall *pdu, int16_t tag, int8_t type)
 	return p9pdu_writef(pdu, 0, "dbw", 0, type, tag);
 }
 
-int p9pdu_finalize(struct p9_fcall *pdu)
+int p9pdu_finalize(struct p9_client *clnt, struct p9_fcall *pdu)
 {
 	int size = pdu->size;
 	int err;
@@ -586,7 +557,7 @@  int p9pdu_finalize(struct p9_fcall *pdu)
 	err = p9pdu_writef(pdu, 0, "d", size);
 	pdu->size = size;
 
-	P9_DUMP_PKT(0, pdu);
+	trace_9p_protocol_dump(clnt, pdu);
 	P9_DPRINTK(P9_DEBUG_9P, ">>> size=%d type: %d tag: %d\n", pdu->size,
 							pdu->id, pdu->tag);
 
@@ -599,8 +570,8 @@  void p9pdu_reset(struct p9_fcall *pdu)
 	pdu->size = 0;
 }
 
-int p9dirent_read(char *buf, int len, struct p9_dirent *dirent,
-						int proto_version)
+int p9dirent_read(struct p9_client *clnt, char *buf, int len,
+		  struct p9_dirent *dirent)
 {
 	struct p9_fcall fake_pdu;
 	int ret;
@@ -611,11 +582,11 @@  int p9dirent_read(char *buf, int len, struct p9_dirent *dirent,
 	fake_pdu.sdata = buf;
 	fake_pdu.offset = 0;
 
-	ret = p9pdu_readf(&fake_pdu, proto_version, "Qqbs", &dirent->qid,
-			&dirent->d_off, &dirent->d_type, &nameptr);
+	ret = p9pdu_readf(&fake_pdu, clnt->proto_version, "Qqbs", &dirent->qid,
+			  &dirent->d_off, &dirent->d_type, &nameptr);
 	if (ret) {
 		P9_DPRINTK(P9_DEBUG_9P, "<<< p9dirent_read failed: %d\n", ret);
-		P9_DUMP_PKT(1, &fake_pdu);
+		trace_9p_protocol_dump(clnt, &fake_pdu);
 		goto out;
 	}
 
diff --git a/net/9p/protocol.h b/net/9p/protocol.h
index e5083f3..b0a6aa8f 100644
--- a/net/9p/protocol.h
+++ b/net/9p/protocol.h
@@ -29,8 +29,7 @@  int p9pdu_vwritef(struct p9_fcall *pdu, int proto_version, const char *fmt,
 								va_list ap);
 int p9pdu_readf(struct p9_fcall *pdu, int proto_version, const char *fmt, ...);
 int p9pdu_prepare(struct p9_fcall *pdu, int16_t tag, int8_t type);
-int p9pdu_finalize(struct p9_fcall *pdu);
-void p9pdu_dump(int, struct p9_fcall *);
+int p9pdu_finalize(struct p9_client *clnt, struct p9_fcall *pdu);
 void p9pdu_reset(struct p9_fcall *pdu);
 size_t pdu_read(struct p9_fcall *pdu, void *data, size_t size);