drm/msm: add event log for profiling msm drm driver events

Provide highspeed lockless logging facility for profiling time
sensitive events in the drm msm driver. Registers with debugfs
as evtlog. Can be cleared with echo 0.

Change-Id: I6b8887b5fa2172ce38dced86128f4ba84b1a58f1
Signed-off-by: Lloyd Atkinson <latkinso@codeaurora.org>

7 files changed, 293 insertions, 2 deletions

diff --git a/drivers/gpu/drm/msm/Makefile b/drivers/gpu/drm/msm/Makefile
index f30d03615ba6..f5dae4af632d 100644
--- a/drivers/gpu/drm/msm/Makefile
+++ b/drivers/gpu/drm/msm/Makefile
@@ -58,7 +58,8 @@ msm-y := \
 	msm_smmu.o \
 	msm_perf.o \
 	msm_rd.o \
-	msm_ringbuffer.o
+	msm_ringbuffer.o \
+	msm_evtlog.o \
 
 msm-$(CONFIG_DRM_FBDEV_EMULATION) += msm_fbdev.o
 msm-$(CONFIG_SYNC) += sde/sde_fence.o
diff --git a/drivers/gpu/drm/msm/msm_drv.h b/drivers/gpu/drm/msm/msm_drv.h
index 50bbc95af9f6..189e1be9e675 100644
--- a/drivers/gpu/drm/msm/msm_drv.h
+++ b/drivers/gpu/drm/msm/msm_drv.h
@@ -48,6 +48,8 @@
 #include <drm/msm_drm.h>
 #include <drm/drm_gem.h>
 
+#include "msm_evtlog.h"
+
 struct msm_kms;
 struct msm_gpu;
 struct msm_mmu;
@@ -178,6 +180,8 @@ struct msm_drm_private {
 	} vram;
 
 	struct msm_vblank_ctrl vblank_ctrl;
