video: driver: Enable msm_vidc_events trace

Enable tracing by adding trace function definitions.

Commands for collecting msm_vidc_events traces:
- adb shell "echo 10240 > /sys/kernel/tracing/buffer_size_kb"
- adb shell "echo 0 > /sys/kernel/tracing/tracing_on"
- adb shell "echo nop > /sys/kernel/tracing/current_tracer"
- adb shell "echo > /sys/kernel/tracing/set_event"
- adb shell "echo 1 > /sys/kernel/tracing/events/msm_vidc_events/enable"
- adb shell "echo 1 > /sys/kernel/tracing/tracing_on"
- adb shell "cat /sys/kernel/tracing/trace_pipe > /data/trace_log.txt"
- adb pull /data/trace_log.txt

Events:
- msm_v4l2_vidc_fw_load
- msm_v4l2_vidc_open
- msm_v4l2_vidc_close
- msm_vidc_dma_buffer
- msm_v4l2_vidc_buffer_event_log
- msm_vidc_perf_power_scale
- msm_vidc_common_state_change
- venus_hfi_var_done

These are the events registered.

Change-Id: Iab6952bb84df102f36a2776fdf9ef5133034c5a0
Signed-off-by: Gaviraju Doddabettahalli Bettegowda <gdoddabe@codeaurora.org>

driver/vidc/inc/msm_vidc_events.h

