video: driver: print buffer statistics once at every sec

- Added change to print buffer statistics like total and avg
etb, ebd, ftb, fbd counts, client set fps, actual fps,
bitrate values in 1 sec window and these stats currently
configured to print at every 1sec boundary.
- Convert meta buffer prints to low level logs.

Change-Id: I1c93eea90fbd5460eb51bbf133c513157003d51e
Signed-off-by: Govindaraj Rajagopal <grajagop@codeaurora.org>

driver/platform/waipio/src/msm_vidc_waipio.c

@@ -89,6 +89,7 @@ static struct msm_platform_core_capability core_data_waipio[] = {
 	{DCVS, 1},
 	{DECODE_BATCH, 1},
 	{DECODE_BATCH_TIMEOUT, 200},
+	{STATS_TIMEOUT, 2000},
 	{AV_SYNC_WINDOW_SIZE, 40},
 	{NON_FATAL_FAULTS, 1},
 	{ENC_AUTO_FRAMERATE, 1},

driver/vidc/inc/msm_vidc_driver.h

@@ -15,6 +15,8 @@
 #define MSM_VIDC_SESSION_INACTIVE_THRESHOLD_MS 1000
 #define HEIC_GRID_DIMENSION 512
 
+enum msm_vidc_debugfs_event;
+
 static inline is_decode_session(struct msm_vidc_inst *inst)
 {
 	return inst->domain == MSM_VIDC_DECODER;
@@ -346,6 +348,11 @@ int msm_vidc_get_delayed_unmap(struct msm_vidc_inst *inst,
 	struct msm_vidc_map *map);
 int msm_vidc_put_delayed_unmap(struct msm_vidc_inst *inst,
 	struct msm_vidc_map *map);
+void msm_vidc_update_stats(struct msm_vidc_inst *inst,
+	struct msm_vidc_buffer *buf, enum msm_vidc_debugfs_event etype);
+void msm_vidc_stats_handler(struct work_struct *work);
+int schedule_stats_work(struct msm_vidc_inst *inst);
+int cancel_stats_work(struct msm_vidc_inst *inst);
 enum msm_vidc_buffer_type v4l2_type_to_driver(u32 type,
 	const char *func);
 int msm_vidc_queue_buffer_single(struct msm_vidc_inst *inst,

driver/vidc/inc/msm_vidc_inst.h

@@ -128,6 +128,7 @@ struct msm_vidc_inst {
 	struct msm_vidc_decode_vpp_delay   decode_vpp_delay;
 	struct msm_vidc_session_idle       session_idle;
 	struct delayed_work                response_work;
+	struct delayed_work                stats_work;
 	struct workqueue_struct           *response_workq;
 	struct list_head                   response_works; /* list of struct response_work */
 	struct list_head                   enc_input_crs;
@@ -138,6 +139,7 @@ struct msm_vidc_inst {
 	struct dentry                     *debugfs_root;
 	struct msm_vidc_debug              debug;
 	struct debug_buf_count             debug_count;
+	struct msm_vidc_statistics         stats;
 	struct msm_vidc_inst_capability   *capabilities;
 	struct completion                  completions[MAX_SIGNAL];
 	enum priority_level                priority_level;

driver/vidc/inc/msm_vidc_internal.h

@@ -328,6 +328,7 @@ enum msm_vidc_core_capability_type {
 	DCVS,
 	DECODE_BATCH,
 	DECODE_BATCH_TIMEOUT,
+	STATS_TIMEOUT,
 	AV_SYNC_WINDOW_SIZE,
 	CLK_FREQ_THRESHOLD,
 	NON_FATAL_FAULTS,
@@ -519,10 +520,16 @@ struct msm_vidc_inst_cap_entry {
 };
 
 struct debug_buf_count {
-	int etb;
+	u64 etb;
-	int ftb;
+	u64 ftb;
-	int fbd;
+	u64 fbd;
-	int ebd;
+	u64 ebd;
+};
+
+struct msm_vidc_statistics {
+	struct debug_buf_count             count;
+	u64                                data_size;
+	u64                                time_ms;
 };
 
 enum efuse_purpose {
@@ -637,13 +644,6 @@ struct hfi_queue_header {
 			ALIGNED_QDSS_SIZE, SZ_1M)
 #define TOTAL_QSIZE (SHARED_QSIZE - ALIGNED_SFR_SIZE - ALIGNED_QDSS_SIZE)
 
-struct buf_count {
-	u32                    etb;
-	u32                    ftb;
-	u32                    fbd;
-	u32                    ebd;
-};
-
 struct profile_data {
 	u64                    start;
 	u64                    stop;
@@ -657,7 +657,6 @@ struct msm_vidc_debug {
 	struct profile_data    pdata[MAX_PROFILING_POINTS];
 	u32                    profile;
 	u32                    samples;
-	struct buf_count       count;
 };
 
 struct msm_vidc_input_cr_data {

driver/vidc/inc/venus_hfi_response.h

@@ -19,6 +19,7 @@ bool is_valid_hfi_buffer_type(struct msm_vidc_inst *inst,
 void handle_session_response_work_handler(struct work_struct *work);
 int handle_session_response_work(struct msm_vidc_inst *inst,
 	struct response_work *work);
+int cancel_response_work(struct msm_vidc_inst *inst);
 int handle_system_error(struct msm_vidc_core *core,
 	struct hfi_packet *pkt);
 void fw_coredump(struct msm_vidc_core *core);

driver/vidc/src/msm_vidc.c

@@ -866,6 +866,7 @@ void *msm_vidc_open(void *vidc_core, u32 session_type)
 	}
 
 	INIT_DELAYED_WORK(&inst->response_work, handle_session_response_work_handler);
+	INIT_DELAYED_WORK(&inst->stats_work, msm_vidc_stats_handler);
 
 	inst->capabilities = kzalloc(sizeof(struct msm_vidc_inst_capability), GFP_KERNEL);
 	if (!inst->capabilities) {
@@ -930,6 +931,8 @@ int msm_vidc_close(void *instance)
 
 	i_vpr_h(inst, "%s()\n", __func__);
 	inst_lock(inst, __func__);
+	cancel_response_work(inst);
+	cancel_stats_work(inst);
 	msm_vidc_session_close(inst);
 	msm_vidc_remove_session(inst);
 	msm_vidc_destroy_buffers(inst);

driver/vidc/src/msm_vidc_driver.c

@@ -2055,7 +2055,7 @@ int msm_vidc_set_auto_framerate(struct msm_vidc_inst *inst, u64 timestamp)
 	struct msm_vidc_timestamp *ts;
 	struct msm_vidc_timestamp *prev = NULL;
 	u32 counter = 0, prev_fr = 0, curr_fr = 0;
-	u64 ts_ms = 0;
+	u64 time_ms = 0;
 	int rc = 0;
 
 	if (!inst || !inst->core || !inst->capabilities) {
@@ -2074,9 +2074,9 @@ int msm_vidc_set_auto_framerate(struct msm_vidc_inst *inst, u64 timestamp)
 
 	list_for_each_entry(ts, &inst->timestamps.list, sort.list) {
 		if (prev) {
-			ts_ms = div_u64(ts->sort.val - prev->sort.val, 1000);
+			time_ms = div_u64(ts->sort.val - prev->sort.val, 1000);
 			prev_fr = curr_fr;
-			curr_fr = ts_ms ? div_u64(MSEC_PER_SEC, ts_ms) << 16 :
+			curr_fr = time_ms ? div_u64(MSEC_PER_SEC, time_ms) << 16 :
 					inst->auto_framerate;
 			if (curr_fr > inst->capabilities->cap[FRAME_RATE].max)
 				curr_fr = inst->capabilities->cap[FRAME_RATE].max;
@@ -2784,9 +2784,106 @@ void msm_vidc_free_capabililty_list(struct msm_vidc_inst *inst,
 	}
 }
 
+void msm_vidc_update_stats(struct msm_vidc_inst *inst,
+	struct msm_vidc_buffer *buf, enum msm_vidc_debugfs_event etype)
+{
+	if (!inst || !buf || !inst->capabilities) {
+		d_vpr_e("%s: invalid params\n", __func__);
+		return;
+	}
+
+	if ((is_decode_session(inst) && etype == MSM_VIDC_DEBUGFS_EVENT_ETB) ||
+		(is_encode_session(inst) && etype == MSM_VIDC_DEBUGFS_EVENT_FBD))
+		inst->stats.data_size += buf->data_size;
+
+	msm_vidc_debugfs_update(inst, etype);
+}
+
+static void msm_vidc_print_stats(struct msm_vidc_inst *inst)
+{
+	u32 frame_rate, operating_rate, achieved_fps, priority, etb, ebd, ftb, fbd, dt_ms;
+	u64 bitrate_kbps = 0, time_ms = ktime_get_ns() / 1000 / 1000;
+
+	if (!inst || !inst->capabilities) {
+		d_vpr_e("%s: invalid params\n", __func__);
+		return;
+	}
+
+	etb = inst->debug_count.etb - inst->stats.count.etb;
+	ebd = inst->debug_count.ebd - inst->stats.count.ebd;
+	ftb = inst->debug_count.ftb - inst->stats.count.ftb;
+	fbd = inst->debug_count.fbd - inst->stats.count.fbd;
+	frame_rate = inst->capabilities->cap[FRAME_RATE].value >> 16;
+	operating_rate = inst->capabilities->cap[OPERATING_RATE].value >> 16;
+	priority =  inst->capabilities->cap[PRIORITY].value;
+
+	dt_ms = time_ms - inst->stats.time_ms;
+	achieved_fps = (fbd * 1000) / dt_ms;
+	bitrate_kbps = (inst->stats.data_size * 8 * 1000) / (dt_ms * 1024);
+
+	i_vpr_hp(inst,
+		"stats: counts (etb,ebd,ftb,fbd): %u %u %u %u (total %u %u %u %u), 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,
+		bitrate_kbps, achieved_fps, frame_rate, operating_rate, priority, dt_ms);
+
+	inst->stats.count = inst->debug_count;
+	inst->stats.data_size = 0;
+	inst->stats.time_ms = time_ms;
+}
+
+int schedule_stats_work(struct msm_vidc_inst *inst)
+{
+	struct msm_vidc_core *core;
+
+	if (!inst || !inst->core) {
+		d_vpr_e("%s: invalid params\n", __func__);
+		return -EINVAL;
+	}
+	core = inst->core;
+	mod_delayed_work(inst->response_workq, &inst->stats_work,
+		msecs_to_jiffies(core->capabilities[STATS_TIMEOUT].value));
+
+	return 0;
+}
+
+int cancel_stats_work(struct msm_vidc_inst *inst)
+{
+	if (!inst) {
+		d_vpr_e("%s: Invalid arguments\n", __func__);
+		return -EINVAL;
+	}
+	cancel_delayed_work(&inst->stats_work);
+
+	/* print final stats */
+	msm_vidc_print_stats(inst);
+
+	return 0;
+}
+
+void msm_vidc_stats_handler(struct work_struct *work)
+{
+	struct msm_vidc_inst *inst;
+
+	inst = container_of(work, struct msm_vidc_inst, stats_work.work);
+	inst = get_inst_ref(g_core, inst);
+	if (!inst) {
+		d_vpr_e("%s: invalid params\n", __func__);
+		return;
+	}
+
+	inst_lock(inst, __func__);
+	msm_vidc_print_stats(inst);
+	schedule_stats_work(inst);
+	inst_unlock(inst, __func__);
+
+	put_inst(inst);
+}
+
 static int msm_vidc_queue_buffer(struct msm_vidc_inst *inst, struct msm_vidc_buffer *buf)
 {
 	struct msm_vidc_buffer *meta;
+	enum msm_vidc_debugfs_event etype;
 	int rc = 0;
 	u32 cr = 0;
 
@@ -2816,7 +2913,7 @@ static int msm_vidc_queue_buffer(struct msm_vidc_inst *inst, struct msm_vidc_buf
 	print_vidc_buffer(VIDC_HIGH, "high", "qbuf", inst, buf);
 	meta = get_meta_buffer(inst, buf);
 	if (meta)
-		print_vidc_buffer(VIDC_HIGH, "high", "qbuf", inst, meta);
+		print_vidc_buffer(VIDC_LOW, "low ", "qbuf", inst, meta);
 
 	if (!meta && is_meta_enabled(inst, buf->type)) {
 		print_vidc_buffer(VIDC_ERR, "err ", "missing meta for", inst, buf);
@@ -2840,10 +2937,12 @@ static int msm_vidc_queue_buffer(struct msm_vidc_inst *inst, struct msm_vidc_buf
 	if (is_input_buffer(buf->type))
 		inst->power.buffer_counter++;
 
-	if (buf->type == MSM_VIDC_BUF_INPUT)
+	if (is_input_buffer(buf->type))
-		msm_vidc_debugfs_update(inst, MSM_VIDC_DEBUGFS_EVENT_ETB);
+		etype = MSM_VIDC_DEBUGFS_EVENT_ETB;
-	else if (buf->type == MSM_VIDC_BUF_OUTPUT)
+	else
-		msm_vidc_debugfs_update(inst, MSM_VIDC_DEBUGFS_EVENT_FTB);
+		etype = MSM_VIDC_DEBUGFS_EVENT_FTB;
+
+	msm_vidc_update_stats(inst, buf, etype);
 
 	return 0;
 }

driver/vidc/src/msm_vidc_vb2.c

@@ -240,6 +240,15 @@ int msm_vidc_start_streaming(struct vb2_queue *q, unsigned int count)
 	if (rc)
 		goto error;
 
+	/* initialize statistics timer(one time) */
+	if (!inst->stats.time_ms)
+		inst->stats.time_ms = ktime_get_ns() / 1000 / 1000;
+
+	/* schedule to print buffer statistics */
+	rc = schedule_stats_work(inst);
+	if (rc)
+		goto error;
+
 	i_vpr_h(inst, "Streamon: %s successful\n", v4l2_type_name(q->type));
 
 	return rc;

driver/vidc/src/venus_hfi_response.c

@@ -729,7 +729,7 @@ static int handle_input_buffer(struct msm_vidc_inst *inst,
 			return -EINVAL;
 		}
 		if (buffer->addr_offset / frame_size < batch_size - 1) {
-			i_vpr_h(inst, "%s: superframe last buffer not reached: %u, %u, %u\n",
+			i_vpr_l(inst, "%s: superframe last buffer not reached: %u, %u, %u\n",
 				__func__, buffer->addr_offset, frame_size, batch_size);
 			return 0;
 		}
@@ -743,7 +743,7 @@ static int handle_input_buffer(struct msm_vidc_inst *inst,
 	buf->flags = get_driver_buffer_flags(inst, buffer->flags);
 
 	print_vidc_buffer(VIDC_HIGH, "high", "dqbuf", inst, buf);
-	msm_vidc_debugfs_update(inst, MSM_VIDC_DEBUGFS_EVENT_EBD);
+	msm_vidc_update_stats(inst, buf, MSM_VIDC_DEBUGFS_EVENT_EBD);
 
 	return rc;
 }
@@ -869,7 +869,7 @@ static int handle_output_buffer(struct msm_vidc_inst *inst,
 		msm_vidc_update_timestamp(inst, buf->timestamp);
 
 	print_vidc_buffer(VIDC_HIGH, "high", "dqbuf", inst, buf);
-	msm_vidc_debugfs_update(inst, MSM_VIDC_DEBUGFS_EVENT_FBD);
+	msm_vidc_update_stats(inst, buf, MSM_VIDC_DEBUGFS_EVENT_FBD);
 
 	return rc;
 }
@@ -916,7 +916,7 @@ static int handle_input_metadata_buffer(struct msm_vidc_inst *inst,
 			return -EINVAL;
 		}
 		if (buffer->addr_offset / frame_size < batch_size - 1) {
-			i_vpr_h(inst, "%s: superframe last buffer not reached: %u, %u, %u\n",
+			i_vpr_l(inst, "%s: superframe last buffer not reached: %u, %u, %u\n",
 				__func__, buffer->addr_offset, frame_size, batch_size);
 			return 0;
 		}
@@ -928,7 +928,7 @@ static int handle_input_metadata_buffer(struct msm_vidc_inst *inst,
 	if (buffer->flags & HFI_BUF_FW_FLAG_LAST)
 		buf->flags |= MSM_VIDC_BUF_FLAG_LAST;
 
-	print_vidc_buffer(VIDC_HIGH, "high", "dqbuf", inst, buf);
+	print_vidc_buffer(VIDC_LOW, "low ", "dqbuf", inst, buf);
 	return rc;
 }
 
@@ -965,7 +965,7 @@ static int handle_output_metadata_buffer(struct msm_vidc_inst *inst,
 	if (buffer->flags & HFI_BUF_FW_FLAG_LAST)
 		buf->flags |= MSM_VIDC_BUF_FLAG_LAST;
 
-	print_vidc_buffer(VIDC_HIGH, "high", "dqbuf", inst, buf);
+	print_vidc_buffer(VIDC_LOW, "low ", "dqbuf", inst, buf);
 	return rc;
 }
 
@@ -1672,6 +1672,25 @@ static int queue_response_work(struct msm_vidc_inst *inst,
 	return 0;
 }
 
+int cancel_response_work(struct msm_vidc_inst *inst)
+{
+	struct response_work *work, *dummy_work = NULL;
+
+	if (!inst) {
+		d_vpr_e("%s: Invalid arguments\n", __func__);
+		return -EINVAL;
+	}
+	cancel_delayed_work(&inst->response_work);
+
+	list_for_each_entry_safe(work, dummy_work, &inst->response_works, list) {
+		list_del(&work->list);
+		kfree(work->data);
+		kfree(work);
+	}
+
+	return 0;
+}
+
 static int handle_session_response(struct msm_vidc_core *core,
 	struct hfi_header *hdr)
 {