+
+	struct msm_evtlog evtlog;
 };
 
 struct msm_format {
diff --git a/drivers/gpu/drm/msm/msm_evtlog.c b/drivers/gpu/drm/msm/msm_evtlog.c
new file mode 100644
index 000000000000..a07e0b53db8f
--- /dev/null
+++ b/drivers/gpu/drm/msm/msm_evtlog.c
@@ -0,0 +1,172 @@
+/* Copyright (c) 2016, The Linux Foundation. All rights reserved.
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License version 2 and
+ * only version 2 as published by the Free Software Foundation.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ */
+
+#define pr_fmt(fmt)	"msm_evtlog:[%s] " fmt, __func__
+
+#include "msm_evtlog.h"
+#include <linux/slab.h>
+#include <linux/sched.h>
+#include <asm-generic/current.h>
+#include <linux/uaccess.h>
+#include <linux/debugfs.h>
+
+#define SIZE_MASK(x) (x - 1)
+
+static int msm_evtlog_debugfs_dump(struct seq_file *s, void *data)
+{
+	struct msm_evtlog *log = s->private;
+	unsigned long cnt;	/* # of samples since clear */
+	unsigned long n;	/* # of samples to print, also head index */
+	unsigned long i;
+	struct timespec timespec;
+
+	/**
+	 * Prints in chronological order, oldest -> newest
+	 * Note due to lock-less design, the first few printed entries
+	 * may be corrupted by new writer not oldest.
+	 * This is a tradeoff for speed of sampling
+	 */
+	cnt = atomic_read(&log->cnt);
+	if (!cnt)
+		return 0;
+
+	n = cnt & SIZE_MASK(log->size);
+
+	/**
+	 * If not full, print from first log
+	 * (which is index 1 since atomic_inc_return is prefix operator)
+	 */
+	i = (cnt < log->size) ? 0 : n;
+
+	seq_puts(s, "time_ns, pid, func, line, val1, val2, msg\n");
+	do {
+		i = (i + 1) & SIZE_MASK(log->size);
+		timespec = ktime_to_timespec(log->events[i].ktime);
+		seq_printf(s, "[%5lu.%06lu], %d, %s, %d, %llu, %llu, %s\n",
+				timespec.tv_sec,
+				timespec.tv_nsec / 1000,
+				log->events[i].pid,
+				log->events[i].func,
+				log->events[i].line,
+				log->events[i].val1,
+				log->events[i].val2,
+				log->events[i].msg);
+	} while (i != n);
+
+	return 0;
+}
+
+static int msm_evtlog_debugfs_open_dump(struct inode *inode, struct file *file)
+{
+	return single_open(file, msm_evtlog_debugfs_dump, inode->i_private);
+}
+
+static ssize_t msm_evtlog_debugfs_write(
+		struct file *file,
+		const char __user *user_buf,
+		size_t size,
+		loff_t *ppos)
+{
+	struct seq_file *s = file->private_data;
+	struct msm_evtlog *log = s->private;
+	char buf[64];
+	int buf_size;
+
+	buf_size = min(size, (sizeof(buf) - 1));
+	if (strncpy_from_user(buf, user_buf, buf_size) < 0)
+		return -EFAULT;
+	buf[buf_size] = 0;
+
+	if (strcmp(buf, "0") == 0)
+		atomic_set(&log->cnt, 0);
+
+	return size;
+
+}
+
+static const struct file_operations msm_evtlog_fops = {
+	.open =		msm_evtlog_debugfs_open_dump,
+	.read =		seq_read,
+	.write =	msm_evtlog_debugfs_write,
+	.llseek =	seq_lseek,
+	.release =	single_release,
+};
+
+int msm_evtlog_init(
+		struct msm_evtlog *log,
+		int size,
+		struct dentry *parent)
+{
+	if (!log || size < 1) {
+		pr_err("Invalid params\n");
+		return -EINVAL;
+	}
+
+	memset(log, 0, sizeof(*log));
+	log->size = roundup_pow_of_two(size);
+	log->events = kcalloc(log->size, sizeof(struct msm_evtlog_evt),
+			GFP_KERNEL);
+
+	if (!log->events) {
+		pr_err("Insufficient memory\n");
+		return -ENOMEM;
+	}
+
+	atomic_set(&log->cnt, 0);
+
+	log->dentry = debugfs_create_file("evtlog", S_IRUGO | S_IWUSR, parent,
+			log, &msm_evtlog_fops);
+
+	if (IS_ERR_OR_NULL(log->dentry)) {
+		int rc = PTR_ERR(log->dentry);
+
+		pr_err("debugfs create file failed, rc=%d\n", rc);
+		kfree(log->events);
+		return rc;
+	}
+
+	return 0;
+}
+
+void msm_evtlog_destroy(struct msm_evtlog *log)
+{
+	debugfs_remove(log->dentry);
+
+	/* Caller needs to make sure that log sampling has stopped */
+	kfree(log->events);
+
+}
+
+void msm_evtlog_sample(
+		struct msm_evtlog *log,
+		const char *func,
+		const char *msg,
+		uint64_t val1,
+		uint64_t val2,
+		uint32_t line)
+{
+	unsigned long i;
+
+	/**
+	 * Since array sized with pow of 2, roll to 0 when cnt overflows
+	 * mod the value with the size to get current idx into array
+	 */
+	i = (unsigned long)(atomic_inc_return(&log->cnt)) &
+			SIZE_MASK(log->size);
+	log->events[i].ktime = ktime_get();
+	log->events[i].func = func;
+	log->events[i].msg = msg;
+	log->events[i].val1 = val1;
+	log->events[i].val2 = val2;
+	log->events[i].line = line;
+	log->events[i].pid = current->pid;
+}
diff --git a/drivers/gpu/drm/msm/msm_evtlog.h b/drivers/gpu/drm/msm/msm_evtlog.h
new file mode 100644
index 000000000000..15b5e961eff7
--- /dev/null
+++ b/drivers/gpu/drm/msm/msm_evtlog.h
@@ -0,0 +1,102 @@
+/* Copyright (c) 2016, The Linux Foundation. All rights reserved.
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License version 2 and
+ * only version 2 as published by the Free Software Foundation.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ */
+
+#ifndef MSM_MSM_EVTLOG_H_
+#define MSM_MSM_EVTLOG_H_
+
+#include <linux/ktime.h>
+#include <linux/atomic.h>
+#include <linux/dcache.h>
+
+/**
+ * struct msm_evtlog_evt - Event log entry
+ * @ktime:     Timestamp of event
+ * @func:      Calling function name
+ * @msg:       User provided string
+ * @val1:      User provided value
+ * @val2:      User provided value
+ * @line:      Line number of caller
+ * @pid:       Process id of logger
+ */
+struct msm_evtlog_evt {
+	ktime_t ktime;
+	const char *func;
+	const char *msg;
+	uint64_t val1;
+	uint64_t val2;
+	uint32_t line;
+	uint32_t pid;
+};
+
+/**
+ * struct msm_evtlog - current driver state information
+ * @events:    Pointer to dynamically allocated event log buffer
+ * @cnt:       Atomic number of events since clear. Can be used to calculate
+ *             the current index. Note: The count does not wrap.
+ *             Reset the event log by setting to zero.
+ *             Used for lock-less producer synchronization.
+ * @size:      Size of events array. Must be power of 2 to facilitate fast
+ *             increments by using a bitmask to get rollover.
+ * @dentry:    Filesystem entry of debugfs registration
+ */
+struct msm_evtlog {
+	struct msm_evtlog_evt *events;
+	atomic_t cnt;
+	unsigned long size;
+	struct dentry *dentry;
+};
+
+/**
+ * msm_evtlog_init() - Create an event log, registered with debugfs.
+ * @log:     Event log handle
+ * @size:    Max # of events in buffer. Will be rounded up to power of 2.
+ * @parent:  Parent directory entry for debugfs registration
+ *
+ * Return: error code.
+ */
+int msm_evtlog_init(struct msm_evtlog *log, int size, struct dentry *parent);
+
+/**
+ * msm_evtlog_destroy() - Destroy event log
+ * @log:            Event log handle
+ *
+ * Unregisters debugfs node and frees memory.
+ * Caller needs to make sure that log sampling has stopped.
+ */
+void msm_evtlog_destroy(struct msm_evtlog *log);
+
+/**
+ * msm_evtlog_sample() - Add entry to the event log
+ * @evtlog:            Event log handle
+ * @func:              Calling function name
+ * @msg:               User provided string
+ * @val1:              User provided value
+ * @val2:              User provided value
+ * @line:              Line number of caller
+ */
+void msm_evtlog_sample(
+		struct msm_evtlog *log,
+		const char *func,
+		const char *msg,
+		uint64_t val1,
+		uint64_t val2,
+		uint32_t line);
+
+/**
+ * Helper macros
+ */
+#define MSM_EVT_MSG(log, msg, x, y) ( \
+		msm_evtlog_sample((log), __func__, (msg), \
+			((uint64_t) x), (uint64_t)(y), __LINE__))
+#define MSM_EVT(log, x, y) MSM_EVT_MSG((log), 0, (x), (y))
+
+#endif /* MSM_MSM_EVTLOG_H_ */
diff --git a/drivers/gpu/drm/msm/sde/sde_crtc.c b/drivers/gpu/drm/msm/sde/sde_crtc.c
index f1f5d415a496..5705d6b8e29e 100644
--- a/drivers/gpu/drm/msm/sde/sde_crtc.c
+++ b/drivers/gpu/drm/msm/sde/sde_crtc.c
@@ -362,6 +362,7 @@ static void sde_crtc_vblank_cb(void *data)
 	struct sde_crtc *sde_crtc = to_sde_crtc(crtc);
 	struct sde_kms *sde_kms = get_kms(crtc);
 	struct drm_device *dev = sde_kms->dev;
