afs: Trace the initiation and completion of client calls

Add tracepoints to trace the initiation and completion of client calls
within the kafs filesystem.

The afs_make_vl_call tracepoint watches calls to the volume location
database server.

The afs_make_fs_call tracepoint watches calls to the file server.

The afs_call_done tracepoint watches for call completion.
Signed-off-by: David Howells <dhowells@redhat.com>

fs/afs/internal.h

@@ -124,6 +124,7 @@ struct afs_call {
 
 struct afs_call_type {
 	const char *name;
+	unsigned int op; /* Really enum afs_fs_operation */
 
 	/* deliver request or reply data to an call
 	 * - returning an error will cause the call to be aborted

fs/afs/rxrpc.c

@@ -219,6 +219,7 @@ struct afs_call *afs_alloc_flat_call(struct afs_net *net,
 			goto nomem_free;
 	}
 
+	call->operation_ID = type->op;
 	init_waitqueue_head(&call->waitq);
 	return call;
 
@@ -422,6 +423,8 @@ long afs_make_call(struct afs_addr_cursor *ac, struct afs_call *call,
 		ac->abort_code = call->abort_code;
 		ac->responded = true;
 	}
+	call->error = ret;
+	trace_afs_call_done(call);
 error_kill_call:
 	afs_put_call(call);
 	ac->error = ret;
@@ -455,10 +458,10 @@ static void afs_deliver_to_call(struct afs_call *call)
 
 			if (ret == -EINPROGRESS || ret == -EAGAIN)
 				return;
-			if (ret == 1 || ret < 0) {
-				call->state = AFS_CALL_COMPLETE;
-				goto done;
-			}
+			if (ret < 0)
+				call->error = ret;
+			if (ret < 0 || ret == 1)
+				goto call_complete;
 			return;
 		}
 
@@ -466,7 +469,7 @@ static void afs_deliver_to_call(struct afs_call *call)
 		switch (ret) {
 		case 0:
 			if (call->state == AFS_CALL_AWAIT_REPLY)
-				call->state = AFS_CALL_COMPLETE;
+				goto call_complete;
 			goto done;
 		case -EINPROGRESS:
 		case -EAGAIN:
@@ -505,7 +508,11 @@ static void afs_deliver_to_call(struct afs_call *call)
 
 save_error:
 	call->error = ret;
-	call->state = AFS_CALL_COMPLETE;
+call_complete:
+	if (call->state != AFS_CALL_COMPLETE) {
+		call->state = AFS_CALL_COMPLETE;
+		trace_afs_call_done(call);
+	}
 	goto done;
 }
 
@@ -567,8 +574,10 @@ static long afs_wait_for_call_to_complete(struct afs_call *call,
 	if (call->state < AFS_CALL_COMPLETE) {
 		_debug("call interrupted");
 		if (rxrpc_kernel_abort_call(call->net->socket, call->rxcall,
-					    RX_USER_ABORT, -EINTR, "KWI"))
+					    RX_USER_ABORT, -EINTR, "KWI")) {
 			call->error = -ERESTARTSYS;
+			trace_afs_call_done(call);
+		}
 	}
 
 	ac->abort_code = call->abort_code;
@@ -882,6 +891,7 @@ int afs_extract_data(struct afs_call *call, void *buf, size_t count,
 		switch (call->state) {
 		case AFS_CALL_AWAIT_REPLY:
 			call->state = AFS_CALL_COMPLETE;
+			trace_afs_call_done(call);
 			break;
 		case AFS_CALL_AWAIT_REQUEST:
 			call->state = AFS_CALL_REPLYING;
@@ -894,5 +904,6 @@ int afs_extract_data(struct afs_call *call, void *buf, size_t count,
 
 	call->error = ret;
 	call->state = AFS_CALL_COMPLETE;
+	trace_afs_call_done(call);
 	return ret;
 }

fs/afs/vlclient.c

@@ -114,6 +114,7 @@ static void afs_destroy_vl_get_entry_by_name_u(struct afs_call *call)
  */
 static const struct afs_call_type afs_RXVLGetEntryByNameU = {
 	.name		= "VL.GetEntryByNameU",
+	.op		= afs_VL_GetEntryByNameU,
 	.deliver	= afs_deliver_vl_get_entry_by_name_u,
 	.destructor	= afs_destroy_vl_get_entry_by_name_u,
 };
@@ -161,6 +162,7 @@ struct afs_vldb_entry *afs_vl_get_entry_by_name_u(struct afs_net *net,
 	if (padsz > 0)
 		memset((void *)bp + volnamesz, 0, padsz);
 
+	trace_afs_make_vl_call(call);
 	return (struct afs_vldb_entry *)afs_make_call(ac, call, GFP_KERNEL, false);
 }
 
@@ -251,6 +253,7 @@ static void afs_vl_get_addrs_u_destructor(struct afs_call *call)
  */
 static const struct afs_call_type afs_RXVLGetAddrsU = {
 	.name		= "VL.GetAddrsU",
+	.op		= afs_VL_GetAddrsU,
 	.deliver	= afs_deliver_vl_get_addrs_u,
 	.destructor	= afs_vl_get_addrs_u_destructor,
 };
@@ -298,6 +301,7 @@ struct afs_addr_list *afs_vl_get_addrs_u(struct afs_net *net,
 	for (i = 0; i < 6; i++)
 		r->uuid.node[i] = ntohl(u->node[i]);
 
+	trace_afs_make_vl_call(call);
 	return (struct afs_addr_list *)afs_make_call(ac, call, GFP_KERNEL, false);
 }
 
@@ -362,6 +366,7 @@ static int afs_deliver_vl_get_capabilities(struct afs_call *call)
  */
 static const struct afs_call_type afs_RXVLGetCapabilities = {
 	.name		= "VL.GetCapabilities",
+	.op		= afs_VL_GetCapabilities,
 	.deliver	= afs_deliver_vl_get_capabilities,
 	.destructor	= afs_flat_call_destructor,
 };
@@ -396,6 +401,7 @@ int afs_vl_get_capabilities(struct afs_net *net,
 	*bp++ = htonl(VLGETCAPABILITIES);
 
 	/* Can't take a ref on server */
+	trace_afs_make_vl_call(call);
 	return afs_make_call(ac, call, GFP_KERNEL, false);
 }
 
@@ -598,7 +604,8 @@ static int afs_deliver_yfsvl_get_endpoints(struct afs_call *call)
  * YFSVL.GetEndpoints operation type.
  */
 static const struct afs_call_type afs_YFSVLGetEndpoints = {
-	.name		= "VL.GetEndpoints",
+	.name		= "YFSVL.GetEndpoints",
+	.op		= afs_YFSVL_GetEndpoints,
 	.deliver	= afs_deliver_yfsvl_get_endpoints,
 	.destructor	= afs_vl_get_addrs_u_destructor,
 };
@@ -633,5 +640,6 @@ struct afs_addr_list *afs_yfsvl_get_endpoints(struct afs_net *net,
 	*bp++ = htonl(YFS_SERVER_UUID);
 	memcpy(bp, uuid, sizeof(*uuid)); /* Type opr_uuid */
 
+	trace_afs_make_vl_call(call);
 	return (struct afs_addr_list *)afs_make_call(ac, call, GFP_KERNEL, false);
 }

include/trace/events/afs.h

@@ -30,6 +30,38 @@ enum afs_call_trace {
 	afs_call_trace_work,
 };
 
+enum afs_fs_operation {
+	afs_FS_FetchData		= 130,	/* AFS Fetch file data */
+	afs_FS_FetchStatus		= 132,	/* AFS Fetch file status */
+	afs_FS_StoreData		= 133,	/* AFS Store file data */
+	afs_FS_StoreStatus		= 135,	/* AFS Store file status */
+	afs_FS_RemoveFile		= 136,	/* AFS Remove a file */
+	afs_FS_CreateFile		= 137,	/* AFS Create a file */
+	afs_FS_Rename			= 138,	/* AFS Rename or move a file or directory */
+	afs_FS_Symlink			= 139,	/* AFS Create a symbolic link */
+	afs_FS_Link			= 140,	/* AFS Create a hard link */
+	afs_FS_MakeDir			= 141,	/* AFS Create a directory */
+	afs_FS_RemoveDir		= 142,	/* AFS Remove a directory */
+	afs_FS_GetVolumeInfo		= 148,	/* AFS Get information about a volume */
+	afs_FS_GetVolumeStatus		= 149,	/* AFS Get volume status information */
+	afs_FS_GetRootVolume		= 151,	/* AFS Get root volume name */
+	afs_FS_SetLock			= 156,	/* AFS Request a file lock */
+	afs_FS_ExtendLock		= 157,	/* AFS Extend a file lock */
+	afs_FS_ReleaseLock		= 158,	/* AFS Release a file lock */
+	afs_FS_Lookup			= 161,	/* AFS lookup file in directory */
+	afs_FS_FetchData64		= 65537, /* AFS Fetch file data */
+	afs_FS_StoreData64		= 65538, /* AFS Store file data */
+	afs_FS_GiveUpAllCallBacks	= 65539, /* AFS Give up all our callbacks on a server */
+	afs_FS_GetCapabilities		= 65540, /* AFS Get FS server capabilities */
+};
+
+enum afs_vl_operation {
+	afs_VL_GetEntryByNameU	= 527,		/* AFS Get Vol Entry By Name operation ID */
+	afs_VL_GetAddrsU	= 533,		/* AFS Get FS server addresses */
+	afs_YFSVL_GetEndpoints	= 64002,	/* YFS Get FS & Vol server addresses */
+	afs_VL_GetCapabilities	= 65537,	/* AFS Get VL server capabilities */
+};
+
 #endif /* end __AFS_DECLARE_TRACE_ENUMS_ONCE_ONLY */
 
 /*
@@ -42,6 +74,37 @@ enum afs_call_trace {
 	EM(afs_call_trace_wake,			"WAKE ") \
 	E_(afs_call_trace_work,			"WORK ")
 
+#define afs_fs_operations \
+	EM(afs_FS_FetchData,			"FS.FetchData") \
+	EM(afs_FS_FetchStatus,			"FS.FetchStatus") \
+	EM(afs_FS_StoreData,			"FS.StoreData") \
+	EM(afs_FS_StoreStatus,			"FS.StoreStatus") \
+	EM(afs_FS_RemoveFile,			"FS.RemoveFile") \
+	EM(afs_FS_CreateFile,			"FS.CreateFile") \
+	EM(afs_FS_Rename,			"FS.Rename") \
+	EM(afs_FS_Symlink,			"FS.Symlink") \
+	EM(afs_FS_Link,				"FS.Link") \
+	EM(afs_FS_MakeDir,			"FS.MakeDir") \
+	EM(afs_FS_RemoveDir,			"FS.RemoveDir") \
+	EM(afs_FS_GetVolumeInfo,		"FS.GetVolumeInfo") \
+	EM(afs_FS_GetVolumeStatus,		"FS.GetVolumeStatus") \
+	EM(afs_FS_GetRootVolume,		"FS.GetRootVolume") \
+	EM(afs_FS_SetLock,			"FS.SetLock") \
+	EM(afs_FS_ExtendLock,			"FS.ExtendLock") \
+	EM(afs_FS_ReleaseLock,			"FS.ReleaseLock") \
+	EM(afs_FS_Lookup,			"FS.Lookup") \
+	EM(afs_FS_FetchData64,			"FS.FetchData64") \
+	EM(afs_FS_StoreData64,			"FS.StoreData64") \
+	EM(afs_FS_GiveUpAllCallBacks,		"FS.GiveUpAllCallBacks") \
+	E_(afs_FS_GetCapabilities,		"FS.GetCapabilities")
+
+#define afs_vl_operations \
+	EM(afs_VL_GetEntryByNameU,		"VL.GetEntryByNameU") \
+	EM(afs_VL_GetAddrsU,			"VL.GetAddrsU") \
+	EM(afs_YFSVL_GetEndpoints,		"YFSVL.GetEndpoints") \
+	E_(afs_VL_GetCapabilities,		"VL.GetCapabilities")
+
+
 /*
  * Export enum symbols via userspace.
  */
@@ -51,6 +114,8 @@ enum afs_call_trace {
 #define E_(a, b) TRACE_DEFINE_ENUM(a);
 
 afs_call_traces;
+afs_fs_operations;
+afs_vl_operations;
 
 /*
  * Now redefine the EM() and E_() macros to map the enums to the strings that
@@ -178,6 +243,83 @@ TRACE_EVENT(afs_call,
 		      __entry->where)
 	    );
 
+TRACE_EVENT(afs_make_fs_call,
+	    TP_PROTO(struct afs_call *call, const struct afs_fid *fid),
+
+	    TP_ARGS(call, fid),
+
+	    TP_STRUCT__entry(
+		    __field(struct afs_call *,		call		)
+		    __field(enum afs_fs_operation,	op		)
+		    __field_struct(struct afs_fid,	fid		)
+			     ),
+
+	    TP_fast_assign(
+		    __entry->call = call;
+		    __entry->op = call->operation_ID;
+		    if (fid) {
+			    __entry->fid = *fid;
+		    } else {
+			    __entry->fid.vid = 0;
+			    __entry->fid.vnode = 0;
+			    __entry->fid.unique = 0;
+		    }
+			   ),
+
+	    TP_printk("c=%p %06x:%06x:%06x %s",
+		      __entry->call,
+		      __entry->fid.vid,
+		      __entry->fid.vnode,
+		      __entry->fid.unique,
+		      __print_symbolic(__entry->op, afs_fs_operations))
+	    );
+
+TRACE_EVENT(afs_make_vl_call,
+	    TP_PROTO(struct afs_call *call),
+
+	    TP_ARGS(call),
+
+	    TP_STRUCT__entry(
+		    __field(struct afs_call *,		call		)
+		    __field(enum afs_vl_operation,	op		)
+			     ),
+
+	    TP_fast_assign(
+		    __entry->call = call;
+		    __entry->op = call->operation_ID;
+			   ),
+
+	    TP_printk("c=%p %s",
+		      __entry->call,
+		      __print_symbolic(__entry->op, afs_vl_operations))
+	    );
+
+TRACE_EVENT(afs_call_done,
+	    TP_PROTO(struct afs_call *call),
+
+	    TP_ARGS(call),
+
+	    TP_STRUCT__entry(
+		    __field(struct afs_call *,		call		)
+		    __field(struct rxrpc_call *,	rx_call		)
+		    __field(int,			ret		)
+		    __field(u32,			abort_code	)
+			     ),
+
+	    TP_fast_assign(
+		    __entry->call = call;
+		    __entry->rx_call = call->rxcall;
+		    __entry->ret = call->error;
+		    __entry->abort_code = call->abort_code;
+			   ),
+
+	    TP_printk("   c=%p ret=%d ab=%d [%p]",
+		      __entry->call,
+		      __entry->ret,
+		      __entry->abort_code,
+		      __entry->rx_call)
+	    );
+
 #endif /* _TRACE_AFS_H */
 
 /* This part must be outside protection */