@@ -0,0 +1,298 @@
+/* SPDX-License-Identifier: GPL-2.0-only */
+/*
+ * Copyright (c) 2012-2021, The Linux Foundation. All rights reserved.
+ */
+
+#if !defined(_TRACE_MSM_VIDC_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_MSM_VIDC_H
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM msm_vidc_events
+#undef TRACE_INCLUDE_PATH
+#define TRACE_INCLUDE_PATH .
+#undef TRACE_INCLUDE_FILE
+#define TRACE_INCLUDE_FILE msm_vidc_events
+
+#include <linux/tracepoint.h>
+#include "msm_vidc_inst.h"
+
+DECLARE_EVENT_CLASS(msm_v4l2_vidc_inst,
+
+	TP_PROTO(char *dummy, struct msm_vidc_inst *inst),
+
+	TP_ARGS(dummy, inst),
+
+	TP_STRUCT__entry(
+		__field(char *, dummy)
+		__field(const char *, debug_str)
+	),
+
+	TP_fast_assign(
+		__entry->dummy = dummy;
+		__entry->debug_str = inst ? inst->debug_str : (u8 *)"";
+	),
+
+	TP_printk("%s: %s\n", __entry->dummy, __entry->debug_str)
+);
+
+DEFINE_EVENT(msm_v4l2_vidc_inst, msm_v4l2_vidc_open,
+
+	TP_PROTO(char *dummy, struct msm_vidc_inst *inst),
+
+	TP_ARGS(dummy, inst)
+);
+
+DEFINE_EVENT(msm_v4l2_vidc_inst, msm_v4l2_vidc_close,
+
+	TP_PROTO(char *dummy, struct msm_vidc_inst *inst),
+
+	TP_ARGS(dummy, inst)
+);
+
+DECLARE_EVENT_CLASS(msm_v4l2_vidc_fw_load,
+
+	TP_PROTO(char *dummy),
+
+	TP_ARGS(dummy),
+
+	TP_STRUCT__entry(
+		__field(char *, dummy)
+	),
+
+	TP_fast_assign(
+		__entry->dummy = dummy;
+	),
+
+	TP_printk("%s\n", __entry->dummy)
+);
+
+DEFINE_EVENT(msm_v4l2_vidc_fw_load, msm_v4l2_vidc_fw_load,
+
+	TP_PROTO(char *dummy),
+
+	TP_ARGS(dummy)
+);
+
+DECLARE_EVENT_CLASS(msm_vidc_driver,
+
+	TP_PROTO(struct msm_vidc_inst *inst, const char *func,
+		const char *old_state, const char *new_state),
+
+	TP_ARGS(inst, func, old_state, new_state),
+
+	TP_STRUCT__entry(
+		__field(const char *, debug_str)
+		__field(const char *, func)
+		__field(const char *, old_state)
+		__field(const char *, new_state)
+	),
+
+	TP_fast_assign(
+		__entry->debug_str = inst ? inst->debug_str : (u8 *)"";
+		__entry->func = func;
+		__entry->old_state = old_state;
+		__entry->new_state = new_state;
+	),
+
+	TP_printk("%s: %s: state changed to %s from %s\n",
+		__entry->debug_str,
+		__entry->func,
+		__entry->new_state,
+		__entry->old_state)
+);
+
+DEFINE_EVENT(msm_vidc_driver, msm_vidc_common_state_change,
+
+	TP_PROTO(struct msm_vidc_inst *inst, const char *func,
+		const char *old_state, const char *new_state),
+
+	TP_ARGS(inst, func, old_state, new_state)
+);
+
+DECLARE_EVENT_CLASS(venus_hfi_var,
+
+	TP_PROTO(u32 cp_start, u32 cp_size,
+		u32 cp_nonpixel_start, u32 cp_nonpixel_size),
+
+	TP_ARGS(cp_start, cp_size, cp_nonpixel_start, cp_nonpixel_size),
+
+	TP_STRUCT__entry(
+		__field(u32, cp_start)
+		__field(u32, cp_size)
+		__field(u32, cp_nonpixel_start)
+		__field(u32, cp_nonpixel_size)
+	),
+
+	TP_fast_assign(
+		__entry->cp_start = cp_start;
+		__entry->cp_size = cp_size;
+		__entry->cp_nonpixel_start = cp_nonpixel_start;
+		__entry->cp_nonpixel_size = cp_nonpixel_size;
+	),
+
+	TP_printk(
+		"TZBSP_MEM_PROTECT_VIDEO_VAR done, cp_start : 0x%x, cp_size : 0x%x, cp_nonpixel_start : 0x%x, cp_nonpixel_size : 0x%x\n",
+		__entry->cp_start,
+		__entry->cp_size,
+		__entry->cp_nonpixel_start,
+		__entry->cp_nonpixel_size)
+);
+
+DEFINE_EVENT(venus_hfi_var, venus_hfi_var_done,
+
+	TP_PROTO(u32 cp_start, u32 cp_size,
+		u32 cp_nonpixel_start, u32 cp_nonpixel_size),
+
+	TP_ARGS(cp_start, cp_size, cp_nonpixel_start, cp_nonpixel_size)
+);
+
+DECLARE_EVENT_CLASS(msm_v4l2_vidc_buffer_events,
+
+	TP_PROTO(struct msm_vidc_inst *inst, const char *str, const char *buf_type,
+			struct msm_vidc_buffer *vbuf, unsigned long inode, long ref_count),
+
+	TP_ARGS(inst, str, buf_type, vbuf, inode, ref_count),
+
+	TP_STRUCT__entry(
+		__field(u8 *, debug_str)
+		__field(const char *, str)
+		__field(const char *, buf_type)
+		__field(u32, index)
+		__field(int, fd)
+		__field(u32, data_offset)
+		__field(u64, device_addr)
+		__field(unsigned long, inode)
+		__field(long, ref_count)
+		__field(u32, buffer_size)
+		__field(u32, data_size)
+		__field(u32, flags)
+		__field(u64, timestamp)
+		__field(int, attr)
+		__field(u64, etb)
+		__field(u64, ebd)
+		__field(u64, ftb)
+		__field(u64, fbd)
+	),
+
+	TP_fast_assign(
+		__entry->debug_str = inst ? inst->debug_str : (u8 *)"";
+		__entry->str = str;
+		__entry->buf_type = buf_type;
+		__entry->index = vbuf ? vbuf->index : -1;
+		__entry->fd = vbuf ? vbuf->fd : 0;
+		__entry->data_offset = vbuf ? vbuf->data_offset : 0;
+		__entry->device_addr = vbuf ? vbuf->device_addr : 0;
+		__entry->inode = inode;
+		__entry->ref_count = ref_count;
+		__entry->buffer_size = vbuf ? vbuf->buffer_size : 0;
+		__entry->data_size = vbuf ? vbuf->data_size : 0;
+		__entry->flags = vbuf ? vbuf->flags : 0;
+		__entry->timestamp = vbuf ? vbuf->timestamp : 0;
+		__entry->attr = vbuf ? vbuf->attr : 0;
+		__entry->etb = inst ? inst->debug_count.etb : 0;
+		__entry->ebd = inst ? inst->debug_count.ebd : 0;
+		__entry->ftb = inst ? inst->debug_count.ftb : 0;
+		__entry->fbd = inst ? inst->debug_count.fbd : 0;
+	),
+
+	TP_printk(
+		"%s: %s: %s: idx %2d fd %3d off %d daddr %#llx inode %8lu ref %2ld size %8d filled %8d flags %#x ts %8lld attr %#x counts(etb ebd ftb fbd) %4llu %4llu %4llu %4llu\n",
+		__entry->debug_str, __entry->str, __entry->buf_type, __entry->index, __entry->fd,
+		__entry->data_offset, __entry->device_addr, __entry->inode, __entry->ref_count,
+		__entry->buffer_size, __entry->data_size, __entry->flags, __entry->timestamp,
+		__entry->attr, __entry->etb, __entry->ebd, __entry->ftb, __entry->fbd)
+);
+
+DEFINE_EVENT(msm_v4l2_vidc_buffer_events, msm_v4l2_vidc_buffer_event_log,
+
+	TP_PROTO(struct msm_vidc_inst *inst, const char *str, const char *buf_type,
+		struct msm_vidc_buffer *vbuf, unsigned long inode, long ref_count),
+
+	TP_ARGS(inst, str, buf_type, vbuf, inode, ref_count)
+);
+
+DECLARE_EVENT_CLASS(msm_vidc_perf,
+
+	TP_PROTO(struct msm_vidc_inst *inst, u64 clk_freq, u64 bw_ddr, u64 bw_llcc),
+
+	TP_ARGS(inst, clk_freq, bw_ddr, bw_llcc),
+
+	TP_STRUCT__entry(
+		__field(u8 *, debug_str)
+		__field(u64, curr_freq)
+		__field(u32, ddr_bw)
+		__field(u32, sys_cache_bw)
+		__field(u32, dcvs_flags)
+		__field(u64, clk_freq)
+		__field(u64, bw_ddr)
+		__field(u64, bw_llcc)
+	),
+
+	TP_fast_assign(
+		__entry->debug_str = inst ? inst->debug_str : (u8 *)"";
+		__entry->curr_freq = inst ? inst->power.curr_freq : 0;
+		__entry->ddr_bw = inst ? inst->power.ddr_bw : 0;
+		__entry->sys_cache_bw = inst ? inst->power.sys_cache_bw : 0;
+		__entry->dcvs_flags = inst ? inst->power.dcvs_flags : 0;
+		__entry->clk_freq = clk_freq;
+		__entry->bw_ddr = bw_ddr;
+		__entry->bw_llcc = bw_llcc;
+	),
+
+	TP_printk("%s: power: inst: clk %lld ddr %d llcc %d dcvs flags %#x, core: clk %lld ddr %lld llcc %lld\n",
+		__entry->debug_str, __entry->curr_freq, __entry->ddr_bw, __entry->sys_cache_bw,
+		__entry->dcvs_flags, __entry->clk_freq, __entry->bw_ddr, __entry->bw_llcc)
+);
+
+DEFINE_EVENT(msm_vidc_perf, msm_vidc_perf_power_scale,
+
+	TP_PROTO(struct msm_vidc_inst *inst, u64 clk_freq, u64 bw_ddr, u64 bw_llcc),
+
+	TP_ARGS(inst, clk_freq, bw_ddr, bw_llcc)
+);
+
+DECLARE_EVENT_CLASS(msm_vidc_buffer_dma_ops,
+
+	TP_PROTO(const char *buffer_op, void *dmabuf, u8 size, void *kvaddr,
+			const char *buf_name, u8 secure, u32 region),
+
+	TP_ARGS(buffer_op, dmabuf, size, kvaddr, buf_name, secure, region),
+
+	TP_STRUCT__entry(
+		__field(const char *, buffer_op)
+		__field(void *, dmabuf)
+		__field(u8, size)
+		__field(void *, kvaddr)
+		__field(const char *, buf_name)
+		__field(u8, secure)
+		__field(u32, region)
+	),
+
+	TP_fast_assign(
+		__entry->buffer_op = buffer_op;
+		__entry->dmabuf = dmabuf;
+		__entry->size = size;
+		__entry->kvaddr = kvaddr;
+		__entry->buf_name = buf_name;
+		__entry->secure = secure;
+		__entry->region = region;
+	),
+
+	TP_printk(
+		"%s: dmabuf %pK, size %d, kvaddr %pK, buffer_type %s, secure %d, region %d\n",
+		__entry->buffer_op, __entry->dmabuf, __entry->size, __entry->kvaddr,
+		__entry->buf_name, __entry->secure, __entry->region)
+);
+
+DEFINE_EVENT(msm_vidc_buffer_dma_ops, msm_vidc_dma_buffer,
+
+	TP_PROTO(const char *buffer_op, void *dmabuf, u8 size, void *kvaddr,
+			const char *buf_name, u8 secure, u32 region),
+
+	TP_ARGS(buffer_op, dmabuf, size, kvaddr, buf_name, secure, region)
+);
+
+#endif
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>

