video: driver: add buffer statistics logic

Added change to print etb, ebd, ftb, fbd,
(ebd-etb), (fbd - etb), (etb-ftb) wallclock
time in ms.

It will help to debug perf issues.

Change-Id: Ideaecb2d51763711d6628729aa0f9056d05f0d51
Signed-off-by: Govindaraj Rajagopal <quic_grajagop@quicinc.com>

driver/vidc/inc/msm_vidc_debug.h

@@ -64,6 +64,7 @@ enum vidc_msg_prio {
 	VIDC_PERF       = 0x00000008,
 	VIDC_PKT        = 0x00000010,
 	VIDC_BUS        = 0x00000020,
+	VIDC_STAT       = 0x00000040,
 	VIDC_ENCODER    = 0x00000100,
 	VIDC_DECODER    = 0x00000200,
 	VIDC_PRINTK     = 0x00001000,
@@ -97,9 +98,12 @@ enum vidc_msg_prio {
 #define i_vpr_p(inst, __fmt, ...) dprintk_inst(VIDC_PERF, "perf", inst, __fmt, ##__VA_ARGS__)
 #define i_vpr_t(inst, __fmt, ...) dprintk_inst(VIDC_PKT,  "pkt ", inst, __fmt, ##__VA_ARGS__)
 #define i_vpr_b(inst, __fmt, ...) dprintk_inst(VIDC_BUS,  "bus ", inst, __fmt, ##__VA_ARGS__)
+#define i_vpr_s(inst, __fmt, ...) dprintk_inst(VIDC_STAT, "stat", inst, __fmt, ##__VA_ARGS__)
 
 #define i_vpr_hp(inst, __fmt, ...) \
 	dprintk_inst(VIDC_HIGH | VIDC_PERF, "high", inst, __fmt, ##__VA_ARGS__)
+#define i_vpr_hs(inst, __fmt, ...) \
+	dprintk_inst(VIDC_HIGH | VIDC_STAT, "high", inst, __fmt, ##__VA_ARGS__)
 
 #define dprintk_core(__level, __level_str, __fmt, ...) \
 	do { \
@@ -118,6 +122,7 @@ enum vidc_msg_prio {
 #define d_vpr_p(__fmt, ...) dprintk_core(VIDC_PERF, "perf", __fmt, ##__VA_ARGS__)
 #define d_vpr_t(__fmt, ...) dprintk_core(VIDC_PKT,  "pkt ", __fmt, ##__VA_ARGS__)
 #define d_vpr_b(__fmt, ...) dprintk_core(VIDC_BUS,  "bus ", __fmt, ##__VA_ARGS__)
+#define d_vpr_s(__fmt, ...) dprintk_core(VIDC_STAT, "stat", __fmt, ##__VA_ARGS__)
 
 #define dprintk_ratelimit(__level, __level_str, __fmt, ...) \
 	do { \

driver/vidc/inc/msm_vidc_driver.h

@@ -585,6 +585,11 @@ int msm_vidc_get_properties(struct msm_vidc_inst *inst);
 int msm_vidc_create_input_metadata_buffer(struct msm_vidc_inst *inst, int buf_fd);
 int msm_vidc_update_input_meta_buffer_index(struct msm_vidc_inst *inst, struct vb2_buffer *vb2);
 int msm_vidc_update_input_rate(struct msm_vidc_inst *inst, u64 time_us);
+int msm_vidc_add_buffer_stats(struct msm_vidc_inst *inst,
+	struct msm_vidc_buffer *buf);
+int msm_vidc_remove_buffer_stats(struct msm_vidc_inst *inst,
+	struct msm_vidc_buffer *buf);
+int msm_vidc_flush_buffer_stats(struct msm_vidc_inst *inst);
 int msm_vidc_get_input_rate(struct msm_vidc_inst *inst);
 int msm_vidc_get_frame_rate(struct msm_vidc_inst *inst);
 int msm_vidc_get_operating_rate(struct msm_vidc_inst *inst);

driver/vidc/inc/msm_vidc_inst.h

@@ -163,6 +163,7 @@ struct msm_vidc_inst {
 	struct list_head                   firmware_list; /* struct msm_vidc_inst_cap_entry */
 	struct list_head                   pending_pkts; /* list of struct hfi_pending_packet */
 	struct list_head                   fence_list; /* list of struct msm_vidc_fence */
+	struct list_head                   buffer_stats_list; /* struct msm_vidc_buffer_stats */
 	bool                               once_per_session_set;
 	bool                               ipsc_properties_set;
 	bool                               opsc_properties_set;
@@ -175,6 +176,7 @@ struct msm_vidc_inst {
 	struct msm_vidc_fence_context      fence_context;
 	bool                               active;
 	u64                                last_qbuf_time_ns;
+	u64                                initial_time_us;
 	bool                               vb2q_init;
 	u32                                max_input_data_size;
 	u32                                dpb_list_payload[MAX_DPB_LIST_ARRAY_SIZE];

driver/vidc/inc/msm_vidc_internal.h

@@ -903,6 +903,8 @@ struct msm_vidc_buffer {
 	u64                                timestamp;
 	enum msm_vidc_buffer_attributes    attr;
 	u64                                fence_id;
+	u32                                start_time_ms;
+	u32                                end_time_ms;
 };
 
 struct msm_vidc_buffers {
@@ -914,6 +916,24 @@ struct msm_vidc_buffers {
 	bool                   reuse;
 };
 
+struct msm_vidc_buffer_stats {
+	struct list_head                   list;
+	u32                                frame_num;
+	u64                                timestamp;
+	u32                                etb_time_ms;
+	u32                                ebd_time_ms;
+	u32                                ftb_time_ms;
+	u32                                fbd_time_ms;
+	u32                                data_size;
+	u32                                flags;
+};
+
+enum msm_vidc_buffer_stats_flag {
+	MSM_VIDC_STATS_FLAG_CORRUPT     = BIT(0),
+	MSM_VIDC_STATS_FLAG_OVERFLOW    = BIT(1),
+	MSM_VIDC_STATS_FLAG_NO_OUTPUT   = BIT(2),
+};
+
 struct msm_vidc_sort {
 	struct list_head       list;
 	s64                    val;

driver/vidc/inc/msm_vidc_memory.h

@@ -27,6 +27,7 @@ enum msm_memory_pool_type {
 	MSM_MEM_POOL_DMABUF,
 	MSM_MEM_POOL_PACKET,
 	MSM_MEM_POOL_BUF_TIMER,
+	MSM_MEM_POOL_BUF_STATS,
 	MSM_MEM_POOL_MAX,
 };
 

driver/vidc/src/msm_vdec.c

@@ -1881,6 +1881,8 @@ static int msm_vdec_qbuf_batch(struct msm_vidc_inst *inst,
 	if (!buf)
 		return -EINVAL;
 
+	msm_vidc_add_buffer_stats(inst, buf);
+
 	allow = msm_vidc_allow_qbuf(inst, vb2->type);
 	if (allow == MSM_VIDC_DISALLOW) {
 		i_vpr_e(inst, "%s: qbuf not allowed\n", __func__);

driver/vidc/src/msm_vidc.c

@@ -897,6 +897,7 @@ void *msm_vidc_open(void *vidc_core, u32 session_type)
 	inst->opsc_properties_set = false;
 	inst->has_bframe = false;
 	inst->auto_framerate = DEFAULT_FPS << 16;
+	inst->initial_time_us = ktime_get_ns() / 1000;
 	kref_init(&inst->kref);
 	mutex_init(&inst->lock);
 	mutex_init(&inst->request_lock);
@@ -957,6 +958,7 @@ void *msm_vidc_open(void *vidc_core, u32 session_type)
 	INIT_LIST_HEAD(&inst->input_timer_list);
 	INIT_LIST_HEAD(&inst->pending_pkts);
 	INIT_LIST_HEAD(&inst->fence_list);
+	INIT_LIST_HEAD(&inst->buffer_stats_list);
 	for (i = 0; i < MAX_SIGNAL; i++)
 		init_completion(&inst->completions[i]);
 

driver/vidc/src/msm_vidc_driver.c

@@ -481,6 +481,25 @@ void print_vb2_buffer(const char *str, struct msm_vidc_inst *inst,
 	}
 }
 
+static void print_buffer_stats(u32 tag, const char *tag_str, struct msm_vidc_inst *inst,
+		struct msm_vidc_buffer_stats *stats)
+{
+	if (!tag_str || !inst || !stats)
+		return;
+
+	/* skip flushed buffer stats */
+	if (!stats->etb_time_ms || !stats->ebd_time_ms ||
+	    !stats->ftb_time_ms || !stats->fbd_time_ms)
+		return;
+
+	dprintk_inst(tag, tag_str, inst,
+		"f.no %4u ts %16llu (etb ebd ftb fbd)ms %6u %6u %6u %6u (ebd-etb fbd-etb etb-ftb)ms %4d %4d %4d size %8u attr %#x\n",
+		stats->frame_num, stats->timestamp, stats->etb_time_ms, stats->ebd_time_ms,
+		stats->ftb_time_ms, stats->fbd_time_ms, stats->ebd_time_ms - stats->etb_time_ms,
+		stats->fbd_time_ms - stats->etb_time_ms, stats->etb_time_ms - stats->ftb_time_ms,
+		stats->data_size, stats->flags);
+}
+
 static void __fatal_error(bool fatal)
 {
 	WARN_ON(fatal);
@@ -498,6 +517,135 @@ static int __strict_check(struct msm_vidc_core *core, const char *function)
 	return fatal ? -EINVAL : 0;
 }
 
+static u32 msm_vidc_get_buffer_stats_flag(struct msm_vidc_inst *inst)
+{
+	u32 flags = 0;
+
+	if (inst->hfi_frame_info.data_corrupt)
+		flags |= MSM_VIDC_STATS_FLAG_CORRUPT;
+
+	if (inst->hfi_frame_info.overflow)
+		flags |= MSM_VIDC_STATS_FLAG_OVERFLOW;
+
+	if (inst->hfi_frame_info.no_output)
+		flags |= MSM_VIDC_STATS_FLAG_NO_OUTPUT;
+
+	return flags;
+}
+
+int msm_vidc_add_buffer_stats(struct msm_vidc_inst *inst,
+	struct msm_vidc_buffer *buf)
+{
+	struct msm_vidc_buffer_stats *stats = NULL;
+
+	if (!inst || !buf) {
+		d_vpr_e("%s: invalid params\n", __func__);
+		return -EINVAL;
+	}
+
+	/* stats applicable only to input & output buffers */
+	if (buf->type != MSM_VIDC_BUF_INPUT && buf->type != MSM_VIDC_BUF_OUTPUT)
+		return -EINVAL;
+
+	/* update start timestamp */
+	buf->start_time_ms = (ktime_get_ns() / 1000 - inst->initial_time_us) / 1000;
+
+	/* add buffer stats only in ETB path */
+	if (buf->type != MSM_VIDC_BUF_INPUT)
+		return 0;
+
+	stats = msm_memory_pool_alloc(inst, MSM_MEM_POOL_BUF_STATS);
+	if (!stats)
+		return -ENOMEM;
+	INIT_LIST_HEAD(&stats->list);
+	list_add_tail(&stats->list, &inst->buffer_stats_list);
+
+	stats->frame_num = inst->debug_count.etb;
+	stats->timestamp = buf->timestamp;
+	stats->etb_time_ms = buf->start_time_ms;
+	if (is_decode_session(inst))
+		stats->data_size =  buf->data_size;
+
+	return 0;
+}
+
+int msm_vidc_remove_buffer_stats(struct msm_vidc_inst *inst,
+	struct msm_vidc_buffer *buf)
+{
+	struct msm_vidc_buffer_stats *stats = NULL, *dummy_stats = NULL;
+
+	if (!inst || !buf) {
+		d_vpr_e("%s: invalid params\n", __func__);
+		return -EINVAL;
+	}
+
+	/* stats applicable only to input & output buffers */
+	if (buf->type != MSM_VIDC_BUF_INPUT && buf->type != MSM_VIDC_BUF_OUTPUT)
+		return -EINVAL;
+
+	/* update end timestamp */
+	buf->end_time_ms = (ktime_get_ns() / 1000 - inst->initial_time_us) / 1000;
+
+	list_for_each_entry_safe(stats, dummy_stats, &inst->buffer_stats_list, list) {
+		if (stats->timestamp == buf->timestamp) {
+			if (buf->type == MSM_VIDC_BUF_INPUT) {
+				/* skip - already updated(multiple input - single output case) */
+				if (stats->ebd_time_ms)
+					continue;
+
+				/* ebd: update end ts and return */
+				stats->ebd_time_ms = buf->end_time_ms;
+				stats->flags |= msm_vidc_get_buffer_stats_flag(inst);
+
+				/* remove entry - no output attached */
+				if (stats->flags & MSM_VIDC_STATS_FLAG_NO_OUTPUT) {
+					list_del_init(&stats->list);
+					msm_memory_pool_free(inst, stats);
+				}
+			} else if (buf->type == MSM_VIDC_BUF_OUTPUT) {
+				/* skip - ebd not arrived(single input - multiple output case) */
+				if (!stats->ebd_time_ms)
+					continue;
+
+				/* fbd: update end ts and remove entry */
+				list_del_init(&stats->list);
+				stats->ftb_time_ms = buf->start_time_ms;
+				stats->fbd_time_ms = buf->end_time_ms;
+				stats->flags |= msm_vidc_get_buffer_stats_flag(inst);
+				if (is_encode_session(inst))
+					stats->data_size = buf->data_size;
+
+				print_buffer_stats(VIDC_STAT, "stat", inst, stats);
+
+				msm_memory_pool_free(inst, stats);
+			}
+		}
+	}
+
+	return 0;
+}
+
+int msm_vidc_flush_buffer_stats(struct msm_vidc_inst *inst)
+{
+	struct msm_vidc_buffer_stats *stats, *dummy_stats;
+
+	if (!inst) {
+		d_vpr_e("%s: invalid params\n", __func__);
+		return -EINVAL;
+	}
+
+	i_vpr_l(inst, "%s: flush buffer_stats list\n", __func__);
+	list_for_each_entry_safe(stats, dummy_stats, &inst->buffer_stats_list, list) {
+		list_del_init(&stats->list);
+		msm_memory_pool_free(inst, stats);
+	}
+
+	/* reset initial ts as well to avoid huge delta */
+	inst->initial_time_us = ktime_get_ns() / 1000;
+
+	return 0;
+}
+
 enum msm_vidc_buffer_type v4l2_type_to_driver(u32 type, const char *func)
 {
 	enum msm_vidc_buffer_type buffer_type = 0;
@@ -3465,7 +3613,7 @@ void msm_vidc_print_stats(struct msm_vidc_inst *inst)
 	achieved_fps = (fbd * 1000) / dt_ms;
 	bitrate_kbps = (inst->stats.data_size * 8 * 1000) / (dt_ms * 1024);
 
-	i_vpr_hp(inst,
+	i_vpr_hs(inst,
 		"stats: counts (etb,ebd,ftb,fbd): %u %u %u %u (total %llu %llu %llu %llu), achieved bitrate %lldKbps fps %u/s, frame rate %u, operating rate %u, priority %u, dt %ums\n",
 		etb, ebd, ftb, fbd, inst->debug_count.etb, inst->debug_count.ebd,
 		inst->debug_count.ftb, inst->debug_count.fbd,
@@ -3677,6 +3825,9 @@ int msm_vidc_queue_buffer_single(struct msm_vidc_inst *inst, struct vb2_buffer *
 	if (!buf)
 		return -EINVAL;
 
+	/* update start timestamp */
+	msm_vidc_add_buffer_stats(inst, buf);
+
 	if (is_meta_rx_inp_enabled(inst, META_OUTBUF_FENCE) &&
 		is_output_buffer(buf->type)) {
 		fence = msm_vidc_fence_create(inst);
@@ -5641,6 +5792,7 @@ void msm_vidc_destroy_buffers(struct msm_vidc_inst *inst)
 	struct msm_vidc_timestamp *ts, *dummy_ts;
 	struct msm_memory_dmabuf *dbuf, *dummy_dbuf;
 	struct msm_vidc_input_timer *timer, *dummy_timer;
+	struct msm_vidc_buffer_stats *stats, *dummy_stats;
 	struct msm_vidc_inst_cap_entry *entry, *dummy_entry;
 	struct msm_vidc_fence *fence, *dummy_fence;
 
@@ -5731,6 +5883,12 @@ void msm_vidc_destroy_buffers(struct msm_vidc_inst *inst)
 		msm_memory_pool_free(inst, timer);
 	}
 
+	list_for_each_entry_safe(stats, dummy_stats, &inst->buffer_stats_list, list) {
+		print_buffer_stats(VIDC_ERR, "err ", inst, stats);
+		list_del(&stats->list);
+		msm_memory_pool_free(inst, stats);
+	}
+
 	list_for_each_entry_safe(dbuf, dummy_dbuf, &inst->dmabuf_tracker, list) {
 		i_vpr_e(inst, "%s: removing dma_buf %#x, refcount %u\n",
 			__func__, dbuf->dmabuf, dbuf->refcount);

driver/vidc/src/msm_vidc_memory.c

@@ -617,6 +617,7 @@ static const struct msm_vidc_type_size_name buftype_size_name_arr[] = {
 	{MSM_MEM_POOL_PACKET,     sizeof(struct hfi_pending_packet) + MSM_MEM_POOL_PACKET_SIZE,
 		"MSM_MEM_POOL_PACKET"},
 	{MSM_MEM_POOL_BUF_TIMER,  sizeof(struct msm_vidc_input_timer), "MSM_MEM_POOL_BUF_TIMER" },
+	{MSM_MEM_POOL_BUF_STATS,  sizeof(struct msm_vidc_buffer_stats), "MSM_MEM_POOL_BUF_STATS"},
 };
 
 int msm_memory_pools_init(struct msm_vidc_inst *inst)

driver/vidc/src/msm_vidc_vb2.c

@@ -403,10 +403,15 @@ void msm_vidc_stop_streaming(struct vb2_queue *q)
 	if (rc)
 		goto unlock;
 
-	/* Input port streamoff - flush timestamps list*/
-	if (q->type == INPUT_MPLANE)
+	/* Input port streamoff */
+	if (q->type == INPUT_MPLANE) {
+		/* flush timestamps list */
 		msm_vidc_flush_ts(inst);
 
+		/* flush buffer_stats list */
+		msm_vidc_flush_buffer_stats(inst);
+	}
+
 	i_vpr_h(inst, "Streamoff: %s successful\n", v4l2_type_name(q->type));
 
 unlock:

driver/vidc/src/venus_hfi_response.c

@@ -856,6 +856,9 @@ static int handle_input_buffer(struct msm_vidc_inst *inst,
 	print_vidc_buffer(VIDC_HIGH, "high", "dqbuf", inst, buf);
 	msm_vidc_update_stats(inst, buf, MSM_VIDC_DEBUGFS_EVENT_EBD);
 
+	/* etd: update end timestamp and flags in stats entry */
+	msm_vidc_remove_buffer_stats(inst, buf);
+
 	return rc;
 }
 
@@ -1019,6 +1022,9 @@ static int handle_output_buffer(struct msm_vidc_inst *inst,
 	print_vidc_buffer(VIDC_HIGH, "high", "dqbuf", inst, buf);
 	msm_vidc_update_stats(inst, buf, MSM_VIDC_DEBUGFS_EVENT_FBD);
 
+	/* fbd: print stats and remove entry */
+	msm_vidc_remove_buffer_stats(inst, buf);
+
 	return rc;
 }