video: rockchip: mpp: Add task timing

1. Add mpp device disable flag in procfs

Usage:

echo 1 > /proc/mpp_service/rkvenc-core0/disable
echo 1 > /proc/mpp_service/rkvdec-core0/disable

2. Add task timing record for timeout issue debug.

Usage echo timing threshold to hardware device:

echo 1 > /proc/mpp_service/timing_en
echo 10000 > /proc/mpp_service/rkvenc-core0/timing_check
echo 10000 > /proc/mpp_service/rkvenc-core1/timing_check

Timing log sample:

[ 4889.485698][ T2820] rk_vcodec: task 0 dump timing at 17501 us:
[ 4889.485714][ T2820] rk_vcodec: timing: create         : 4888014063 us
[ 4889.485759][ T2820] rk_vcodec: timing: create end     : 311 us
[ 4889.485769][ T2820] rk_vcodec: timing: pending        : 312 us
[ 4889.485777][ T2820] rk_vcodec: timing: run            : 486 us
[ 4889.485786][ T2820] rk_vcodec: timing: timeout start  : 620 us
[ 4889.485794][ T2820] rk_vcodec: timing: run end        : 682 us
[ 4889.485803][ T2820] rk_vcodec: timing: irq            : 17380 us
[ 4889.485810][ T2820] rk_vcodec: timing: timeout cancel : 17409 us
[ 4889.485819][ T2820] rk_vcodec: timing: isr            : 17438 us
[ 4889.485827][ T2820] rk_vcodec: timing: finish         : 17501 us

Signed-off-by: Herman Chen <herman.chen@rock-chips.com>
Change-Id: I27614c99ad9b48825e56bd5c53a9f089efffe750

drivers/video/rockchip/mpp/mpp_common.c