driver/vidc/src/msm_vidc_debug.c

@@ -2,7 +2,7 @@
 /*
  * Copyright (c) 2020-2021, The Linux Foundation. All rights reserved.
  */
-
+#define CREATE_TRACE_POINTS
 #include "msm_vidc_debug.h"
 #include "msm_vidc_driver.h"
 #include "msm_vidc_dt.h"
@@ -10,6 +10,7 @@
 #include "msm_vidc_core.h"
 #include "msm_vidc_inst.h"
 #include "msm_vidc_internal.h"
+#include "msm_vidc_events.h"
 
 extern struct msm_vidc_core *g_core;
 

driver/vidc/src/msm_vidc_driver.c

@@ -22,6 +22,8 @@
 #include "venus_hfi.h"
 #include "venus_hfi_response.h"
 #include "hfi_packet.h"
+#include "msm_vidc_events.h"
+
 extern struct msm_vidc_core *g_core;
 
 #define is_odd(val) ((val) % 2 == 1)
@@ -371,7 +373,7 @@ void print_vidc_buffer(u32 tag, const char *tag_str, const char *str, struct msm
 {
 	struct dma_buf *dbuf;
 
-	if (!(tag & msm_vidc_debug) || !inst || !vbuf || !tag_str || !str)
+	if (!inst || !vbuf || !tag_str || !str)
 		return;
 
 	dbuf = (struct dma_buf *)vbuf->dmabuf;
@@ -384,6 +386,11 @@ void print_vidc_buffer(u32 tag, const char *tag_str, const char *str, struct msm
 		(dbuf ? file_count(dbuf->file) : -1), vbuf->buffer_size, vbuf->data_size,
 		vbuf->flags, vbuf->timestamp, vbuf->attr, inst->debug_count.etb,
 		inst->debug_count.ebd, inst->debug_count.ftb, inst->debug_count.fbd);
+
+	trace_msm_v4l2_vidc_buffer_event_log(inst, str, buf_name(vbuf->type), vbuf,
+		(dbuf ? file_inode(dbuf->file)->i_ino : -1), (dbuf ? file_count(dbuf->file) : -1));
+
+
 }
 
 void print_vb2_buffer(const char *str, struct msm_vidc_inst *inst,
@@ -1194,6 +1201,9 @@ int msm_vidc_change_inst_state(struct msm_vidc_inst *inst,
 		i_vpr_h(inst, "%s: state changed to %s from %s\n",
 		   func, state_name(request_state), state_name(inst->state));
 
+	trace_msm_vidc_common_state_change(inst, func, state_name(inst->state),
+			state_name(request_state));
+
 	inst->state = request_state;
 
 	return 0;

driver/vidc/src/msm_vidc_memory.c

@@ -16,6 +16,7 @@
 #include "msm_vidc_driver.h"
 #include "msm_vidc_dt.h"
 #include "msm_vidc_core.h"
+#include "msm_vidc_events.h"
 
 struct msm_vidc_buf_region_name {
 	enum msm_vidc_buffer_region region;
@@ -388,6 +389,9 @@ int msm_vidc_memory_alloc(struct msm_vidc_core *core, struct msm_vidc_alloc *mem
 		"%s: dmabuf %pK, size %d, kvaddr %pK, buffer_type %s, secure %d, region %d\n",
 		__func__, mem->dmabuf, mem->size, mem->kvaddr, buf_name(mem->type),
 		mem->secure, mem->region);
+	trace_msm_vidc_dma_buffer("ALLOC", mem->dmabuf, mem->size, mem->kvaddr,
+		buf_name(mem->type), mem->secure, mem->region);
+
 	return 0;
 
 error:
@@ -409,6 +413,9 @@ int msm_vidc_memory_free(struct msm_vidc_core *core, struct msm_vidc_alloc *mem)
 		__func__, mem->dmabuf, mem->size, mem->kvaddr, buf_name(mem->type),
 		mem->secure, mem->region);
 
+	trace_msm_vidc_dma_buffer("FREE", mem->dmabuf, mem->size, mem->kvaddr,
+		buf_name(mem->type), mem->secure, mem->region);
+
 	if (mem->kvaddr) {
 		dma_buf_vunmap(mem->dmabuf, mem->kvaddr);
 		mem->kvaddr = NULL;

driver/vidc/src/msm_vidc_power.c

@@ -13,6 +13,7 @@
 #include "msm_vidc_platform.h"
 #include "msm_vidc_buffer.h"
 #include "venus_hfi.h"
+#include "msm_vidc_events.h"
 
 /* Q16 Format */
 #define MSM_VIDC_MIN_UBWC_COMPLEXITY_FACTOR (1 << 16)
@@ -524,6 +525,10 @@ int msm_vidc_scale_power(struct msm_vidc_inst *inst, bool scale_buses)
 		inst->power.sys_cache_bw, inst->power.dcvs_flags,
 		core->power.clk_freq, core->power.bw_ddr,
 		core->power.bw_llcc);
+
+	trace_msm_vidc_perf_power_scale(inst, core->power.clk_freq,
+		core->power.bw_ddr, core->power.bw_llcc);
+
 	return 0;
 }
 

driver/vidc/src/msm_vidc_v4l2.c

@@ -10,6 +10,7 @@
 #include "msm_vidc_debug.h"
 #include "msm_vidc_driver.h"
 #include "msm_vidc.h"
+#include "msm_vidc_events.h"
 
 extern struct msm_vidc_core *g_core;
 
@@ -36,14 +37,17 @@ int msm_v4l2_open(struct file *filp)
 	struct msm_vidc_core *core = video_drvdata(filp);
 	struct msm_vidc_inst *inst;
 
+	trace_msm_v4l2_vidc_open("START", NULL);
 	inst = msm_vidc_open(core, vid_dev->type);
 	if (!inst) {
 		d_vpr_e("Failed to create instance, type = %d\n",
 			vid_dev->type);
+		trace_msm_v4l2_vidc_open("END", NULL);
 		return -ENOMEM;
 	}
 	clear_bit(V4L2_FL_USES_V4L2_FH, &vdev->flags);
 	filp->private_data = &(inst->event_handler);
+	trace_msm_v4l2_vidc_open("END", inst);
 	return 0;
 }
 
@@ -53,9 +57,11 @@ int msm_v4l2_close(struct file *filp)
 	struct msm_vidc_inst *inst;
 
 	inst = get_vidc_inst(filp, NULL);
+	trace_msm_v4l2_vidc_close("START", inst);
 
 	rc = msm_vidc_close(inst);
 	filp->private_data = NULL;
+	trace_msm_v4l2_vidc_close("END", NULL);
 	return rc;
 }
 

