msm: kgsl: improve context and timestamp trace

Add kgsl_context_create and kgsl_context_detach
trace events for tracking context lifetime.
Include more timestamp information in existing
events.

Change-Id: I13afb1e816caa7b668cde31cdcc8a8bd1bf8b4dc
Signed-off-by: Jeremy Gebben <jgebben@codeaurora.org>

drivers/gpu/msm/kgsl.c

@@ -386,6 +386,7 @@ kgsl_context_detach(struct kgsl_context *context)
 	if (context == NULL)
 		return;
 	device = context->dev_priv->device;
+	trace_kgsl_context_detach(device, context);
 	id = context->id;
 
 	if (device->ftbl->drawctxt_destroy)
@@ -1019,19 +1020,25 @@ static long _device_waittimestamp(struct kgsl_device_private *dev_priv,
 		unsigned int timeout)
 {
 	int result = 0;
+	struct kgsl_device *device = dev_priv->device;
+	unsigned int context_id = context ? context->id : KGSL_MEMSTORE_GLOBAL;
 
 	/* Set the active count so that suspend doesn't do the wrong thing */
 
-	dev_priv->device->active_cnt++;
+	device->active_cnt++;
 
-	trace_kgsl_waittimestamp_entry(dev_priv->device,
-			context ? context->id : KGSL_MEMSTORE_GLOBAL,
-			timestamp, timeout);
+	trace_kgsl_waittimestamp_entry(device, context_id,
+				       kgsl_readtimestamp(device, context,
+							KGSL_TIMESTAMP_RETIRED),
+				       timestamp, timeout);
 
-	result = dev_priv->device->ftbl->waittimestamp(dev_priv->device,
+	result = device->ftbl->waittimestamp(dev_priv->device,
 					context, timestamp, timeout);
 
-	trace_kgsl_waittimestamp_exit(dev_priv->device, result);
+	trace_kgsl_waittimestamp_exit(device,
+				      kgsl_readtimestamp(device, context,
+							KGSL_TIMESTAMP_RETIRED),
+				      result);
 
 	/* Fire off any pending suspend operations that are in flight */
 
@@ -1048,7 +1055,7 @@ static long kgsl_ioctl_device_waittimestamp(struct kgsl_device_private
 {
 	struct kgsl_device_waittimestamp *param = data;
 
-	return _device_waittimestamp(dev_priv, KGSL_MEMSTORE_GLOBAL,
+	return _device_waittimestamp(dev_priv, NULL,
 			param->timestamp, param->timeout);
 }
 
@@ -1149,7 +1156,7 @@ static long kgsl_ioctl_rb_issueibcmds(struct kgsl_device_private *dev_priv,
 					     &param->timestamp,
 					     param->flags);
 
-	trace_kgsl_issueibcmds(dev_priv->device, param, result);
+	trace_kgsl_issueibcmds(dev_priv->device, param, ibdesc, result);
 
 free_ibdesc:
 	kfree(ibdesc);
@@ -1206,7 +1213,7 @@ static void kgsl_freemem_event_cb(struct kgsl_device *device,
 	spin_lock(&entry->priv->mem_lock);
 	rb_erase(&entry->node, &entry->priv->mem_rb);
 	spin_unlock(&entry->priv->mem_lock);
-	trace_kgsl_mem_timestamp_free(entry, id, timestamp);
+	trace_kgsl_mem_timestamp_free(device, entry, id, timestamp, 0);
 	kgsl_mem_entry_detach_process(entry);
 }
 
@@ -1217,27 +1224,25 @@ static long _cmdstream_freememontimestamp(struct kgsl_device_private *dev_priv,
 	int result = 0;
 	struct kgsl_mem_entry *entry = NULL;
 	struct kgsl_device *device = dev_priv->device;
-	unsigned int cur;
 	unsigned int context_id = context ? context->id : KGSL_MEMSTORE_GLOBAL;
 
 	spin_lock(&dev_priv->process_priv->mem_lock);
 	entry = kgsl_sharedmem_find(dev_priv->process_priv, gpuaddr);
 	spin_unlock(&dev_priv->process_priv->mem_lock);
 
-	if (entry) {
-		cur = device->ftbl->readtimestamp(device, context,
-						KGSL_TIMESTAMP_RETIRED);
-
-		trace_kgsl_mem_timestamp_queue(entry, context_id, cur);
-		result = kgsl_add_event(dev_priv->device, context_id,
-				timestamp, kgsl_freemem_event_cb,
-				entry, dev_priv);
-	} else {
+	if (!entry) {
 		KGSL_DRV_ERR(dev_priv->device,
-			"invalid gpuaddr %08x\n", gpuaddr);
+				"invalid gpuaddr %08x\n", gpuaddr);
 		result = -EINVAL;
+		goto done;
 	}
-
+	trace_kgsl_mem_timestamp_queue(device, entry, context_id,
+				       kgsl_readtimestamp(device, context,
+						  KGSL_TIMESTAMP_RETIRED),
+				       timestamp);
+	result = kgsl_add_event(dev_priv->device, context_id, timestamp,
+				kgsl_freemem_event_cb, entry, dev_priv);
+done:
 	return result;
 }
 
@@ -1284,11 +1289,14 @@ static long kgsl_ioctl_drawctxt_create(struct kgsl_device_private *dev_priv,
 		goto done;
 	}
 
-	if (dev_priv->device->ftbl->drawctxt_create)
+	if (dev_priv->device->ftbl->drawctxt_create) {
 		result = dev_priv->device->ftbl->drawctxt_create(
 			dev_priv->device, dev_priv->process_priv->pagetable,
 			context, param->flags);
-
+		if (result)
+			goto done;
+	}
+	trace_kgsl_context_create(dev_priv->device, context, param->flags);
 	param->drawctxt_id = context->id;
 done:
 	if (result && context)

drivers/gpu/msm/kgsl.h

@@ -158,7 +158,6 @@ struct kgsl_mem_entry {
 	int flags;
 	void *priv_data;
 	struct rb_node node;
-	uint32_t free_timestamp;
 	unsigned int context_id;
 	/* back pointer to private structure under whose context this
 	* allocation is made */

drivers/gpu/msm/kgsl_trace.h

@@ -22,6 +22,7 @@
 #define TRACE_INCLUDE_FILE kgsl_trace
 
 #include <linux/tracepoint.h>
+#include "kgsl_device.h"
 
 struct kgsl_device;
 struct kgsl_ringbuffer_issueibcmds;
@@ -33,9 +34,11 @@ struct kgsl_device_waittimestamp;
 TRACE_EVENT(kgsl_issueibcmds,
 
 	TP_PROTO(struct kgsl_device *device,
-			struct kgsl_ringbuffer_issueibcmds *cmd, int result),
+			struct kgsl_ringbuffer_issueibcmds *cmd,
+			struct kgsl_ibdesc *ibdesc,
+			int result),
 
-	TP_ARGS(device, cmd, result),
+	TP_ARGS(device, cmd, ibdesc, result),
 
 	TP_STRUCT__entry(
 		__string(device_name, device->name)
@@ -50,7 +53,7 @@ TRACE_EVENT(kgsl_issueibcmds,
 	TP_fast_assign(
 		__assign_str(device_name, device->name);
 		__entry->drawctxt_id = cmd->drawctxt_id;
-		__entry->ibdesc_addr = cmd->ibdesc_addr;
+		__entry->ibdesc_addr = ibdesc[0].gpuaddr;
 		__entry->numibs = cmd->numibs;
 		__entry->timestamp = cmd->timestamp;
 		__entry->flags = cmd->flags;
@@ -58,14 +61,19 @@ TRACE_EVENT(kgsl_issueibcmds,
 	),
 
 	TP_printk(
-		"d_name=%s ctx=%u ib=%u numibs=%u timestamp=%u "
-		"flags=%u result=%d",
+		"d_name=%s ctx=%u ib=0x%u numibs=%u timestamp=0x%x "
+		"flags=0x%x(%s) result=%d",
 		__get_str(device_name),
 		__entry->drawctxt_id,
 		__entry->ibdesc_addr,
 		__entry->numibs,
 		__entry->timestamp,
 		__entry->flags,
+		__entry->flags ? __print_flags(__entry->flags, "|",
+			{ KGSL_CONTEXT_SAVE_GMEM, "SAVE_GMEM" },
+			{ KGSL_CONTEXT_SUBMIT_IB_LIST, "IB_LIST" },
+			{ KGSL_CONTEXT_CTX_SWITCH, "CTX_SWITCH" })
+			: "None",
 		__entry->result
 	)
 );
@@ -97,7 +105,7 @@ TRACE_EVENT(kgsl_readtimestamp,
 	),
 
 	TP_printk(
-		"d_name=%s context_id=%u type=%u timestamp=%u",
+		"d_name=%s context_id=%u type=%u timestamp=0x%x",
 		__get_str(device_name),
 		__entry->context_id,
 		__entry->type,
@@ -112,30 +120,34 @@ TRACE_EVENT(kgsl_waittimestamp_entry,
 
 	TP_PROTO(struct kgsl_device *device,
 			unsigned int context_id,
-			unsigned int timestamp,
+			unsigned int curr_ts,
+			unsigned int wait_ts,
 			unsigned int timeout),
 
-	TP_ARGS(device, context_id, timestamp, timeout),
+	TP_ARGS(device, context_id, curr_ts, wait_ts, timeout),
 
 	TP_STRUCT__entry(
 		__string(device_name, device->name)
 		__field(unsigned int, context_id)
-		__field(unsigned int, timestamp)
+		__field(unsigned int, curr_ts)
+		__field(unsigned int, wait_ts)
 		__field(unsigned int, timeout)
 	),
 
 	TP_fast_assign(
 		__assign_str(device_name, device->name);
 		__entry->context_id = context_id;
-		__entry->timestamp = timestamp;
+		__entry->curr_ts = curr_ts;
+		__entry->wait_ts = wait_ts;
 		__entry->timeout = timeout;
 	),
 
 	TP_printk(
-		"d_name=%s context_id=%u timestamp=%u timeout=%u",
+		"d_name=%s context_id=%u curr_ts=%u timestamp=0x%x timeout=%u",
 		__get_str(device_name),
 		__entry->context_id,
-		__entry->timestamp,
+		__entry->curr_ts,
+		__entry->wait_ts,
 		__entry->timeout
 	)
 );
@@ -145,23 +157,27 @@ TRACE_EVENT(kgsl_waittimestamp_entry,
  */
 TRACE_EVENT(kgsl_waittimestamp_exit,
 
-	TP_PROTO(struct kgsl_device *device, int result),
+	TP_PROTO(struct kgsl_device *device, unsigned int curr_ts,
+		 int result),
 
-	TP_ARGS(device, result),
+	TP_ARGS(device, curr_ts, result),
 
 	TP_STRUCT__entry(
 		__string(device_name, device->name)
+		__field(unsigned int, curr_ts)
 		__field(int, result)
 	),
 
 	TP_fast_assign(
 		__assign_str(device_name, device->name);
+		__entry->curr_ts = curr_ts;
 		__entry->result = result;
 	),
 
 	TP_printk(
-		"d_name=%s result=%d",
+		"d_name=%s curr_ts=%u result=%d",
 		__get_str(device_name),
+		__entry->curr_ts,
 		__entry->result
 	)
 );
@@ -343,12 +359,13 @@ TRACE_EVENT(kgsl_mem_free,
 
 DECLARE_EVENT_CLASS(kgsl_mem_timestamp_template,
 
-	TP_PROTO(struct kgsl_mem_entry *mem_entry, unsigned int id,
-		unsigned int curr_ts),
+	TP_PROTO(struct kgsl_device *device, struct kgsl_mem_entry *mem_entry,
+		unsigned int id, unsigned int curr_ts, unsigned int free_ts),
 
-	TP_ARGS(mem_entry, id, curr_ts),
+	TP_ARGS(device, mem_entry, id, curr_ts, free_ts),
 
 	TP_STRUCT__entry(
+		__string(device_name, device->name)
 		__field(unsigned int, gpuaddr)
 		__field(unsigned int, size)
 		__field(int, type)
@@ -358,33 +375,92 @@ DECLARE_EVENT_CLASS(kgsl_mem_timestamp_template,
 	),
 
 	TP_fast_assign(
+		__assign_str(device_name, device->name);
 		__entry->gpuaddr = mem_entry->memdesc.gpuaddr;
 		__entry->size = mem_entry->memdesc.size;
 		__entry->drawctxt_id = id;
 		__entry->type = mem_entry->memtype;
 		__entry->curr_ts = curr_ts;
-		__entry->free_ts = mem_entry->free_timestamp;
+		__entry->free_ts = free_ts;
 	),
 
 	TP_printk(
-		"gpuaddr=0x%08x size=%d type=%d ctx=%u curr_ts=0x%08x free_ts=0x%08x",
-		__entry->gpuaddr, __entry->size, __entry->type,
-		__entry->drawctxt_id, __entry->curr_ts, __entry->free_ts
+		"d_name=%s gpuaddr=0x%08x size=%d type=%d ctx=%u"
+		" curr_ts=0x%08x free_ts=0x%08x",
+		__get_str(device_name),
+		__entry->gpuaddr,
+		__entry->size,
+		__entry->type,
+		__entry->drawctxt_id,
+		__entry->curr_ts,
+		__entry->free_ts
 	)
 );
 
 DEFINE_EVENT(kgsl_mem_timestamp_template, kgsl_mem_timestamp_queue,
-	TP_PROTO(struct kgsl_mem_entry *mem_entry, unsigned int id,
-		unsigned int curr_ts),
-	TP_ARGS(mem_entry, id, curr_ts)
+	TP_PROTO(struct kgsl_device *device, struct kgsl_mem_entry *mem_entry,
+		unsigned int id, unsigned int curr_ts, unsigned int free_ts),
+	TP_ARGS(device, mem_entry, id, curr_ts, free_ts)
 );
 
 DEFINE_EVENT(kgsl_mem_timestamp_template, kgsl_mem_timestamp_free,
-	TP_PROTO(struct kgsl_mem_entry *mem_entry, unsigned int id,
-		unsigned int curr_ts),
-	TP_ARGS(mem_entry, id, curr_ts)
+	TP_PROTO(struct kgsl_device *device, struct kgsl_mem_entry *mem_entry,
+		unsigned int id, unsigned int curr_ts, unsigned int free_ts),
+	TP_ARGS(device, mem_entry, id, curr_ts, free_ts)
 );
 
+TRACE_EVENT(kgsl_context_create,
+
+	TP_PROTO(struct kgsl_device *device, struct kgsl_context *context,
+		 unsigned int flags),
+
+	TP_ARGS(device, context, flags),
+
+	TP_STRUCT__entry(
+		__string(device_name, device->name)
+		__field(unsigned int, id)
+		__field(unsigned int, flags)
+	),
+
+	TP_fast_assign(
+		__assign_str(device_name, device->name);
+		__entry->id = context->id;
+		__entry->flags = flags;
+	),
+
+	TP_printk(
+		"d_name=%s ctx=%u flags=0x%x %s",
+		__get_str(device_name), __entry->id, __entry->flags,
+		__entry->flags ? __print_flags(__entry->flags, "|",
+			{ KGSL_CONTEXT_NO_GMEM_ALLOC , "NO_GMEM_ALLOC" },
+			{ KGSL_CONTEXT_PREAMBLE, "PREAMBLE" },
+			{ KGSL_CONTEXT_TRASH_STATE, "TRASH_STATE" },
+			{ KGSL_CONTEXT_PER_CONTEXT_TS, "PER_CONTEXT_TS" })
+			: "None"
+	)
+);
+
+TRACE_EVENT(kgsl_context_detach,
+
+	TP_PROTO(struct kgsl_device *device, struct kgsl_context *context),
+
+	TP_ARGS(device, context),
+
+	TP_STRUCT__entry(
+		__string(device_name, device->name)
+		__field(unsigned int, id)
+	),
+
+	TP_fast_assign(
+		__assign_str(device_name, device->name);
+		__entry->id = context->id;
+	),
+
+	TP_printk(
+		"d_name=%s ctx=%u",
+		__get_str(device_name), __entry->id
+	)
+);
 
 TRACE_EVENT(kgsl_mmu_pagefault,
 
@@ -414,7 +490,6 @@ TRACE_EVENT(kgsl_mmu_pagefault,
 	)
 );
 
-
 #endif /* _KGSL_TRACE_H */
 
 /* This part must be outside protection */