+	struct msm_drm_private *priv = dev->dev_private;
 	unsigned pending;
 
 	pending = atomic_xchg(&sde_crtc->pending, 0);
@@ -372,6 +373,7 @@ static void sde_crtc_vblank_cb(void *data)
 	if (sde_crtc->drm_requested_vblank) {
 		drm_handle_vblank(dev, sde_crtc->id);
 		DBG_IRQ("");
+		MSM_EVT(&priv->evtlog, sde_crtc->id, 0);
 	}
 }
 
diff --git a/drivers/gpu/drm/msm/sde/sde_encoder.c b/drivers/gpu/drm/msm/sde/sde_encoder.c
index 55c200d9707d..69b2206f47ca 100644
--- a/drivers/gpu/drm/msm/sde/sde_encoder.c
+++ b/drivers/gpu/drm/msm/sde/sde_encoder.c
@@ -27,6 +27,10 @@
 #define MAX_PHYS_ENCODERS_PER_VIRTUAL \
 	(MAX_H_TILES_PER_DISPLAY * NUM_PHYS_ENCODER_TYPES)
 
+#define EVTLOG(enc) (!enc ? NULL : \
+		!enc->base.dev ? NULL : \
+		&((struct msm_drm_private *)enc->base.dev->dev_private)->evtlog)
+
 /**
  * struct sde_encoder_virt - virtual encoder. Container of one or more physical
  *	encoders. Virtual encoder manages one "logical" display. Physical
@@ -205,6 +209,7 @@ static bool sde_encoder_virt_mode_fixup(struct drm_encoder *drm_enc,
 	}
 
 	sde_enc = to_sde_encoder_virt(drm_enc);
+	MSM_EVT(EVTLOG(sde_enc), 0, 0);
 
 	for (i = 0; i < sde_enc->num_phys_encs; i++) {
 		struct sde_encoder_phys *phys = sde_enc->phys_encs[i];
@@ -226,6 +231,8 @@ static bool sde_encoder_virt_mode_fixup(struct drm_encoder *drm_enc,
 	/* Call to populate mode->crtc* information required by framework */
 	drm_mode_set_crtcinfo(adj_mode, 0);
 