@@ -485,6 +485,10 @@ mpp_session_push_pending(struct mpp_session *session,
 {
 	kref_get(&task->ref);
 	mutex_lock(&session->pending_lock);
+	if (session->srv->timing_en) {
+		task->on_pending = ktime_get();
+		set_bit(TASK_TIMING_PENDING, &task->state);
+	}
 	list_add_tail(&task->pending_link, &session->pending_list);
 	mutex_unlock(&session->pending_lock);
 
@@ -570,7 +574,10 @@ static void mpp_task_timeout_work(struct work_struct *work_s)
 		return;
 	}
 
+	mpp_task_dump_timing(task, ktime_us_delta(ktime_get(), task->on_create));
+
 	mpp = mpp_get_task_used_device(task, session);
+
 	/* hardware maybe dead, reset it */
 	mpp_reset_up_read(mpp->reset_group);
 	mpp_dev_reset(mpp);
@@ -590,6 +597,8 @@ static int mpp_process_task_default(struct mpp_session *session,
 {
 	struct mpp_task *task = NULL;
 	struct mpp_dev *mpp = session->mpp;
+	u32 timing_en;
+	ktime_t on_create;
 
 	if (unlikely(!mpp)) {
 		mpp_err("pid %d client %d found invalid process function\n",
@@ -597,12 +606,24 @@ static int mpp_process_task_default(struct mpp_session *session,
 		return -EINVAL;
 	}
 
+	timing_en = session->srv->timing_en;
+	if (timing_en)
+		on_create = ktime_get();
+
 	if (mpp->dev_ops->alloc_task)
 		task = mpp->dev_ops->alloc_task(session, msgs);
 	if (!task) {
 		mpp_err("alloc_task failed.\n");
 		return -ENOMEM;
 	}
+
+	if (timing_en) {
+		task->on_create_end = ktime_get();
+		task->on_create = on_create;
+		set_bit(TASK_TIMING_CREATE_END, &task->state);
+		set_bit(TASK_TIMING_CREATE, &task->state);
+	}
+
 	/* ensure current device */
 	mpp = mpp_get_task_used_device(task, session);
 
@@ -734,9 +755,16 @@ static int mpp_task_run(struct mpp_dev *mpp,
 			struct mpp_task *task)
 {
 	int ret;
+	u32 timing_en;
 
 	mpp_debug_enter();
 
+	timing_en = mpp->srv->timing_en;
+	if (timing_en) {
+		task->on_run = ktime_get();
+		set_bit(TASK_TIMING_RUN, &task->state);
+	}
+
 	/*
 	 * before running, we have to switch grf ctrl bit to ensure
 	 * working in current hardware
@@ -767,9 +795,19 @@ static int mpp_task_run(struct mpp_dev *mpp,
 	mpp_time_record(task);
 	schedule_delayed_work(&task->timeout_work,
 			      msecs_to_jiffies(MPP_WORK_TIMEOUT_DELAY));
+
+	if (timing_en) {
+		task->on_sched_timeout = ktime_get();
+		set_bit(TASK_TIMING_TO_SCHED, &task->state);
+	}
+
 	if (mpp->dev_ops->run)
 		mpp->dev_ops->run(mpp, task);
 
+	if (timing_en) {
+		task->on_run_end = ktime_get();
+		set_bit(TASK_TIMING_RUN_END, &task->state);
+	}
 	mpp_debug_leave();
 
 	return 0;
@@ -1889,6 +1927,19 @@ int mpp_task_finish(struct mpp_session *session,
 
 	set_bit(TASK_STATE_FINISH, &task->state);
 	set_bit(TASK_STATE_DONE, &task->state);
+
+	if (session->srv->timing_en) {
+		s64 time_diff;
+
+		task->on_finish = ktime_get();
+		set_bit(TASK_TIMING_FINISH, &task->state);
+
+		time_diff = ktime_us_delta(task->on_finish, task->on_create);
+
+		if (mpp->timing_check && time_diff > (s64)mpp->timing_check)
+			mpp_task_dump_timing(task, time_diff);
+	}
+
 	/* Wake up the GET thread */
 	wake_up(&task->wait);
 	mpp_taskqueue_pop_running(mpp->queue, task);
@@ -2176,6 +2227,12 @@ irqreturn_t mpp_dev_irq(int irq, void *param)
 	struct mpp_dev *mpp = param;
 	struct mpp_task *task = mpp->cur_task;
 	irqreturn_t irq_ret = IRQ_NONE;
+	u32 timing_en = mpp->srv->timing_en;
+
+	if (task && timing_en) {
+		task->on_irq = ktime_get();
+		set_bit(TASK_TIMING_IRQ, &task->state);
+	}
 
 	if (mpp->dev_ops->irq)
 		irq_ret = mpp->dev_ops->irq(mpp);
@@ -2191,6 +2248,10 @@ irqreturn_t mpp_dev_irq(int irq, void *param)
 				irq_ret = IRQ_HANDLED;
 				goto done;
 			}
+			if (timing_en) {
+				task->on_cancel_timeout = ktime_get();
+				set_bit(TASK_TIMING_TO_CANCEL, &task->state);
+			}
 			cancel_delayed_work(&task->timeout_work);
 			/* normal condition, set state and wake up isr thread */
 			set_bit(TASK_STATE_IRQ, &task->state);
@@ -2206,6 +2267,12 @@ irqreturn_t mpp_dev_isr_sched(int irq, void *param)
 {
 	irqreturn_t ret = IRQ_NONE;
 	struct mpp_dev *mpp = param;
+	struct mpp_task *task = mpp->cur_task;
+
+	if (task && mpp->srv->timing_en) {
+		task->on_isr = ktime_get();
+		set_bit(TASK_TIMING_ISR, &task->state);
+	}
 
 	if (mpp->auto_freq_en &&
 	    mpp->hw_ops->reduce_freq &&
@@ -2290,6 +2357,33 @@ int mpp_time_diff(struct mpp_task *task)
 	return 0;
 }
 
+#define LOG_TIMING(state, id, stage, time, base) \
+	do { \
+		if (test_bit(id, &state)) \
+			pr_info("timing: %-14s : %lld us\n", stage, ktime_us_delta(time, base)); \
+		else \
+			pr_info("timing: %-14s : invalid\n", stage); \
+	} while (0)
+
+void mpp_task_dump_timing(struct mpp_task *task, s64 time_diff)
+{
+	ktime_t s = task->on_create;
+	unsigned long state = task->state;
+
+	pr_info("task %d dump timing at %lld us:", task->task_id, time_diff);
+
+	pr_info("timing: %-14s : %lld us\n", "create", ktime_to_us(s));
+	LOG_TIMING(state, TASK_TIMING_CREATE_END, "create end",     task->on_create_end, s);
+	LOG_TIMING(state, TASK_TIMING_PENDING,    "pending",        task->on_pending, s);
+	LOG_TIMING(state, TASK_TIMING_RUN,        "run",            task->on_run, s);
+	LOG_TIMING(state, TASK_TIMING_TO_SCHED,   "timeout start",  task->on_sched_timeout, s);
+	LOG_TIMING(state, TASK_TIMING_RUN_END,    "run end",        task->on_run_end, s);
+	LOG_TIMING(state, TASK_TIMING_IRQ,        "irq",            task->on_irq, s);
+	LOG_TIMING(state, TASK_TIMING_TO_CANCEL,  "timeout cancel", task->on_cancel_timeout, s);
+	LOG_TIMING(state, TASK_TIMING_ISR,        "isr",            task->on_isr, s);
+	LOG_TIMING(state, TASK_TIMING_FINISH,     "finish",         task->on_finish, s);
+}
+
 int mpp_write_req(struct mpp_dev *mpp, u32 *regs,
 		  u32 start_idx, u32 end_idx, u32 en_idx)
 {
@@ -2470,4 +2564,10 @@ mpp_procfs_create_u32(const char *name, umode_t mode,
 {
 	return proc_create_data(name, mode, parent, &procfs_fops_u32, data);
 }
+
+void mpp_procfs_create_common(struct proc_dir_entry *parent, struct mpp_dev *mpp)
+{
+	mpp_procfs_create_u32("disable_work", 0644, parent, &mpp->disable);
+	mpp_procfs_create_u32("timing_check", 0644, parent, &mpp->timing_check);
+}
 #endif

drivers/video/rockchip/mpp/mpp_common.h

@@ -358,6 +358,10 @@ struct mpp_dev {
 	/* multi-core data */
 	struct list_head queue_link;
 	s32 core_id;
+
+	/* common per-device procfs */
+	u32 disable;
+	u32 timing_check;
 };
 
 struct mpp_session {
@@ -421,6 +425,18 @@ enum mpp_task_state {
 	TASK_STATE_ABORT	= 9,
 	TASK_STATE_ABORT_READY	= 10,
 	TASK_STATE_PROC_DONE	= 11,
+
+	/* timing debug state */
+	TASK_TIMING_CREATE	= 16,
+	TASK_TIMING_CREATE_END	= 17,
+	TASK_TIMING_PENDING	= 18,
+	TASK_TIMING_RUN		= 19,
+	TASK_TIMING_TO_SCHED	= 20,
+	TASK_TIMING_RUN_END	= 21,
+	TASK_TIMING_IRQ		= 22,
+	TASK_TIMING_TO_CANCEL	= 23,
+	TASK_TIMING_ISR		= 24,
+	TASK_TIMING_FINISH	= 25,
 };
 
 /* The context for the a task */
@@ -449,6 +465,19 @@ struct mpp_task {
 	/* record context running start time */
 	ktime_t start;
 	ktime_t part;
+
+	/* debug timing */
+	ktime_t on_create;
+	ktime_t on_create_end;
+	ktime_t on_pending;
+	ktime_t on_run;
+	ktime_t on_sched_timeout;
+	ktime_t on_run_end;
+	ktime_t on_irq;
+	ktime_t on_cancel_timeout;
+	ktime_t on_isr;
+	ktime_t on_finish;
+
 	/* hardware info for current task */
 	struct mpp_hw_info *hw_info;
 	u32 task_index;
@@ -540,6 +569,9 @@ struct mpp_service {
 	struct mutex session_lock;
 	struct list_head session_list;
 	u32 session_count;
+
+	/* global timing record flag */
+	u32 timing_en;
 };
 
 /*
@@ -637,6 +669,8 @@ int mpp_task_dump_mem_region(struct mpp_dev *mpp,
 int mpp_task_dump_reg(struct mpp_dev *mpp,
 		      struct mpp_task *task);
 int mpp_task_dump_hw_reg(struct mpp_dev *mpp);
+void mpp_task_dump_timing(struct mpp_task *task, s64 time_diff);
+
 void mpp_reg_show(struct mpp_dev *mpp, u32 offset);
 void mpp_free_task(struct kref *ref);
 
@@ -814,6 +848,7 @@ mpp_get_task_used_device(const struct mpp_task *task,
 struct proc_dir_entry *
 mpp_procfs_create_u32(const char *name, umode_t mode,
 		      struct proc_dir_entry *parent, void *data);
+void mpp_procfs_create_common(struct proc_dir_entry *parent, struct mpp_dev *mpp);
 #else
 static inline struct proc_dir_entry *
 mpp_procfs_create_u32(const char *name, umode_t mode,
@@ -821,6 +856,9 @@ mpp_procfs_create_u32(const char *name, umode_t mode,
 {
 	return 0;
 }
+void mpp_procfs_create_common(struct proc_dir_entry *parent, struct mpp_dev *mpp)
+{
+}
 #endif
 
 #ifdef CONFIG_ROCKCHIP_MPP_PROC_FS

drivers/video/rockchip/mpp/mpp_rkvdec2.c

@@ -631,6 +631,10 @@ static int rkvdec2_procfs_init(struct mpp_dev *mpp)
 		dec->procfs = NULL;
 		return -EIO;
 	}
+
+	/* for common mpp_dev options */
+	mpp_procfs_create_common(dec->procfs, mpp);
+
 	mpp_procfs_create_u32("aclk", 0644,
 			      dec->procfs, &dec->aclk_info.debug_rate_hz);
 	mpp_procfs_create_u32("clk_core", 0644,
@@ -645,8 +649,6 @@ static int rkvdec2_procfs_init(struct mpp_dev *mpp)
 			   dec->procfs, rkvdec2_show_pref_sel_offset);
 	mpp_procfs_create_u32("task_count", 0644,
 			      dec->procfs, &mpp->task_index);
-	mpp_procfs_create_u32("disable_work", 0644,
-			      dec->procfs, &dec->disable_work);
 
 	return 0;
 }

drivers/video/rockchip/mpp/mpp_rkvdec2.h

@@ -199,7 +199,6 @@ struct rkvdec2_dev {
 	/* for ccu link mode */
 	struct rkvdec2_ccu *ccu;
 	u32 core_mask;
-	bool disable_work;
 	u32 task_index;
 };
 

drivers/video/rockchip/mpp/mpp_rkvdec2_link.c

@@ -1683,7 +1683,7 @@ static int rkvdec2_soft_ccu_reset(struct mpp_taskqueue *queue,
 		struct mpp_dev *mpp = queue->cores[i];
 		struct rkvdec2_dev *dec = to_rkvdec2_dev(mpp);
 
-		if (dec->disable_work)
+		if (mpp->disable)
 			continue;
 
 		dev_info(mpp->dev, "resetting...\n");
@@ -1861,9 +1861,10 @@ static struct mpp_dev *rkvdec2_get_idle_core(struct mpp_taskqueue *queue,
 	struct rkvdec2_dev *dec = NULL;
 
 	for (i = 0; i < queue->core_count; i++) {
-		struct rkvdec2_dev *core = to_rkvdec2_dev(queue->cores[i]);
+		struct mpp_dev *mpp = queue->cores[i];
+		struct rkvdec2_dev *core = to_rkvdec2_dev(mpp);
 
-		if (core->disable_work)
+		if (mpp->disable)
 			continue;
 
 		if (test_bit(i, &queue->core_idle)) {
@@ -1892,13 +1893,13 @@ static struct mpp_dev *rkvdec2_get_idle_core(struct mpp_taskqueue *queue,
 
 static bool rkvdec2_core_working(struct mpp_taskqueue *queue)
 {
-	u32 i = 0;
-	struct rkvdec2_dev *core;
+	struct mpp_dev *mpp;
 	bool flag = false;
+	u32 i = 0;
 
 	for (i = 0; i < queue->core_count; i++) {
-		core = to_rkvdec2_dev(queue->cores[i]);
-		if (core->disable_work)
+		mpp = queue->cores[i];
+		if (mpp->disable)
 			continue;
 		if (!test_bit(i, &queue->core_idle)) {
 			flag = true;

drivers/video/rockchip/mpp/mpp_rkvenc2.c

@@ -263,7 +263,6 @@ struct rkvenc_dev {
 	/* for ccu */
 	struct rkvenc_ccu *ccu;
 	struct list_head core_link;
-	u32 disable_work;
 
 	/* internal rcb-memory */
 	u32 sram_size;
@@ -818,7 +817,7 @@ static void *rkvenc2_prepare(struct mpp_dev *mpp, struct mpp_task *mpp_task)
 	for (i = 0; i < core_id_max; i++) {
 		struct mpp_dev *mpp = queue->cores[i];
 
-		if (mpp && to_rkvenc_dev(mpp)->disable_work)
+		if (mpp && mpp->disable)
 			clear_bit(i, &core_idle);
 	}
 
@@ -1182,6 +1181,7 @@ static int rkvenc_isr(struct mpp_dev *mpp)
 
 		mpp_task_dump_hw_reg(mpp);
 	}
+
 	mpp_task_finish(mpp_task->session, mpp_task);
 
 	core_idle = queue->core_idle;
@@ -1435,6 +1435,10 @@ static int rkvenc_procfs_init(struct mpp_dev *mpp)
 		enc->procfs = NULL;
 		return -EIO;
 	}
+
+	/* for common mpp_dev options */
+	mpp_procfs_create_common(enc->procfs, mpp);
+
 	/* for debug */
 	mpp_procfs_create_u32("aclk", 0644,
 			      enc->procfs, &enc->aclk_info.debug_rate_hz);
@@ -1445,8 +1449,6 @@ static int rkvenc_procfs_init(struct mpp_dev *mpp)
 	/* for show session info */
 	proc_create_single_data("sessions-info", 0444,
 				enc->procfs, rkvenc_show_session_info, mpp);
-	mpp_procfs_create_u32("disable_work", 0644,
-			      enc->procfs, &enc->disable_work);
 
 	return 0;
 }

drivers/video/rockchip/mpp/mpp_service.c

@@ -334,6 +334,7 @@ static int mpp_procfs_init(struct mpp_service *srv)
 	/* show support devices */
 	proc_create_single_data("supports-device", 0444,
 				srv->procfs, mpp_show_support_device, srv);
+	mpp_procfs_create_u32("timing_en", 0644, srv->procfs, &srv->timing_en);
 
 	return 0;
 }