driver/vidc/src/venus_hfi.c

@@ -25,6 +25,7 @@
 #include "msm_vidc_debug.h"
 #include "hfi_packet.h"
 #include "venus_hfi_response.h"
+#include "msm_vidc_events.h"
 
 #define MIN_PAYLOAD_SIZE 3
 
@@ -1303,6 +1304,10 @@ static int __protect_cp_mem(struct msm_vidc_core *core)
 	if (rc)
 		d_vpr_e("Failed to protect memory(%d)\n", rc);
 
+	trace_venus_hfi_var_done(
+		memprot.cp_start, memprot.cp_size,
+		memprot.cp_nonpixel_start, memprot.cp_nonpixel_size);
+
 	return rc;
 }
 #if 0 // TODO
@@ -2614,6 +2619,7 @@ int __load_fw(struct msm_vidc_core *core)
 	core->handoff_done = false;
 	core->hw_power_control = false;
 
+	trace_msm_v4l2_vidc_fw_load("START");
 	rc = __init_resources(core);
 	if (rc) {
 		d_vpr_e("%s: Failed to init resources: %d\n", __func__, rc);
@@ -2651,6 +2657,7 @@ int __load_fw(struct msm_vidc_core *core)
 	* present.
 	*/
 	__hand_off_regulators(core);
+	trace_msm_v4l2_vidc_fw_load("END");
 
 	return rc;
 fail_protect_mem:
@@ -2662,6 +2669,7 @@ fail_load_fw:
 fail_venus_power_on:
 	__deinit_resources(core);
 fail_init_res:
+	trace_msm_v4l2_vidc_fw_load("END");
 	return rc;
 }