+	MSM_EVT(EVTLOG(sde_enc), adj_mode->flags, adj_mode->private_flags);
+
 	return ret;
 }
 
@@ -244,6 +251,7 @@ static void sde_encoder_virt_mode_set(struct drm_encoder *drm_enc,
 	}
 
 	sde_enc = to_sde_encoder_virt(drm_enc);
+	MSM_EVT(EVTLOG(sde_enc), 0, 0);
 
 	for (i = 0; i < sde_enc->num_phys_encs; i++) {
 		struct sde_encoder_phys *phys = sde_enc->phys_encs[i];
@@ -272,6 +280,7 @@ static void sde_encoder_virt_enable(struct drm_encoder *drm_enc)
 	}
 
 	sde_enc = to_sde_encoder_virt(drm_enc);
+	MSM_EVT(EVTLOG(sde_enc), 0, 0);
 
 	bs_set(sde_enc, 1);
 
@@ -308,6 +317,7 @@ static void sde_encoder_virt_disable(struct drm_encoder *drm_enc)
 	}
 
 	sde_enc = to_sde_encoder_virt(drm_enc);
+	MSM_EVT(EVTLOG(sde_enc), 0, 0);
 
 	for (i = 0; i < sde_enc->num_phys_encs; i++) {
 		struct sde_encoder_phys *phys = sde_enc->phys_encs[i];
diff --git a/drivers/gpu/drm/msm/sde/sde_kms.c b/drivers/gpu/drm/msm/sde/sde_kms.c
index 7a25ffa56bcf..c45e6c4ee732 100644
--- a/drivers/gpu/drm/msm/sde/sde_kms.c
+++ b/drivers/gpu/drm/msm/sde/sde_kms.c
@@ -581,7 +581,7 @@ struct msm_kms *sde_kms_init(struct drm_device *dev)
 	sde_debugfs_init(sde_kms);
 	msm_evtlog_init(&priv->evtlog, SDE_EVTLOG_SIZE,
 			sde_debugfs_get_root(sde_kms));
-	MSM_EVT(dev, 0, 0);
+	MSM_EVT(&priv->evtlog, 0, 0);
 
 	/*
 	 * modeset_init should create the DRM related objects i.e. CRTCs,