drm/i915: Add tracepoints

By adding tracepoint equivalents for WATCH_BUF/EXEC we are able to monitor
the lifetimes of objects, requests and significant events. These events can
then be probed using the tracing frameworks, such as systemtap and, in
particular, perf.

For example to record the stack trace for every GPU stall during a run, use

  $ perf record -e i915:i915_gem_request_wait_begin -c 1 -g

And

  $ perf report

to view the results.

[Updated to fix compilation issues caused.]
Cc: Arjan van de Ven <arjan@linux.intel.com>
Cc: Ben Gamari <bgamari@gmail.com>
Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>

drivers/gpu/drm/i915/Makefile

@@ -9,6 +9,7 @@ i915-y := i915_drv.o i915_dma.o i915_irq.o i915_mem.o \
 	  i915_gem.o \
 	  i915_gem_debug.o \
 	  i915_gem_tiling.o \
+	  i915_trace_points.o \
 	  intel_display.o \
 	  intel_crt.o \
 	  intel_lvds.o \

drivers/gpu/drm/i915/i915_dma.c

@@ -33,6 +33,7 @@
 #include "intel_drv.h"
 #include "i915_drm.h"
 #include "i915_drv.h"
+#include "i915_trace.h"
 
 /* Really want an OS-independent resettable timer.  Would like to have
  * this loop run for (eg) 3 sec, but have the timer reset every time
@@ -49,14 +50,18 @@ int i915_wait_ring(struct drm_device * dev, int n, const char *caller)
 	u32 last_head = I915_READ(PRB0_HEAD) & HEAD_ADDR;
 	int i;
 
+	trace_i915_ring_wait_begin (dev);
+
 	for (i = 0; i < 100000; i++) {
 		ring->head = I915_READ(PRB0_HEAD) & HEAD_ADDR;
 		acthd = I915_READ(acthd_reg);
 		ring->space = ring->head - (ring->tail + 8);
 		if (ring->space < 0)
 			ring->space += ring->Size;
-		if (ring->space >= n)
+		if (ring->space >= n) {
+			trace_i915_ring_wait_end (dev);
 			return 0;
+		}
 
 		if (dev->primary->master) {
 			struct drm_i915_master_private *master_priv = dev->primary->master->driver_priv;
@@ -76,6 +81,7 @@ int i915_wait_ring(struct drm_device * dev, int n, const char *caller)
 
 	}
 
+	trace_i915_ring_wait_end (dev);
 	return -EBUSY;
 }
 

drivers/gpu/drm/i915/i915_irq.c

@@ -31,6 +31,7 @@
 #include "drm.h"
 #include "i915_drm.h"
 #include "i915_drv.h"
+#include "i915_trace.h"
 #include "intel_drv.h"
 
 #define MAX_NOPID ((u32)~0)
@@ -279,7 +280,9 @@ irqreturn_t igdng_irq_handler(struct drm_device *dev)
 		}
 
 		if (gt_iir & GT_USER_INTERRUPT) {
-			dev_priv->mm.irq_gem_seqno = i915_get_gem_seqno(dev);
+			u32 seqno = i915_get_gem_seqno(dev);
+			dev_priv->mm.irq_gem_seqno = seqno;
+			trace_i915_gem_request_complete(dev, seqno);
 			DRM_WAKEUP(&dev_priv->irq_queue);
 		}
 
@@ -622,7 +625,9 @@ irqreturn_t i915_driver_irq_handler(DRM_IRQ_ARGS)
 		}
 
 		if (iir & I915_USER_INTERRUPT) {
-			dev_priv->mm.irq_gem_seqno = i915_get_gem_seqno(dev);
+			u32 seqno = i915_get_gem_seqno(dev);
+			dev_priv->mm.irq_gem_seqno = seqno;
+			trace_i915_gem_request_complete(dev, seqno);
 			DRM_WAKEUP(&dev_priv->irq_queue);
 			dev_priv->hangcheck_count = 0;
 			mod_timer(&dev_priv->hangcheck_timer, jiffies + DRM_I915_HANGCHECK_PERIOD);

drivers/gpu/drm/i915/i915_trace.h

+#if !defined(_I915_TRACE_H_) || defined(TRACE_HEADER_MULTI_READ)
+#define _I915_TRACE_H_
+
+#include <linux/stringify.h>
+#include <linux/types.h>
+#include <linux/tracepoint.h>
+
+#include <drm/drmP.h>
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM i915
+#define TRACE_SYSTEM_STRING __stringify(TRACE_SYSTEM)
+#define TRACE_INCLUDE_FILE i915_trace
+
+/* object tracking */
+
+TRACE_EVENT(i915_gem_object_create,
+
+	    TP_PROTO(struct drm_gem_object *obj),
+
+	    TP_ARGS(obj),
+
+	    TP_STRUCT__entry(
+			     __field(struct drm_gem_object *, obj)
+			     __field(u32, size)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->obj = obj;
+			   __entry->size = obj->size;
+			   ),
+
+	    TP_printk("obj=%p, size=%u", __entry->obj, __entry->size)
+);
+
+TRACE_EVENT(i915_gem_object_bind,
+
+	    TP_PROTO(struct drm_gem_object *obj, u32 gtt_offset),
+
+	    TP_ARGS(obj, gtt_offset),
+
+	    TP_STRUCT__entry(
+			     __field(struct drm_gem_object *, obj)
+			     __field(u32, gtt_offset)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->obj = obj;
+			   __entry->gtt_offset = gtt_offset;
+			   ),
+
+	    TP_printk("obj=%p, gtt_offset=%08x",
+		      __entry->obj, __entry->gtt_offset)
+);
+
+TRACE_EVENT(i915_gem_object_clflush,
+
+	    TP_PROTO(struct drm_gem_object *obj),
+
+	    TP_ARGS(obj),
+
+	    TP_STRUCT__entry(
+			     __field(struct drm_gem_object *, obj)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->obj = obj;
+			   ),
+
+	    TP_printk("obj=%p", __entry->obj)
+);
+
+TRACE_EVENT(i915_gem_object_change_domain,
+
+	    TP_PROTO(struct drm_gem_object *obj, uint32_t old_read_domains, uint32_t old_write_domain),
+
+	    TP_ARGS(obj, old_read_domains, old_write_domain),
+
+	    TP_STRUCT__entry(
+			     __field(struct drm_gem_object *, obj)
+			     __field(u32, read_domains)
+			     __field(u32, write_domain)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->obj = obj;
+			   __entry->read_domains = obj->read_domains | (old_read_domains << 16);
+			   __entry->write_domain = obj->write_domain | (old_write_domain << 16);
+			   ),
+
+	    TP_printk("obj=%p, read=%04x, write=%04x",
+		      __entry->obj,
+		      __entry->read_domains, __entry->write_domain)
+);
+
+TRACE_EVENT(i915_gem_object_get_fence,
+
+	    TP_PROTO(struct drm_gem_object *obj, int fence, int tiling_mode),
+
+	    TP_ARGS(obj, fence, tiling_mode),
+
+	    TP_STRUCT__entry(
+			     __field(struct drm_gem_object *, obj)
+			     __field(int, fence)
+			     __field(int, tiling_mode)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->obj = obj;
+			   __entry->fence = fence;
+			   __entry->tiling_mode = tiling_mode;
+			   ),
+
+	    TP_printk("obj=%p, fence=%d, tiling=%d",
+		      __entry->obj, __entry->fence, __entry->tiling_mode)
+);
+
+TRACE_EVENT(i915_gem_object_unbind,
+
+	    TP_PROTO(struct drm_gem_object *obj),
+
+	    TP_ARGS(obj),
+
+	    TP_STRUCT__entry(
+			     __field(struct drm_gem_object *, obj)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->obj = obj;
+			   ),
+
+	    TP_printk("obj=%p", __entry->obj)
+);
+
+TRACE_EVENT(i915_gem_object_destroy,
+
+	    TP_PROTO(struct drm_gem_object *obj),
+
+	    TP_ARGS(obj),
+
+	    TP_STRUCT__entry(
+			     __field(struct drm_gem_object *, obj)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->obj = obj;
+			   ),
+
+	    TP_printk("obj=%p", __entry->obj)
+);
+
+/* batch tracing */
+
+TRACE_EVENT(i915_gem_request_submit,
+
+	    TP_PROTO(struct drm_device *dev, u32 seqno),
+
+	    TP_ARGS(dev, seqno),
+
+	    TP_STRUCT__entry(
+			     __field(struct drm_device *, dev)
+			     __field(u32, seqno)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->dev = dev;
+			   __entry->seqno = seqno;
+			   ),
+
+	    TP_printk("dev=%p, seqno=%u", __entry->dev, __entry->seqno)
+);
+
+TRACE_EVENT(i915_gem_request_flush,
+
+	    TP_PROTO(struct drm_device *dev, u32 seqno,
+		     u32 flush_domains, u32 invalidate_domains),
+
+	    TP_ARGS(dev, seqno, flush_domains, invalidate_domains),
+
+	    TP_STRUCT__entry(
+			     __field(struct drm_device *, dev)
+			     __field(u32, seqno)
+			     __field(u32, flush_domains)
+			     __field(u32, invalidate_domains)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->dev = dev;
+			   __entry->seqno = seqno;
+			   __entry->flush_domains = flush_domains;
+			   __entry->invalidate_domains = invalidate_domains;
+			   ),
+
+	    TP_printk("dev=%p, seqno=%u, flush=%04x, invalidate=%04x",
+		      __entry->dev, __entry->seqno,
+		      __entry->flush_domains, __entry->invalidate_domains)
+);
+
+
+TRACE_EVENT(i915_gem_request_complete,
+
+	    TP_PROTO(struct drm_device *dev, u32 seqno),
+
+	    TP_ARGS(dev, seqno),
+
+	    TP_STRUCT__entry(
+			     __field(struct drm_device *, dev)
+			     __field(u32, seqno)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->dev = dev;
+			   __entry->seqno = seqno;
+			   ),
+
+	    TP_printk("dev=%p, seqno=%u", __entry->dev, __entry->seqno)
+);
+
+TRACE_EVENT(i915_gem_request_retire,
+
+	    TP_PROTO(struct drm_device *dev, u32 seqno),
+
+	    TP_ARGS(dev, seqno),
+
+	    TP_STRUCT__entry(
+			     __field(struct drm_device *, dev)
+			     __field(u32, seqno)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->dev = dev;
+			   __entry->seqno = seqno;
+			   ),
+
+	    TP_printk("dev=%p, seqno=%u", __entry->dev, __entry->seqno)
+);
+
+TRACE_EVENT(i915_gem_request_wait_begin,
+
+	    TP_PROTO(struct drm_device *dev, u32 seqno),
+
+	    TP_ARGS(dev, seqno),
+
+	    TP_STRUCT__entry(
+			     __field(struct drm_device *, dev)
+			     __field(u32, seqno)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->dev = dev;
+			   __entry->seqno = seqno;
+			   ),
+
+	    TP_printk("dev=%p, seqno=%u", __entry->dev, __entry->seqno)
+);
+
+TRACE_EVENT(i915_gem_request_wait_end,
+
+	    TP_PROTO(struct drm_device *dev, u32 seqno),
+
+	    TP_ARGS(dev, seqno),
+
+	    TP_STRUCT__entry(
+			     __field(struct drm_device *, dev)
+			     __field(u32, seqno)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->dev = dev;
+			   __entry->seqno = seqno;
+			   ),
+
+	    TP_printk("dev=%p, seqno=%u", __entry->dev, __entry->seqno)
+);
+
+TRACE_EVENT(i915_ring_wait_begin,
+
+	    TP_PROTO(struct drm_device *dev),
+
+	    TP_ARGS(dev),
+
+	    TP_STRUCT__entry(
+			     __field(struct drm_device *, dev)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->dev = dev;
+			   ),
+
+	    TP_printk("dev=%p", __entry->dev)
+);
+
+TRACE_EVENT(i915_ring_wait_end,
+
+	    TP_PROTO(struct drm_device *dev),
+
+	    TP_ARGS(dev),
+
+	    TP_STRUCT__entry(
+			     __field(struct drm_device *, dev)
+			     ),
+
+	    TP_fast_assign(
+			   __entry->dev = dev;
+			   ),
+
+	    TP_printk("dev=%p", __entry->dev)
+);
+
+#endif /* _I915_TRACE_H_ */
+
+/* This part must be outside protection */
+#undef TRACE_INCLUDE_PATH
+#define TRACE_INCLUDE_PATH ../../drivers/gpu/drm/i915
+#include <trace/define_trace.h>

drivers/gpu/drm/i915/i915_trace_points.c

+/*
+ * Copyright © 2009 Intel Corporation
+ *
+ * Authors:
+ *    Chris Wilson <chris@chris-wilson.co.uk>
+ */
+
+#include "i915_drv.h"
+
+#define CREATE_TRACE_POINTS
+#include "i915_trace.h"