diff mbox series

[v2] bus: mhi: host: Add tracing support

Message ID 20231013-ftrace_support-v2-1-6e893ce010b5@quicinc.com (mailing list archive)
State Superseded
Headers show
Series [v2] bus: mhi: host: Add tracing support | expand

Commit Message

Krishna Chaitanya Chundru Oct. 13, 2023, 9:52 a.m. UTC
This change adds ftrace support for following functions which
helps in debugging the issues when there is Channel state & MHI
state change and also when we receive data and control events:
1. mhi_intvec_threaded_handler
2. mhi_process_data_event_ring
3. mhi_process_ctrl_ev_ring
4. mhi_gen_tre
5. mhi_update_channel_state
6. mhi_tryset_pm_state
7. mhi_pm_st_worker

Signed-off-by: Krishna chaitanya chundru <quic_krichai@quicinc.com>
---
Changes in v2:
- Passing the raw state into the trace event and using  __print_symbolic() as suggested by bjorn.
- Change mhi_pm_st_worker to mhi_pm_st_transition as suggested by bjorn.
- Fixed the kernel test rebot issues.
- Link to v1: https://lore.kernel.org/r/20231005-ftrace_support-v1-1-23a2f394fa49@quicinc.com
---
 MAINTAINERS                     |   1 +
 drivers/bus/mhi/host/init.c     |   3 +
 drivers/bus/mhi/host/internal.h |   1 +
 drivers/bus/mhi/host/main.c     |  32 +++--
 drivers/bus/mhi/host/pm.c       |   6 +-
 include/trace/events/mhi_host.h | 287 ++++++++++++++++++++++++++++++++++++++++
 6 files changed, 317 insertions(+), 13 deletions(-)


---
base-commit: 3006adf3be79cde4d14b1800b963b82b6e5572e0
change-id: 20231005-ftrace_support-6869d4156139

Best regards,

Comments

Steven Rostedt Oct. 16, 2023, 3:13 p.m. UTC | #1
On Fri, 13 Oct 2023 15:22:19 +0530
Krishna chaitanya chundru <quic_krichai@quicinc.com> wrote:

> +++ b/include/trace/events/mhi_host.h
> @@ -0,0 +1,287 @@
> +/* SPDX-License-Identifier: GPL-2.0-only */
> +/*
> + * Copyright (c) 2023 Qualcomm Innovation Center, Inc. All rights reserved.
> + */
> +
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM mhi_host
> +
> +#if !defined(_TRACE_EVENT_MHI_HOST_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_EVENT_MHI_HOST_H
> +
> +#include <linux/tracepoint.h>
> +#define MHI_STATE						\
> +	EM(MHI_STATE_RESET,	"RESET")			\
> +	EM(MHI_STATE_READY,	"READY")			\
> +	EM(MHI_STATE_M0,	"M0")				\
> +	EM(MHI_STATE_M1,	"M1")				\
> +	EM(MHI_STATE_M2,	"M2")				\
> +	EM(MHI_STATE_M3,	"M3")				\
> +	EM(MHI_STATE_M3_FAST,	"M3 FAST")			\
> +	EM(MHI_STATE_BHI,	"BHI")				\
> +	EMe(MHI_STATE_SYS_ERR,	"SYS ERROR")
> +
> +#define MHI_EE							\
> +	EM(MHI_EE_PBL,		"PRIMARY BOOTLOADER")		\
> +	EM(MHI_EE_SBL,		"SECONDARY BOOTLOADER")		\
> +	EM(MHI_EE_AMSS,		"MISSION MODE")			\
> +	EM(MHI_EE_RDDM,		"RAMDUMP DOWNLOAD MODE")	\
> +	EM(MHI_EE_WFW,		"WLAN FIRMWARE")		\
> +	EM(MHI_EE_PTHRU,	"PASS THROUGH")			\
> +	EM(MHI_EE_EDL,		"EMERGENCY DOWNLOAD")		\
> +	EM(MHI_EE_FP,		"FLASH PROGRAMMER")		\
> +	EM(MHI_EE_DISABLE_TRANSITION,	"DISABLE")		\
> +	EMe(MHI_EE_NOT_SUPPORTED,	"NOT SUPPORTED")
> +
> +#define MHI_PM_STATE							\
> +	EM(MHI_PM_STATE_DISABLE,	"DISABLE")			\
> +	EM(MHI_PM_STATE_POR,		"POWER ON RESET")		\
> +	EM(MHI_PM_STATE_M0,		"M0")				\
> +	EM(MHI_PM_STATE_M2,		"M2")				\
> +	EM(MHI_PM_STATE_M3_ENTER,	"M?->M3")			\
> +	EM(MHI_PM_STATE_M3,		"M3")				\
> +	EM(MHI_PM_STATE_M3_EXIT,	"M3->M0")			\
> +	EM(MHI_PM_STATE_FW_DL_ERR,	"Firmware Download Error")	\
> +	EM(MHI_PM_STATE_SYS_ERR_DETECT,		"SYS ERROR Detect")	\
> +	EM(MHI_PM_STATE_SYS_ERR_PROCESS,	"SYS ERROR Process")	\
> +	EM(MHI_PM_STATE_SHUTDOWN_PROCESS,	"SHUTDOWN Process")	\
> +	EMe(MHI_PM_STATE_LD_ERR_FATAL_DETECT,	"Linkdown or Error Fatal Detect")
> +
> +#define MHI_CH_STATE						\
> +	EM(MHI_CH_STATE_TYPE_RESET, "RESET")			\
> +	EM(MHI_CH_STATE_TYPE_STOP, "STOP")			\
> +	EMe(MHI_CH_STATE_TYPE_START, "START")
> +
> +#define MHI_DEV_ST_TRANSITION						\
> +	EM(DEV_ST_TRANSITION_PBL,	"PBL")				\
> +	EM(DEV_ST_TRANSITION_READY,	"READY")			\
> +	EM(DEV_ST_TRANSITION_SBL,	"SBL")				\
> +	EM(DEV_ST_TRANSITION_MISSION_MODE,	"MISSION MODE")		\
> +	EM(DEV_ST_TRANSITION_FP,		"FLASH PROGRAMMER")	\
> +	EM(DEV_ST_TRANSITION_SYS_ERR,		"SYS ERROR")		\
> +	EMe(DEV_ST_TRANSITION_DISABLE,		"DISABLE")
> +
> +/* Enums require being exported to userspace, for user tool parsing */
> +#undef	EM
> +#undef	EMe
> +#define	EM(a, b)	TRACE_DEFINE_ENUM(a);
> +#define	EMe(a, b)	TRACE_DEFINE_ENUM(a);
> +
> +MHI_STATE
> +MHI_EE
> +MHI_PM_STATE
> +MHI_CH_STATE
> +MHI_DEV_ST_TRANSITION
> +
> +/*
> + * Now redefine the EM() and EMe() macros to map the enums to the strings
> + * that will be printed in the output.
> + */
> +#undef EM
> +#undef EMe
> +#define EM(a, b)	{a, b},
> +#define EMe(a, b)	{a, b}
> +
> +TRACE_EVENT(mhi_gen_tre,
> +
> +	TP_PROTO(const char *name, int ch_num, u64 wp, __le64 tre_ptr,
> +		 __le32 dword0, __le32 dword1),
> +
> +	TP_ARGS(name, ch_num, wp, tre_ptr, dword0, dword1),
> +
> +	TP_STRUCT__entry(
> +		__string(name, name)
> +		__field(int, ch_num)

This is fine as __string() is four bytes in the event (2 bytes for offset
where the string exists, and 2 bytes for its length).

> +		__field(u64, wp)
> +		__field(__le64, tre_ptr)

Which makes the two 8 byte fields aligned. Good!

> +		__field(__le32, dword0)
> +		__field(__le32, dword1)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, name);
> +		__entry->ch_num = ch_num;
> +		__entry->wp = wp;
> +		__entry->tre_ptr = tre_ptr;
> +		__entry->dword0 = dword0;
> +		__entry->dword1 = dword1;
> +	),
> +
> +	TP_printk("%s: Chan: %d WP: 0x%llx TRE: 0x%llx 0x%08x 0x%08x\n",
> +		  __get_str(name), __entry->ch_num, __entry->wp, __entry->tre_ptr,
> +		  __entry->dword0, __entry->dword1)
> +);
> +
> +TRACE_EVENT(mhi_intvec_threaded_handler,
> +
> +	TP_PROTO(const char *name, int local_ee, int state, int dev_ee, int dev_state),
> +
> +	TP_ARGS(name, local_ee, state, dev_ee, dev_state),
> +
> +	TP_STRUCT__entry(
> +		__string(name, name)
> +		__field(int, local_ee)
> +		__field(int, state)
> +		__field(int, dev_ee)
> +		__field(int, dev_state)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, name);
> +		__entry->local_ee = local_ee;
> +		__entry->state = state;
> +		__entry->dev_ee = dev_ee;
> +		__entry->dev_state = dev_state;
> +	),
> +
> +	TP_printk("%s: local ee: %s state: %s device ee: %s state: %s\n",
> +		  __get_str(name),
> +		  __print_symbolic(__entry->local_ee, MHI_EE),
> +		  __print_symbolic(__entry->state, MHI_STATE),
> +		  __print_symbolic(__entry->dev_ee, MHI_EE),
> +		  __print_symbolic(__entry->dev_state, MHI_STATE))
> +);
> +
> +TRACE_EVENT(mhi_tryset_pm_state,
> +
> +	TP_PROTO(const char *name, int pm_state),
> +
> +	TP_ARGS(name, pm_state),
> +
> +	TP_STRUCT__entry(
> +		__string(name, name)
> +		__field(int, pm_state)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, name);
> +		if (pm_state)
> +			pm_state = __fls(pm_state);
> +		__entry->pm_state = pm_state;
> +	),
> +
> +	TP_printk("%s: PM state: %s\n", __get_str(name),
> +		  __print_symbolic(__entry->pm_state, MHI_PM_STATE))
> +);
> +
> +TRACE_EVENT(mhi_process_data_event_ring,
> +
> +	TP_PROTO(const char *name, __le64 ptr, __le32 dword0, __le32 dword1),
> +
> +	TP_ARGS(name, ptr, dword0, dword1),
> +
> +	TP_STRUCT__entry(
> +		__string(name, name)
> +		__field(__le64, ptr)

Here, I would switch the __field(__le64, ptr) with the __string().

		__field(__le64, ptr)
		__string(name, name)

otherwise you just created a 4 byte hole in the ring buffer, wasting
precious ring buffer space.

> +		__field(__le32, dword0)
> +		__field(__le32, dword1)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, name);
> +		__entry->ptr = ptr;
> +		__entry->dword0 = dword0;
> +		__entry->dword1 = dword1;
> +	),
> +
> +	TP_printk("%s: Processing Event:0x%llx 0x%08x 0x%08x\n",
> +		  __get_str(name), __entry->ptr, __entry->dword0, __entry->dword1)
> +);
> +
> +TRACE_EVENT(mhi_process_ctrl_ev_ring,
> +
> +	TP_PROTO(const char *name, u64 rp, __le64 ptr, __le32 dword0, __le32 dword1, int state),
> +
> +	TP_ARGS(name, rp, ptr, dword0, dword1, state),
> +
> +	TP_STRUCT__entry(
> +		__string(name, name)
> +		__field(u64, rp)
> +		__field(__le64, ptr)

I would move __string(name, name) here (after the two 8 byte fields).

-- Steve

> +		__field(__le32, dword0)
> +		__field(__le32, dword1)
> +		__field(int, state)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, name);
> +		__entry->rp = rp;
> +		__entry->ptr = ptr;
> +		__entry->dword0 = dword0;
> +		__entry->dword1 = dword1;
> +		__entry->state = state;
> +	),
> +
> +	TP_printk("%s: RP:0x%llx Processing Event:0x%llx 0x%08x 0x%08x state:%s\n",
> +		  __get_str(name), __entry->rp, __entry->ptr, __entry->dword0,
> +		  __entry->dword1, __print_symbolic(__entry->state, MHI_STATE))
> +);
> +
> +TRACE_EVENT(mhi_update_channel_state_start,
> +
> +	TP_PROTO(const char *name, int ch_num, int state),
> +
> +	TP_ARGS(name, ch_num, state),
> +
> +	TP_STRUCT__entry(
> +		__string(name, name)
> +		__field(int, ch_num)
> +		__field(int, state)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, name);
> +		__entry->ch_num = ch_num;
> +		__entry->state = state;
> +	),
> +
> +	TP_printk("%s: ch%d: Updating state to: %s\n",
> +		  __get_str(name), __entry->ch_num,
> +		  __print_symbolic(__entry->state, MHI_CH_STATE))
> +);
> +
> +TRACE_EVENT(mhi_update_channel_state_end,
> +
> +	TP_PROTO(const char *name, int ch_num, int state),
> +
> +	TP_ARGS(name, ch_num, state),
> +
> +	TP_STRUCT__entry(
> +		__string(name, name)
> +		__field(int, ch_num)
> +		__field(int, state)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, name);
> +		__entry->ch_num = ch_num;
> +		__entry->state = state;
> +	),
> +
> +	TP_printk("%s: ch%d: Updated state to: %s\n",
> +		  __get_str(name), __entry->ch_num,
> +		  __print_symbolic(__entry->state, MHI_CH_STATE))
> +);
> +
> +TRACE_EVENT(mhi_pm_st_transition,
> +
> +	TP_PROTO(const char *name, int state),
> +
> +	TP_ARGS(name, state),
> +
> +	TP_STRUCT__entry(
> +		__string(name, name)
> +		__field(int, state)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, name);
> +		__entry->state = state;
> +	),
> +
> +	TP_printk("%s: Handling state transition: %s\n", __get_str(name),
> +		  __print_symbolic(__entry->state, MHI_DEV_ST_TRANSITION))
> +);
> +
> +#endif
> +#include <trace/define_trace.h>
kernel test robot Oct. 17, 2023, 8:21 a.m. UTC | #2
Hi Krishna,

kernel test robot noticed the following build warnings:

[auto build test WARNING on 3006adf3be79cde4d14b1800b963b82b6e5572e0]

url:    https://github.com/intel-lab-lkp/linux/commits/Krishna-chaitanya-chundru/bus-mhi-host-Add-tracing-support/20231017-120241
base:   3006adf3be79cde4d14b1800b963b82b6e5572e0
patch link:    https://lore.kernel.org/r/20231013-ftrace_support-v2-1-6e893ce010b5%40quicinc.com
patch subject: [PATCH v2] bus: mhi: host: Add tracing support
config: m68k-allyesconfig (https://download.01.org/0day-ci/archive/20231017/202310171556.hmPBsvRX-lkp@intel.com/config)
compiler: m68k-linux-gcc (GCC) 13.2.0
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20231017/202310171556.hmPBsvRX-lkp@intel.com/reproduce)

If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202310171556.hmPBsvRX-lkp@intel.com/

All warnings (new ones prefixed by >>):

>> drivers/bus/mhi/host/main.c:249:12: warning: no previous prototype for 'mhi_to_physical' [-Wmissing-prototypes]
     249 | dma_addr_t mhi_to_physical(struct mhi_ring *ring, void *addr)
         |            ^~~~~~~~~~~~~~~


vim +/mhi_to_physical +249 drivers/bus/mhi/host/main.c

   248	
 > 249	dma_addr_t mhi_to_physical(struct mhi_ring *ring, void *addr)
   250	{
   251		return (addr - ring->base) + ring->iommu_base;
   252	}
   253
Krishna Chaitanya Chundru Oct. 17, 2023, 9:08 a.m. UTC | #3
On 10/16/2023 8:43 PM, Steven Rostedt wrote:
> On Fri, 13 Oct 2023 15:22:19 +0530
> Krishna chaitanya chundru <quic_krichai@quicinc.com> wrote:
>
>> +++ b/include/trace/events/mhi_host.h
>> @@ -0,0 +1,287 @@
>> +/* SPDX-License-Identifier: GPL-2.0-only */
>> +/*
>> + * Copyright (c) 2023 Qualcomm Innovation Center, Inc. All rights reserved.
>> + */
>> +
>> +#undef TRACE_SYSTEM
>> +#define TRACE_SYSTEM mhi_host
>> +
>> +#if !defined(_TRACE_EVENT_MHI_HOST_H) || defined(TRACE_HEADER_MULTI_READ)
>> +#define _TRACE_EVENT_MHI_HOST_H
>> +
>> +#include <linux/tracepoint.h>
>> +#define MHI_STATE						\
>> +	EM(MHI_STATE_RESET,	"RESET")			\
>> +	EM(MHI_STATE_READY,	"READY")			\
>> +	EM(MHI_STATE_M0,	"M0")				\
>> +	EM(MHI_STATE_M1,	"M1")				\
>> +	EM(MHI_STATE_M2,	"M2")				\
>> +	EM(MHI_STATE_M3,	"M3")				\
>> +	EM(MHI_STATE_M3_FAST,	"M3 FAST")			\
>> +	EM(MHI_STATE_BHI,	"BHI")				\
>> +	EMe(MHI_STATE_SYS_ERR,	"SYS ERROR")
>> +
>> +#define MHI_EE							\
>> +	EM(MHI_EE_PBL,		"PRIMARY BOOTLOADER")		\
>> +	EM(MHI_EE_SBL,		"SECONDARY BOOTLOADER")		\
>> +	EM(MHI_EE_AMSS,		"MISSION MODE")			\
>> +	EM(MHI_EE_RDDM,		"RAMDUMP DOWNLOAD MODE")	\
>> +	EM(MHI_EE_WFW,		"WLAN FIRMWARE")		\
>> +	EM(MHI_EE_PTHRU,	"PASS THROUGH")			\
>> +	EM(MHI_EE_EDL,		"EMERGENCY DOWNLOAD")		\
>> +	EM(MHI_EE_FP,		"FLASH PROGRAMMER")		\
>> +	EM(MHI_EE_DISABLE_TRANSITION,	"DISABLE")		\
>> +	EMe(MHI_EE_NOT_SUPPORTED,	"NOT SUPPORTED")
>> +
>> +#define MHI_PM_STATE							\
>> +	EM(MHI_PM_STATE_DISABLE,	"DISABLE")			\
>> +	EM(MHI_PM_STATE_POR,		"POWER ON RESET")		\
>> +	EM(MHI_PM_STATE_M0,		"M0")				\
>> +	EM(MHI_PM_STATE_M2,		"M2")				\
>> +	EM(MHI_PM_STATE_M3_ENTER,	"M?->M3")			\
>> +	EM(MHI_PM_STATE_M3,		"M3")				\
>> +	EM(MHI_PM_STATE_M3_EXIT,	"M3->M0")			\
>> +	EM(MHI_PM_STATE_FW_DL_ERR,	"Firmware Download Error")	\
>> +	EM(MHI_PM_STATE_SYS_ERR_DETECT,		"SYS ERROR Detect")	\
>> +	EM(MHI_PM_STATE_SYS_ERR_PROCESS,	"SYS ERROR Process")	\
>> +	EM(MHI_PM_STATE_SHUTDOWN_PROCESS,	"SHUTDOWN Process")	\
>> +	EMe(MHI_PM_STATE_LD_ERR_FATAL_DETECT,	"Linkdown or Error Fatal Detect")
>> +
>> +#define MHI_CH_STATE						\
>> +	EM(MHI_CH_STATE_TYPE_RESET, "RESET")			\
>> +	EM(MHI_CH_STATE_TYPE_STOP, "STOP")			\
>> +	EMe(MHI_CH_STATE_TYPE_START, "START")
>> +
>> +#define MHI_DEV_ST_TRANSITION						\
>> +	EM(DEV_ST_TRANSITION_PBL,	"PBL")				\
>> +	EM(DEV_ST_TRANSITION_READY,	"READY")			\
>> +	EM(DEV_ST_TRANSITION_SBL,	"SBL")				\
>> +	EM(DEV_ST_TRANSITION_MISSION_MODE,	"MISSION MODE")		\
>> +	EM(DEV_ST_TRANSITION_FP,		"FLASH PROGRAMMER")	\
>> +	EM(DEV_ST_TRANSITION_SYS_ERR,		"SYS ERROR")		\
>> +	EMe(DEV_ST_TRANSITION_DISABLE,		"DISABLE")
>> +
>> +/* Enums require being exported to userspace, for user tool parsing */
>> +#undef	EM
>> +#undef	EMe
>> +#define	EM(a, b)	TRACE_DEFINE_ENUM(a);
>> +#define	EMe(a, b)	TRACE_DEFINE_ENUM(a);
>> +
>> +MHI_STATE
>> +MHI_EE
>> +MHI_PM_STATE
>> +MHI_CH_STATE
>> +MHI_DEV_ST_TRANSITION
>> +
>> +/*
>> + * Now redefine the EM() and EMe() macros to map the enums to the strings
>> + * that will be printed in the output.
>> + */
>> +#undef EM
>> +#undef EMe
>> +#define EM(a, b)	{a, b},
>> +#define EMe(a, b)	{a, b}
>> +
>> +TRACE_EVENT(mhi_gen_tre,
>> +
>> +	TP_PROTO(const char *name, int ch_num, u64 wp, __le64 tre_ptr,
>> +		 __le32 dword0, __le32 dword1),
>> +
>> +	TP_ARGS(name, ch_num, wp, tre_ptr, dword0, dword1),
>> +
>> +	TP_STRUCT__entry(
>> +		__string(name, name)
>> +		__field(int, ch_num)
> This is fine as __string() is four bytes in the event (2 bytes for offset
> where the string exists, and 2 bytes for its length).
>
>> +		__field(u64, wp)
>> +		__field(__le64, tre_ptr)
> Which makes the two 8 byte fields aligned. Good!
>
>> +		__field(__le32, dword0)
>> +		__field(__le32, dword1)
>> +	),
>> +
>> +	TP_fast_assign(
>> +		__assign_str(name, name);
>> +		__entry->ch_num = ch_num;
>> +		__entry->wp = wp;
>> +		__entry->tre_ptr = tre_ptr;
>> +		__entry->dword0 = dword0;
>> +		__entry->dword1 = dword1;
>> +	),
>> +
>> +	TP_printk("%s: Chan: %d WP: 0x%llx TRE: 0x%llx 0x%08x 0x%08x\n",
>> +		  __get_str(name), __entry->ch_num, __entry->wp, __entry->tre_ptr,
>> +		  __entry->dword0, __entry->dword1)
>> +);
>> +
>> +TRACE_EVENT(mhi_intvec_threaded_handler,
>> +
>> +	TP_PROTO(const char *name, int local_ee, int state, int dev_ee, int dev_state),
>> +
>> +	TP_ARGS(name, local_ee, state, dev_ee, dev_state),
>> +
>> +	TP_STRUCT__entry(
>> +		__string(name, name)
>> +		__field(int, local_ee)
>> +		__field(int, state)
>> +		__field(int, dev_ee)
>> +		__field(int, dev_state)
>> +	),
>> +
>> +	TP_fast_assign(
>> +		__assign_str(name, name);
>> +		__entry->local_ee = local_ee;
>> +		__entry->state = state;
>> +		__entry->dev_ee = dev_ee;
>> +		__entry->dev_state = dev_state;
>> +	),
>> +
>> +	TP_printk("%s: local ee: %s state: %s device ee: %s state: %s\n",
>> +		  __get_str(name),
>> +		  __print_symbolic(__entry->local_ee, MHI_EE),
>> +		  __print_symbolic(__entry->state, MHI_STATE),
>> +		  __print_symbolic(__entry->dev_ee, MHI_EE),
>> +		  __print_symbolic(__entry->dev_state, MHI_STATE))
>> +);
>> +
>> +TRACE_EVENT(mhi_tryset_pm_state,
>> +
>> +	TP_PROTO(const char *name, int pm_state),
>> +
>> +	TP_ARGS(name, pm_state),
>> +
>> +	TP_STRUCT__entry(
>> +		__string(name, name)
>> +		__field(int, pm_state)
>> +	),
>> +
>> +	TP_fast_assign(
>> +		__assign_str(name, name);
>> +		if (pm_state)
>> +			pm_state = __fls(pm_state);
>> +		__entry->pm_state = pm_state;
>> +	),
>> +
>> +	TP_printk("%s: PM state: %s\n", __get_str(name),
>> +		  __print_symbolic(__entry->pm_state, MHI_PM_STATE))
>> +);
>> +
>> +TRACE_EVENT(mhi_process_data_event_ring,
>> +
>> +	TP_PROTO(const char *name, __le64 ptr, __le32 dword0, __le32 dword1),
>> +
>> +	TP_ARGS(name, ptr, dword0, dword1),
>> +
>> +	TP_STRUCT__entry(
>> +		__string(name, name)
>> +		__field(__le64, ptr)
> Here, I would switch the __field(__le64, ptr) with the __string().
>
> 		__field(__le64, ptr)
> 		__string(name, name)
>
> otherwise you just created a 4 byte hole in the ring buffer, wasting
> precious ring buffer space.
>
>> +		__field(__le32, dword0)
>> +		__field(__le32, dword1)
>> +	),
>> +
>> +	TP_fast_assign(
>> +		__assign_str(name, name);
>> +		__entry->ptr = ptr;
>> +		__entry->dword0 = dword0;
>> +		__entry->dword1 = dword1;
>> +	),
>> +
>> +	TP_printk("%s: Processing Event:0x%llx 0x%08x 0x%08x\n",
>> +		  __get_str(name), __entry->ptr, __entry->dword0, __entry->dword1)
>> +);
>> +
>> +TRACE_EVENT(mhi_process_ctrl_ev_ring,
>> +
>> +	TP_PROTO(const char *name, u64 rp, __le64 ptr, __le32 dword0, __le32 dword1, int state),
>> +
>> +	TP_ARGS(name, rp, ptr, dword0, dword1, state),
>> +
>> +	TP_STRUCT__entry(
>> +		__string(name, name)
>> +		__field(u64, rp)
>> +		__field(__le64, ptr)
> I would move __string(name, name) here (after the two 8 byte fields).
>
> -- Steve

I will reoder as suggested in my next patch.

-- KC.

>> +		__field(__le32, dword0)
>> +		__field(__le32, dword1)
>> +		__field(int, state)
>> +	),
>> +
>> +	TP_fast_assign(
>> +		__assign_str(name, name);
>> +		__entry->rp = rp;
>> +		__entry->ptr = ptr;
>> +		__entry->dword0 = dword0;
>> +		__entry->dword1 = dword1;
>> +		__entry->state = state;
>> +	),
>> +
>> +	TP_printk("%s: RP:0x%llx Processing Event:0x%llx 0x%08x 0x%08x state:%s\n",
>> +		  __get_str(name), __entry->rp, __entry->ptr, __entry->dword0,
>> +		  __entry->dword1, __print_symbolic(__entry->state, MHI_STATE))
>> +);
>> +
>> +TRACE_EVENT(mhi_update_channel_state_start,
>> +
>> +	TP_PROTO(const char *name, int ch_num, int state),
>> +
>> +	TP_ARGS(name, ch_num, state),
>> +
>> +	TP_STRUCT__entry(
>> +		__string(name, name)
>> +		__field(int, ch_num)
>> +		__field(int, state)
>> +	),
>> +
>> +	TP_fast_assign(
>> +		__assign_str(name, name);
>> +		__entry->ch_num = ch_num;
>> +		__entry->state = state;
>> +	),
>> +
>> +	TP_printk("%s: ch%d: Updating state to: %s\n",
>> +		  __get_str(name), __entry->ch_num,
>> +		  __print_symbolic(__entry->state, MHI_CH_STATE))
>> +);
>> +
>> +TRACE_EVENT(mhi_update_channel_state_end,
>> +
>> +	TP_PROTO(const char *name, int ch_num, int state),
>> +
>> +	TP_ARGS(name, ch_num, state),
>> +
>> +	TP_STRUCT__entry(
>> +		__string(name, name)
>> +		__field(int, ch_num)
>> +		__field(int, state)
>> +	),
>> +
>> +	TP_fast_assign(
>> +		__assign_str(name, name);
>> +		__entry->ch_num = ch_num;
>> +		__entry->state = state;
>> +	),
>> +
>> +	TP_printk("%s: ch%d: Updated state to: %s\n",
>> +		  __get_str(name), __entry->ch_num,
>> +		  __print_symbolic(__entry->state, MHI_CH_STATE))
>> +);
>> +
>> +TRACE_EVENT(mhi_pm_st_transition,
>> +
>> +	TP_PROTO(const char *name, int state),
>> +
>> +	TP_ARGS(name, state),
>> +
>> +	TP_STRUCT__entry(
>> +		__string(name, name)
>> +		__field(int, state)
>> +	),
>> +
>> +	TP_fast_assign(
>> +		__assign_str(name, name);
>> +		__entry->state = state;
>> +	),
>> +
>> +	TP_printk("%s: Handling state transition: %s\n", __get_str(name),
>> +		  __print_symbolic(__entry->state, MHI_DEV_ST_TRANSITION))
>> +);
>> +
>> +#endif
>> +#include <trace/define_trace.h>
kernel test robot Oct. 20, 2023, 3:27 a.m. UTC | #4
Hi Krishna,

kernel test robot noticed the following build warnings:

[auto build test WARNING on 3006adf3be79cde4d14b1800b963b82b6e5572e0]

url:    https://github.com/intel-lab-lkp/linux/commits/Krishna-chaitanya-chundru/bus-mhi-host-Add-tracing-support/20231017-120241
base:   3006adf3be79cde4d14b1800b963b82b6e5572e0
patch link:    https://lore.kernel.org/r/20231013-ftrace_support-v2-1-6e893ce010b5%40quicinc.com
patch subject: [PATCH v2] bus: mhi: host: Add tracing support
config: i386-randconfig-002-20231020 (https://download.01.org/0day-ci/archive/20231020/202310201110.S903HmeD-lkp@intel.com/config)
compiler: gcc-7 (Ubuntu 7.5.0-6ubuntu2) 7.5.0
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20231020/202310201110.S903HmeD-lkp@intel.com/reproduce)

If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202310201110.S903HmeD-lkp@intel.com/

All warnings (new ones prefixed by >>):

>> drivers/bus/mhi/host/main.c:249:12: warning: no previous declaration for 'mhi_to_physical' [-Wmissing-declarations]
    dma_addr_t mhi_to_physical(struct mhi_ring *ring, void *addr)
               ^~~~~~~~~~~~~~~


vim +/mhi_to_physical +249 drivers/bus/mhi/host/main.c

   248	
 > 249	dma_addr_t mhi_to_physical(struct mhi_ring *ring, void *addr)
   250	{
   251		return (addr - ring->base) + ring->iommu_base;
   252	}
   253
Jeffrey Hugo Oct. 20, 2023, 3:03 p.m. UTC | #5
On 10/13/2023 3:52 AM, Krishna chaitanya chundru wrote:
> This change adds ftrace support for following functions which
> helps in debugging the issues when there is Channel state & MHI
> state change and also when we receive data and control events:
> 1. mhi_intvec_threaded_handler
> 2. mhi_process_data_event_ring
> 3. mhi_process_ctrl_ev_ring
> 4. mhi_gen_tre
> 5. mhi_update_channel_state
> 6. mhi_tryset_pm_state
> 7. mhi_pm_st_worker
> 
> Signed-off-by: Krishna chaitanya chundru <quic_krichai@quicinc.com>
> ---
> Changes in v2:
> - Passing the raw state into the trace event and using  __print_symbolic() as suggested by bjorn.
> - Change mhi_pm_st_worker to mhi_pm_st_transition as suggested by bjorn.
> - Fixed the kernel test rebot issues.
> - Link to v1: https://lore.kernel.org/r/20231005-ftrace_support-v1-1-23a2f394fa49@quicinc.com
> ---
>   MAINTAINERS                     |   1 +
>   drivers/bus/mhi/host/init.c     |   3 +
>   drivers/bus/mhi/host/internal.h |   1 +
>   drivers/bus/mhi/host/main.c     |  32 +++--
>   drivers/bus/mhi/host/pm.c       |   6 +-
>   include/trace/events/mhi_host.h | 287 ++++++++++++++++++++++++++++++++++++++++
>   6 files changed, 317 insertions(+), 13 deletions(-)
> 
> diff --git a/MAINTAINERS b/MAINTAINERS
> index 35977b269d5e..4339c668a6ab 100644
> --- a/MAINTAINERS
> +++ b/MAINTAINERS
> @@ -13862,6 +13862,7 @@ F:	Documentation/mhi/
>   F:	drivers/bus/mhi/
>   F:	drivers/pci/endpoint/functions/pci-epf-mhi.c
>   F:	include/linux/mhi.h
> +F:	include/trace/events/mhi_host.h
>   
>   MICROBLAZE ARCHITECTURE
>   M:	Michal Simek <monstr@monstr.eu>
> diff --git a/drivers/bus/mhi/host/init.c b/drivers/bus/mhi/host/init.c
> index f78aefd2d7a3..3afa90a204fd 100644
> --- a/drivers/bus/mhi/host/init.c
> +++ b/drivers/bus/mhi/host/init.c
> @@ -20,6 +20,9 @@
>   #include <linux/wait.h>
>   #include "internal.h"
>   
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/mhi_host.h>

This feels redundant to me.  A few lines ago we included internal.h, and 
internal.h includes trace/events/mhi_host.h

> +
>   static DEFINE_IDA(mhi_controller_ida);
>   
>   const char * const mhi_ee_str[MHI_EE_MAX] = {
> diff --git a/drivers/bus/mhi/host/internal.h b/drivers/bus/mhi/host/internal.h
> index 2e139e76de4c..a80a317a59a9 100644
> --- a/drivers/bus/mhi/host/internal.h
> +++ b/drivers/bus/mhi/host/internal.h
> @@ -7,6 +7,7 @@
>   #ifndef _MHI_INT_H
>   #define _MHI_INT_H
>   
> +#include <trace/events/mhi_host.h>
>   #include "../common.h"
>   
>   extern struct bus_type mhi_bus_type;
> diff --git a/drivers/bus/mhi/host/main.c b/drivers/bus/mhi/host/main.c
> index dcf627b36e82..fcdb728ba49f 100644
> --- a/drivers/bus/mhi/host/main.c
> +++ b/drivers/bus/mhi/host/main.c
> @@ -246,6 +246,11 @@ static void *mhi_to_virtual(struct mhi_ring *ring, dma_addr_t addr)
>   	return (addr - ring->iommu_base) + ring->base;
>   }
>   
> +dma_addr_t mhi_to_physical(struct mhi_ring *ring, void *addr)
> +{
> +	return (addr - ring->base) + ring->iommu_base;
> +}

This seems to be poorly named since we are using the iommu_base which 
suggests we are converting to an IOVA.

Why do we need this though?  This seems like it might be a security 
issue, or at the very least, not preferred, and I'm struggling to figure 
out what value this provides to you are I when looking at the log.

> +
>   static void mhi_add_ring_element(struct mhi_controller *mhi_cntrl,
>   				 struct mhi_ring *ring)
>   {
> @@ -491,11 +496,9 @@ irqreturn_t mhi_intvec_threaded_handler(int irq_number, void *priv)
>   
>   	state = mhi_get_mhi_state(mhi_cntrl);
>   	ee = mhi_get_exec_env(mhi_cntrl);
> -	dev_dbg(dev, "local ee: %s state: %s device ee: %s state: %s\n",
> -		TO_MHI_EXEC_STR(mhi_cntrl->ee),
> -		mhi_state_str(mhi_cntrl->dev_state),
> -		TO_MHI_EXEC_STR(ee), mhi_state_str(state));
>   
> +	trace_mhi_intvec_threaded_handler(mhi_cntrl->mhi_dev->name, mhi_cntrl->ee,
> +					  mhi_cntrl->dev_state, ee, state);

Why are we removing the debug message when adding this trace?  The 
commit text doesn't say.  (Looks like you do this several times, assume 
this comment applies to all isntances)

>   	if (state == MHI_STATE_SYS_ERR) {
>   		dev_dbg(dev, "System error detected\n");
>   		pm_state = mhi_tryset_pm_state(mhi_cntrl,
> @@ -832,6 +835,12 @@ int mhi_process_ctrl_ev_ring(struct mhi_controller *mhi_cntrl,
>   	while (dev_rp != local_rp) {
>   		enum mhi_pkt_type type = MHI_TRE_GET_EV_TYPE(local_rp);
>   
> +		trace_mhi_process_ctrl_ev_ring(mhi_cntrl->mhi_dev->name,
> +					       mhi_to_physical(ev_ring, local_rp),
> +					       local_rp->ptr, local_rp->dword[0],
> +					       local_rp->dword[1],
> +					       MHI_TRE_GET_EV_STATE(local_rp));

Why not just pass in the local_rp as a single parameter and have the 
trace implementation decode it?  (Looks like you do this several times, 
assume this comment applies to all isntances)

> +
>   		switch (type) {
>   		case MHI_PKT_TYPE_BW_REQ_EVENT:
>   		{
> @@ -997,6 +1006,9 @@ int mhi_process_data_event_ring(struct mhi_controller *mhi_cntrl,
>   	while (dev_rp != local_rp && event_quota > 0) {
>   		enum mhi_pkt_type type = MHI_TRE_GET_EV_TYPE(local_rp);
>   
> +		trace_mhi_process_data_event_ring(mhi_cntrl->mhi_dev->name, local_rp->ptr,
> +						  local_rp->dword[0], local_rp->dword[1]);
> +
>   		chan = MHI_TRE_GET_EV_CHID(local_rp);
>   
>   		WARN_ON(chan >= mhi_cntrl->max_chan);
> @@ -1235,6 +1247,9 @@ int mhi_gen_tre(struct mhi_controller *mhi_cntrl, struct mhi_chan *mhi_chan,
>   	mhi_tre->dword[0] = MHI_TRE_DATA_DWORD0(info->len);
>   	mhi_tre->dword[1] = MHI_TRE_DATA_DWORD1(bei, eot, eob, chain);
>   
> +	trace_mhi_gen_tre(mhi_cntrl->mhi_dev->name, mhi_chan->chan,
> +			  mhi_to_physical(tre_ring, mhi_tre),
> +			  mhi_tre->ptr, mhi_tre->dword[0], mhi_tre->dword[1]);
>   	/* increment WP */
>   	mhi_add_ring_element(mhi_cntrl, tre_ring);
>   	mhi_add_ring_element(mhi_cntrl, buf_ring);
> @@ -1327,9 +1342,8 @@ static int mhi_update_channel_state(struct mhi_controller *mhi_cntrl,
>   	enum mhi_cmd_type cmd = MHI_CMD_NOP;
>   	int ret;
>   
> -	dev_dbg(dev, "%d: Updating channel state to: %s\n", mhi_chan->chan,
> -		TO_CH_STATE_TYPE_STR(to_state));
> -
> +	trace_mhi_update_channel_state_start(mhi_cntrl->mhi_dev->name, mhi_chan->chan,
> +					     to_state);
>   	switch (to_state) {
>   	case MHI_CH_STATE_TYPE_RESET:
>   		write_lock_irq(&mhi_chan->lock);
> @@ -1396,9 +1410,7 @@ static int mhi_update_channel_state(struct mhi_controller *mhi_cntrl,
>   		write_unlock_irq(&mhi_chan->lock);
>   	}
>   
> -	dev_dbg(dev, "%d: Channel state change to %s successful\n",
> -		mhi_chan->chan, TO_CH_STATE_TYPE_STR(to_state));
> -
> +	trace_mhi_update_channel_state_end(mhi_cntrl->mhi_dev->name, mhi_chan->chan, to_state);
>   exit_channel_update:
>   	mhi_cntrl->runtime_put(mhi_cntrl);
>   	mhi_device_put(mhi_cntrl->mhi_dev);
> diff --git a/drivers/bus/mhi/host/pm.c b/drivers/bus/mhi/host/pm.c
> index 8a4362d75fc4..e32afdc92fde 100644
> --- a/drivers/bus/mhi/host/pm.c
> +++ b/drivers/bus/mhi/host/pm.c
> @@ -123,6 +123,7 @@ enum mhi_pm_state __must_check mhi_tryset_pm_state(struct mhi_controller *mhi_cn
>   	if (unlikely(!(dev_state_transitions[index].to_states & state)))
>   		return cur_state;
>   
> +	trace_mhi_tryset_pm_state(mhi_cntrl->mhi_dev->name, state);
>   	mhi_cntrl->pm_state = state;
>   	return mhi_cntrl->pm_state;
>   }
> @@ -753,7 +754,6 @@ void mhi_pm_st_worker(struct work_struct *work)
>   	struct mhi_controller *mhi_cntrl = container_of(work,
>   							struct mhi_controller,
>   							st_worker);
> -	struct device *dev = &mhi_cntrl->mhi_dev->dev;
>   
>   	spin_lock_irq(&mhi_cntrl->transition_lock);
>   	list_splice_tail_init(&mhi_cntrl->transition_list, &head);
> @@ -761,8 +761,8 @@ void mhi_pm_st_worker(struct work_struct *work)
>   
>   	list_for_each_entry_safe(itr, tmp, &head, node) {
>   		list_del(&itr->node);
> -		dev_dbg(dev, "Handling state transition: %s\n",
> -			TO_DEV_STATE_TRANS_STR(itr->state));
> +
> +		trace_mhi_pm_st_transition(mhi_cntrl->mhi_dev->name, itr->state);
>   
>   		switch (itr->state) {
>   		case DEV_ST_TRANSITION_PBL:
> diff --git a/include/trace/events/mhi_host.h b/include/trace/events/mhi_host.h
> new file mode 100644
> index 000000000000..a496d99f8fad
> --- /dev/null
> +++ b/include/trace/events/mhi_host.h
> @@ -0,0 +1,287 @@
> +/* SPDX-License-Identifier: GPL-2.0-only */
> +/*
> + * Copyright (c) 2023 Qualcomm Innovation Center, Inc. All rights reserved.
> + */
> +
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM mhi_host
> +
> +#if !defined(_TRACE_EVENT_MHI_HOST_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_EVENT_MHI_HOST_H
> +
> +#include <linux/tracepoint.h>
> +#define MHI_STATE						\
> +	EM(MHI_STATE_RESET,	"RESET")			\
> +	EM(MHI_STATE_READY,	"READY")			\
> +	EM(MHI_STATE_M0,	"M0")				\
> +	EM(MHI_STATE_M1,	"M1")				\
> +	EM(MHI_STATE_M2,	"M2")				\
> +	EM(MHI_STATE_M3,	"M3")				\
> +	EM(MHI_STATE_M3_FAST,	"M3 FAST")			\
> +	EM(MHI_STATE_BHI,	"BHI")				\
> +	EMe(MHI_STATE_SYS_ERR,	"SYS ERROR")
> +
> +#define MHI_EE							\
> +	EM(MHI_EE_PBL,		"PRIMARY BOOTLOADER")		\
> +	EM(MHI_EE_SBL,		"SECONDARY BOOTLOADER")		\
> +	EM(MHI_EE_AMSS,		"MISSION MODE")			\
> +	EM(MHI_EE_RDDM,		"RAMDUMP DOWNLOAD MODE")	\
> +	EM(MHI_EE_WFW,		"WLAN FIRMWARE")		\
> +	EM(MHI_EE_PTHRU,	"PASS THROUGH")			\
> +	EM(MHI_EE_EDL,		"EMERGENCY DOWNLOAD")		\
> +	EM(MHI_EE_FP,		"FLASH PROGRAMMER")		\
> +	EM(MHI_EE_DISABLE_TRANSITION,	"DISABLE")		\
> +	EMe(MHI_EE_NOT_SUPPORTED,	"NOT SUPPORTED")
> +
> +#define MHI_PM_STATE							\
> +	EM(MHI_PM_STATE_DISABLE,	"DISABLE")			\
> +	EM(MHI_PM_STATE_POR,		"POWER ON RESET")		\
> +	EM(MHI_PM_STATE_M0,		"M0")				\
> +	EM(MHI_PM_STATE_M2,		"M2")				\
> +	EM(MHI_PM_STATE_M3_ENTER,	"M?->M3")			\
> +	EM(MHI_PM_STATE_M3,		"M3")				\
> +	EM(MHI_PM_STATE_M3_EXIT,	"M3->M0")			\
> +	EM(MHI_PM_STATE_FW_DL_ERR,	"Firmware Download Error")	\
> +	EM(MHI_PM_STATE_SYS_ERR_DETECT,		"SYS ERROR Detect")	\
> +	EM(MHI_PM_STATE_SYS_ERR_PROCESS,	"SYS ERROR Process")	\
> +	EM(MHI_PM_STATE_SHUTDOWN_PROCESS,	"SHUTDOWN Process")	\
> +	EMe(MHI_PM_STATE_LD_ERR_FATAL_DETECT,	"Linkdown or Error Fatal Detect")
> +
> +#define MHI_CH_STATE						\
> +	EM(MHI_CH_STATE_TYPE_RESET, "RESET")			\
> +	EM(MHI_CH_STATE_TYPE_STOP, "STOP")			\
> +	EMe(MHI_CH_STATE_TYPE_START, "START")
> +
> +#define MHI_DEV_ST_TRANSITION						\
> +	EM(DEV_ST_TRANSITION_PBL,	"PBL")				\
> +	EM(DEV_ST_TRANSITION_READY,	"READY")			\
> +	EM(DEV_ST_TRANSITION_SBL,	"SBL")				\
> +	EM(DEV_ST_TRANSITION_MISSION_MODE,	"MISSION MODE")		\
> +	EM(DEV_ST_TRANSITION_FP,		"FLASH PROGRAMMER")	\
> +	EM(DEV_ST_TRANSITION_SYS_ERR,		"SYS ERROR")		\
> +	EMe(DEV_ST_TRANSITION_DISABLE,		"DISABLE")
> +
> +/* Enums require being exported to userspace, for user tool parsing */
> +#undef	EM
> +#undef	EMe
> +#define	EM(a, b)	TRACE_DEFINE_ENUM(a);
> +#define	EMe(a, b)	TRACE_DEFINE_ENUM(a);
> +
> +MHI_STATE
> +MHI_EE
> +MHI_PM_STATE
> +MHI_CH_STATE
> +MHI_DEV_ST_TRANSITION
> +
> +/*
> + * Now redefine the EM() and EMe() macros to map the enums to the strings
> + * that will be printed in the output.
> + */
> +#undef EM
> +#undef EMe
> +#define EM(a, b)	{a, b},
> +#define EMe(a, b)	{a, b}
> +
> +TRACE_EVENT(mhi_gen_tre,
> +
> +	TP_PROTO(const char *name, int ch_num, u64 wp, __le64 tre_ptr,
> +		 __le32 dword0, __le32 dword1),
> +
> +	TP_ARGS(name, ch_num, wp, tre_ptr, dword0, dword1),
> +
> +	TP_STRUCT__entry(
> +		__string(name, name)
> +		__field(int, ch_num)
> +		__field(u64, wp)
> +		__field(__le64, tre_ptr)
> +		__field(__le32, dword0)
> +		__field(__le32, dword1)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, name);
> +		__entry->ch_num = ch_num;
> +		__entry->wp = wp;
> +		__entry->tre_ptr = tre_ptr;
> +		__entry->dword0 = dword0;
> +		__entry->dword1 = dword1;
> +	),
> +
> +	TP_printk("%s: Chan: %d WP: 0x%llx TRE: 0x%llx 0x%08x 0x%08x\n",
> +		  __get_str(name), __entry->ch_num, __entry->wp, __entry->tre_ptr,
> +		  __entry->dword0, __entry->dword1)
> +);
> +
> +TRACE_EVENT(mhi_intvec_threaded_handler,
> +
> +	TP_PROTO(const char *name, int local_ee, int state, int dev_ee, int dev_state),
> +
> +	TP_ARGS(name, local_ee, state, dev_ee, dev_state),
> +
> +	TP_STRUCT__entry(
> +		__string(name, name)
> +		__field(int, local_ee)
> +		__field(int, state)
> +		__field(int, dev_ee)
> +		__field(int, dev_state)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, name);
> +		__entry->local_ee = local_ee;
> +		__entry->state = state;
> +		__entry->dev_ee = dev_ee;
> +		__entry->dev_state = dev_state;
> +	),
> +
> +	TP_printk("%s: local ee: %s state: %s device ee: %s state: %s\n",
> +		  __get_str(name),
> +		  __print_symbolic(__entry->local_ee, MHI_EE),
> +		  __print_symbolic(__entry->state, MHI_STATE),
> +		  __print_symbolic(__entry->dev_ee, MHI_EE),
> +		  __print_symbolic(__entry->dev_state, MHI_STATE))
> +);
> +
> +TRACE_EVENT(mhi_tryset_pm_state,
> +
> +	TP_PROTO(const char *name, int pm_state),
> +
> +	TP_ARGS(name, pm_state),
> +
> +	TP_STRUCT__entry(
> +		__string(name, name)
> +		__field(int, pm_state)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, name);
> +		if (pm_state)
> +			pm_state = __fls(pm_state);
> +		__entry->pm_state = pm_state;
> +	),
> +
> +	TP_printk("%s: PM state: %s\n", __get_str(name),
> +		  __print_symbolic(__entry->pm_state, MHI_PM_STATE))
> +);
> +
> +TRACE_EVENT(mhi_process_data_event_ring,
> +
> +	TP_PROTO(const char *name, __le64 ptr, __le32 dword0, __le32 dword1),
> +
> +	TP_ARGS(name, ptr, dword0, dword1),
> +
> +	TP_STRUCT__entry(
> +		__string(name, name)
> +		__field(__le64, ptr)
> +		__field(__le32, dword0)
> +		__field(__le32, dword1)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, name);
> +		__entry->ptr = ptr;
> +		__entry->dword0 = dword0;
> +		__entry->dword1 = dword1;
> +	),
> +
> +	TP_printk("%s: Processing Event:0x%llx 0x%08x 0x%08x\n",
> +		  __get_str(name), __entry->ptr, __entry->dword0, __entry->dword1)
> +);
> +
> +TRACE_EVENT(mhi_process_ctrl_ev_ring,
> +
> +	TP_PROTO(const char *name, u64 rp, __le64 ptr, __le32 dword0, __le32 dword1, int state),
> +
> +	TP_ARGS(name, rp, ptr, dword0, dword1, state),
> +
> +	TP_STRUCT__entry(
> +		__string(name, name)
> +		__field(u64, rp)
> +		__field(__le64, ptr)
> +		__field(__le32, dword0)
> +		__field(__le32, dword1)
> +		__field(int, state)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, name);
> +		__entry->rp = rp;
> +		__entry->ptr = ptr;
> +		__entry->dword0 = dword0;
> +		__entry->dword1 = dword1;
> +		__entry->state = state;
> +	),
> +
> +	TP_printk("%s: RP:0x%llx Processing Event:0x%llx 0x%08x 0x%08x state:%s\n",
> +		  __get_str(name), __entry->rp, __entry->ptr, __entry->dword0,
> +		  __entry->dword1, __print_symbolic(__entry->state, MHI_STATE))
> +);
> +
> +TRACE_EVENT(mhi_update_channel_state_start,
> +
> +	TP_PROTO(const char *name, int ch_num, int state),
> +
> +	TP_ARGS(name, ch_num, state),
> +
> +	TP_STRUCT__entry(
> +		__string(name, name)
> +		__field(int, ch_num)
> +		__field(int, state)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, name);
> +		__entry->ch_num = ch_num;
> +		__entry->state = state;
> +	),
> +
> +	TP_printk("%s: ch%d: Updating state to: %s\n",
> +		  __get_str(name), __entry->ch_num,
> +		  __print_symbolic(__entry->state, MHI_CH_STATE))
> +);
> +
> +TRACE_EVENT(mhi_update_channel_state_end,
> +
> +	TP_PROTO(const char *name, int ch_num, int state),
> +
> +	TP_ARGS(name, ch_num, state),
> +
> +	TP_STRUCT__entry(
> +		__string(name, name)
> +		__field(int, ch_num)
> +		__field(int, state)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, name);
> +		__entry->ch_num = ch_num;
> +		__entry->state = state;
> +	),
> +
> +	TP_printk("%s: ch%d: Updated state to: %s\n",
> +		  __get_str(name), __entry->ch_num,
> +		  __print_symbolic(__entry->state, MHI_CH_STATE))
> +);
> +
> +TRACE_EVENT(mhi_pm_st_transition,
> +
> +	TP_PROTO(const char *name, int state),
> +
> +	TP_ARGS(name, state),
> +
> +	TP_STRUCT__entry(
> +		__string(name, name)
> +		__field(int, state)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, name);
> +		__entry->state = state;
> +	),
> +
> +	TP_printk("%s: Handling state transition: %s\n", __get_str(name),
> +		  __print_symbolic(__entry->state, MHI_DEV_ST_TRANSITION))
> +);
> +
> +#endif
> +#include <trace/define_trace.h>
> 
> ---
> base-commit: 3006adf3be79cde4d14b1800b963b82b6e5572e0
> change-id: 20231005-ftrace_support-6869d4156139
> 
> Best regards,
Steven Rostedt Oct. 20, 2023, 4:28 p.m. UTC | #6
On Fri, 20 Oct 2023 09:03:59 -0600
Jeffrey Hugo <quic_jhugo@quicinc.com> wrote:

> > diff --git a/drivers/bus/mhi/host/init.c b/drivers/bus/mhi/host/init.c
> > index f78aefd2d7a3..3afa90a204fd 100644
> > --- a/drivers/bus/mhi/host/init.c
> > +++ b/drivers/bus/mhi/host/init.c
> > @@ -20,6 +20,9 @@
> >   #include <linux/wait.h>
> >   #include "internal.h"
> >   
> > +#define CREATE_TRACE_POINTS
> > +#include <trace/events/mhi_host.h>  
> 
> This feels redundant to me.  A few lines ago we included internal.h, and 
> internal.h includes trace/events/mhi_host.h

It's not redundant. The #define CREATE_TRACE_POINTS enables the magic of
creating the tracepoints and trace events via the TRACE_EVENT() macro.

It should never be done in a header file, only in .c code!

The header file include of trace headers are used for having access to the
declarations of the functions. That is (trace_*()) in the code.

-- Steve
Krishna Chaitanya Chundru Oct. 23, 2023, 7:11 a.m. UTC | #7
On 10/20/2023 8:33 PM, Jeffrey Hugo wrote:
> On 10/13/2023 3:52 AM, Krishna chaitanya chundru wrote:
>> This change adds ftrace support for following functions which
>> helps in debugging the issues when there is Channel state & MHI
>> state change and also when we receive data and control events:
>> 1. mhi_intvec_threaded_handler
>> 2. mhi_process_data_event_ring
>> 3. mhi_process_ctrl_ev_ring
>> 4. mhi_gen_tre
>> 5. mhi_update_channel_state
>> 6. mhi_tryset_pm_state
>> 7. mhi_pm_st_worker
>>
>> Signed-off-by: Krishna chaitanya chundru <quic_krichai@quicinc.com>
>> ---
>> Changes in v2:
>> - Passing the raw state into the trace event and using 
>> __print_symbolic() as suggested by bjorn.
>> - Change mhi_pm_st_worker to mhi_pm_st_transition as suggested by bjorn.
>> - Fixed the kernel test rebot issues.
>> - Link to v1: 
>> https://lore.kernel.org/r/20231005-ftrace_support-v1-1-23a2f394fa49@quicinc.com
>> ---
>>   MAINTAINERS                     |   1 +
>>   drivers/bus/mhi/host/init.c     |   3 +
>>   drivers/bus/mhi/host/internal.h |   1 +
>>   drivers/bus/mhi/host/main.c     |  32 +++--
>>   drivers/bus/mhi/host/pm.c       |   6 +-
>>   include/trace/events/mhi_host.h | 287 
>> ++++++++++++++++++++++++++++++++++++++++
>>   6 files changed, 317 insertions(+), 13 deletions(-)
>>
>> diff --git a/MAINTAINERS b/MAINTAINERS
>> index 35977b269d5e..4339c668a6ab 100644
>> --- a/MAINTAINERS
>> +++ b/MAINTAINERS
>> @@ -13862,6 +13862,7 @@ F:    Documentation/mhi/
>>   F:    drivers/bus/mhi/
>>   F:    drivers/pci/endpoint/functions/pci-epf-mhi.c
>>   F:    include/linux/mhi.h
>> +F:    include/trace/events/mhi_host.h
>>     MICROBLAZE ARCHITECTURE
>>   M:    Michal Simek <monstr@monstr.eu>
>> diff --git a/drivers/bus/mhi/host/init.c b/drivers/bus/mhi/host/init.c
>> index f78aefd2d7a3..3afa90a204fd 100644
>> --- a/drivers/bus/mhi/host/init.c
>> +++ b/drivers/bus/mhi/host/init.c
>> @@ -20,6 +20,9 @@
>>   #include <linux/wait.h>
>>   #include "internal.h"
>>   +#define CREATE_TRACE_POINTS
>> +#include <trace/events/mhi_host.h>
>
> This feels redundant to me.  A few lines ago we included internal.h, 
> and internal.h includes trace/events/mhi_host.h

As Steve mentioned, this is mandatory step for creating trace points & 
trace events.

>
>> +
>>   static DEFINE_IDA(mhi_controller_ida);
>>     const char * const mhi_ee_str[MHI_EE_MAX] = {
>> diff --git a/drivers/bus/mhi/host/internal.h 
>> b/drivers/bus/mhi/host/internal.h
>> index 2e139e76de4c..a80a317a59a9 100644
>> --- a/drivers/bus/mhi/host/internal.h
>> +++ b/drivers/bus/mhi/host/internal.h
>> @@ -7,6 +7,7 @@
>>   #ifndef _MHI_INT_H
>>   #define _MHI_INT_H
>>   +#include <trace/events/mhi_host.h>
>>   #include "../common.h"
>>     extern struct bus_type mhi_bus_type;
>> diff --git a/drivers/bus/mhi/host/main.c b/drivers/bus/mhi/host/main.c
>> index dcf627b36e82..fcdb728ba49f 100644
>> --- a/drivers/bus/mhi/host/main.c
>> +++ b/drivers/bus/mhi/host/main.c
>> @@ -246,6 +246,11 @@ static void *mhi_to_virtual(struct mhi_ring 
>> *ring, dma_addr_t addr)
>>       return (addr - ring->iommu_base) + ring->base;
>>   }
>>   +dma_addr_t mhi_to_physical(struct mhi_ring *ring, void *addr)
>> +{
>> +    return (addr - ring->base) + ring->iommu_base;
>> +}
>
> This seems to be poorly named since we are using the iommu_base which 
> suggests we are converting to an IOVA.
>
> Why do we need this though?  This seems like it might be a security 
> issue, or at the very least, not preferred, and I'm struggling to 
> figure out what value this provides to you are I when looking at the log.
>
I will rename the function to reflect it is converting to IOVA.

We MHI TRE we write the IOVA address, to correlate between TRE events in 
the MHI ring and event we are processing  we want to log the IOVA address.

As we are logging only IOVA address which is provided in the devicetree 
and not the original physical address we are not expecting any security 
issues here.

Correct me if I was wrong.

>> +
>>   static void mhi_add_ring_element(struct mhi_controller *mhi_cntrl,
>>                    struct mhi_ring *ring)
>>   {
>> @@ -491,11 +496,9 @@ irqreturn_t mhi_intvec_threaded_handler(int 
>> irq_number, void *priv)
>>         state = mhi_get_mhi_state(mhi_cntrl);
>>       ee = mhi_get_exec_env(mhi_cntrl);
>> -    dev_dbg(dev, "local ee: %s state: %s device ee: %s state: %s\n",
>> -        TO_MHI_EXEC_STR(mhi_cntrl->ee),
>> -        mhi_state_str(mhi_cntrl->dev_state),
>> -        TO_MHI_EXEC_STR(ee), mhi_state_str(state));
>>   + trace_mhi_intvec_threaded_handler(mhi_cntrl->mhi_dev->name, 
>> mhi_cntrl->ee,
>> +                      mhi_cntrl->dev_state, ee, state);
>
> Why are we removing the debug message when adding this trace?  The 
> commit text doesn't say.  (Looks like you do this several times, 
> assume this comment applies to all isntances)

I will add this in the commit text in my next patch.

Just a query is recommended to keep both debug message and trace events. 
If yes we will not remove the debug messages.

>
>>       if (state == MHI_STATE_SYS_ERR) {
>>           dev_dbg(dev, "System error detected\n");
>>           pm_state = mhi_tryset_pm_state(mhi_cntrl,
>> @@ -832,6 +835,12 @@ int mhi_process_ctrl_ev_ring(struct 
>> mhi_controller *mhi_cntrl,
>>       while (dev_rp != local_rp) {
>>           enum mhi_pkt_type type = MHI_TRE_GET_EV_TYPE(local_rp);
>>   + trace_mhi_process_ctrl_ev_ring(mhi_cntrl->mhi_dev->name,
>> +                           mhi_to_physical(ev_ring, local_rp),
>> +                           local_rp->ptr, local_rp->dword[0],
>> +                           local_rp->dword[1],
>> +                           MHI_TRE_GET_EV_STATE(local_rp));
>
> Why not just pass in the local_rp as a single parameter and have the 
> trace implementation decode it?  (Looks like you do this several 
> times, assume this comment applies to all isntances)

MHI_TRE_GET_EV_STATE definition is present in drivers/bus/mhi/common.h 
which is common for both EP & MHI driver.

If we keep this macro definition again in mhi_host.h it will be 
redundant one.

And we are only using this way only for this trace log. So we are using 
the macro to get the state information.

- KC

>
>> +
>>           switch (type) {
>>           case MHI_PKT_TYPE_BW_REQ_EVENT:
>>           {
>> @@ -997,6 +1006,9 @@ int mhi_process_data_event_ring(struct 
>> mhi_controller *mhi_cntrl,
>>       while (dev_rp != local_rp && event_quota > 0) {
>>           enum mhi_pkt_type type = MHI_TRE_GET_EV_TYPE(local_rp);
>>   + trace_mhi_process_data_event_ring(mhi_cntrl->mhi_dev->name, 
>> local_rp->ptr,
>> +                          local_rp->dword[0], local_rp->dword[1]);
>> +
>>           chan = MHI_TRE_GET_EV_CHID(local_rp);
>>             WARN_ON(chan >= mhi_cntrl->max_chan);
>> @@ -1235,6 +1247,9 @@ int mhi_gen_tre(struct mhi_controller 
>> *mhi_cntrl, struct mhi_chan *mhi_chan,
>>       mhi_tre->dword[0] = MHI_TRE_DATA_DWORD0(info->len);
>>       mhi_tre->dword[1] = MHI_TRE_DATA_DWORD1(bei, eot, eob, chain);
>>   +    trace_mhi_gen_tre(mhi_cntrl->mhi_dev->name, mhi_chan->chan,
>> +              mhi_to_physical(tre_ring, mhi_tre),
>> +              mhi_tre->ptr, mhi_tre->dword[0], mhi_tre->dword[1]);
>>       /* increment WP */
>>       mhi_add_ring_element(mhi_cntrl, tre_ring);
>>       mhi_add_ring_element(mhi_cntrl, buf_ring);
>> @@ -1327,9 +1342,8 @@ static int mhi_update_channel_state(struct 
>> mhi_controller *mhi_cntrl,
>>       enum mhi_cmd_type cmd = MHI_CMD_NOP;
>>       int ret;
>>   -    dev_dbg(dev, "%d: Updating channel state to: %s\n", 
>> mhi_chan->chan,
>> -        TO_CH_STATE_TYPE_STR(to_state));
>> -
>> + trace_mhi_update_channel_state_start(mhi_cntrl->mhi_dev->name, 
>> mhi_chan->chan,
>> +                         to_state);
>>       switch (to_state) {
>>       case MHI_CH_STATE_TYPE_RESET:
>>           write_lock_irq(&mhi_chan->lock);
>> @@ -1396,9 +1410,7 @@ static int mhi_update_channel_state(struct 
>> mhi_controller *mhi_cntrl,
>>           write_unlock_irq(&mhi_chan->lock);
>>       }
>>   -    dev_dbg(dev, "%d: Channel state change to %s successful\n",
>> -        mhi_chan->chan, TO_CH_STATE_TYPE_STR(to_state));
>> -
>> + trace_mhi_update_channel_state_end(mhi_cntrl->mhi_dev->name, 
>> mhi_chan->chan, to_state);
>>   exit_channel_update:
>>       mhi_cntrl->runtime_put(mhi_cntrl);
>>       mhi_device_put(mhi_cntrl->mhi_dev);
>> diff --git a/drivers/bus/mhi/host/pm.c b/drivers/bus/mhi/host/pm.c
>> index 8a4362d75fc4..e32afdc92fde 100644
>> --- a/drivers/bus/mhi/host/pm.c
>> +++ b/drivers/bus/mhi/host/pm.c
>> @@ -123,6 +123,7 @@ enum mhi_pm_state __must_check 
>> mhi_tryset_pm_state(struct mhi_controller *mhi_cn
>>       if (unlikely(!(dev_state_transitions[index].to_states & state)))
>>           return cur_state;
>>   +    trace_mhi_tryset_pm_state(mhi_cntrl->mhi_dev->name, state);
>>       mhi_cntrl->pm_state = state;
>>       return mhi_cntrl->pm_state;
>>   }
>> @@ -753,7 +754,6 @@ void mhi_pm_st_worker(struct work_struct *work)
>>       struct mhi_controller *mhi_cntrl = container_of(work,
>>                               struct mhi_controller,
>>                               st_worker);
>> -    struct device *dev = &mhi_cntrl->mhi_dev->dev;
>>         spin_lock_irq(&mhi_cntrl->transition_lock);
>>       list_splice_tail_init(&mhi_cntrl->transition_list, &head);
>> @@ -761,8 +761,8 @@ void mhi_pm_st_worker(struct work_struct *work)
>>         list_for_each_entry_safe(itr, tmp, &head, node) {
>>           list_del(&itr->node);
>> -        dev_dbg(dev, "Handling state transition: %s\n",
>> -            TO_DEV_STATE_TRANS_STR(itr->state));
>> +
>> + trace_mhi_pm_st_transition(mhi_cntrl->mhi_dev->name, itr->state);
>>             switch (itr->state) {
>>           case DEV_ST_TRANSITION_PBL:
>> diff --git a/include/trace/events/mhi_host.h 
>> b/include/trace/events/mhi_host.h
>> new file mode 100644
>> index 000000000000..a496d99f8fad
>> --- /dev/null
>> +++ b/include/trace/events/mhi_host.h
>> @@ -0,0 +1,287 @@
>> +/* SPDX-License-Identifier: GPL-2.0-only */
>> +/*
>> + * Copyright (c) 2023 Qualcomm Innovation Center, Inc. All rights 
>> reserved.
>> + */
>> +
>> +#undef TRACE_SYSTEM
>> +#define TRACE_SYSTEM mhi_host
>> +
>> +#if !defined(_TRACE_EVENT_MHI_HOST_H) || 
>> defined(TRACE_HEADER_MULTI_READ)
>> +#define _TRACE_EVENT_MHI_HOST_H
>> +
>> +#include <linux/tracepoint.h>
>> +#define MHI_STATE                        \
>> +    EM(MHI_STATE_RESET,    "RESET")            \
>> +    EM(MHI_STATE_READY,    "READY")            \
>> +    EM(MHI_STATE_M0,    "M0")                \
>> +    EM(MHI_STATE_M1,    "M1")                \
>> +    EM(MHI_STATE_M2,    "M2")                \
>> +    EM(MHI_STATE_M3,    "M3")                \
>> +    EM(MHI_STATE_M3_FAST,    "M3 FAST")            \
>> +    EM(MHI_STATE_BHI,    "BHI")                \
>> +    EMe(MHI_STATE_SYS_ERR,    "SYS ERROR")
>> +
>> +#define MHI_EE                            \
>> +    EM(MHI_EE_PBL,        "PRIMARY BOOTLOADER")        \
>> +    EM(MHI_EE_SBL,        "SECONDARY BOOTLOADER")        \
>> +    EM(MHI_EE_AMSS,        "MISSION MODE")            \
>> +    EM(MHI_EE_RDDM,        "RAMDUMP DOWNLOAD MODE")    \
>> +    EM(MHI_EE_WFW,        "WLAN FIRMWARE")        \
>> +    EM(MHI_EE_PTHRU,    "PASS THROUGH")            \
>> +    EM(MHI_EE_EDL,        "EMERGENCY DOWNLOAD")        \
>> +    EM(MHI_EE_FP,        "FLASH PROGRAMMER")        \
>> +    EM(MHI_EE_DISABLE_TRANSITION,    "DISABLE")        \
>> +    EMe(MHI_EE_NOT_SUPPORTED,    "NOT SUPPORTED")
>> +
>> +#define MHI_PM_STATE                            \
>> +    EM(MHI_PM_STATE_DISABLE,    "DISABLE")            \
>> +    EM(MHI_PM_STATE_POR,        "POWER ON RESET")        \
>> +    EM(MHI_PM_STATE_M0,        "M0")                \
>> +    EM(MHI_PM_STATE_M2,        "M2")                \
>> +    EM(MHI_PM_STATE_M3_ENTER,    "M?->M3")            \
>> +    EM(MHI_PM_STATE_M3,        "M3")                \
>> +    EM(MHI_PM_STATE_M3_EXIT,    "M3->M0")            \
>> +    EM(MHI_PM_STATE_FW_DL_ERR,    "Firmware Download Error") \
>> +    EM(MHI_PM_STATE_SYS_ERR_DETECT,        "SYS ERROR Detect")    \
>> +    EM(MHI_PM_STATE_SYS_ERR_PROCESS,    "SYS ERROR Process") \
>> +    EM(MHI_PM_STATE_SHUTDOWN_PROCESS,    "SHUTDOWN Process") \
>> +    EMe(MHI_PM_STATE_LD_ERR_FATAL_DETECT,    "Linkdown or Error 
>> Fatal Detect")
>> +
>> +#define MHI_CH_STATE                        \
>> +    EM(MHI_CH_STATE_TYPE_RESET, "RESET")            \
>> +    EM(MHI_CH_STATE_TYPE_STOP, "STOP")            \
>> +    EMe(MHI_CH_STATE_TYPE_START, "START")
>> +
>> +#define MHI_DEV_ST_TRANSITION                        \
>> +    EM(DEV_ST_TRANSITION_PBL,    "PBL")                \
>> +    EM(DEV_ST_TRANSITION_READY,    "READY")            \
>> +    EM(DEV_ST_TRANSITION_SBL,    "SBL")                \
>> +    EM(DEV_ST_TRANSITION_MISSION_MODE,    "MISSION MODE")        \
>> +    EM(DEV_ST_TRANSITION_FP,        "FLASH PROGRAMMER")    \
>> +    EM(DEV_ST_TRANSITION_SYS_ERR,        "SYS ERROR")        \
>> +    EMe(DEV_ST_TRANSITION_DISABLE,        "DISABLE")
>> +
>> +/* Enums require being exported to userspace, for user tool parsing */
>> +#undef    EM
>> +#undef    EMe
>> +#define    EM(a, b)    TRACE_DEFINE_ENUM(a);
>> +#define    EMe(a, b)    TRACE_DEFINE_ENUM(a);
>> +
>> +MHI_STATE
>> +MHI_EE
>> +MHI_PM_STATE
>> +MHI_CH_STATE
>> +MHI_DEV_ST_TRANSITION
>> +
>> +/*
>> + * Now redefine the EM() and EMe() macros to map the enums to the 
>> strings
>> + * that will be printed in the output.
>> + */
>> +#undef EM
>> +#undef EMe
>> +#define EM(a, b)    {a, b},
>> +#define EMe(a, b)    {a, b}
>> +
>> +TRACE_EVENT(mhi_gen_tre,
>> +
>> +    TP_PROTO(const char *name, int ch_num, u64 wp, __le64 tre_ptr,
>> +         __le32 dword0, __le32 dword1),
>> +
>> +    TP_ARGS(name, ch_num, wp, tre_ptr, dword0, dword1),
>> +
>> +    TP_STRUCT__entry(
>> +        __string(name, name)
>> +        __field(int, ch_num)
>> +        __field(u64, wp)
>> +        __field(__le64, tre_ptr)
>> +        __field(__le32, dword0)
>> +        __field(__le32, dword1)
>> +    ),
>> +
>> +    TP_fast_assign(
>> +        __assign_str(name, name);
>> +        __entry->ch_num = ch_num;
>> +        __entry->wp = wp;
>> +        __entry->tre_ptr = tre_ptr;
>> +        __entry->dword0 = dword0;
>> +        __entry->dword1 = dword1;
>> +    ),
>> +
>> +    TP_printk("%s: Chan: %d WP: 0x%llx TRE: 0x%llx 0x%08x 0x%08x\n",
>> +          __get_str(name), __entry->ch_num, __entry->wp, 
>> __entry->tre_ptr,
>> +          __entry->dword0, __entry->dword1)
>> +);
>> +
>> +TRACE_EVENT(mhi_intvec_threaded_handler,
>> +
>> +    TP_PROTO(const char *name, int local_ee, int state, int dev_ee, 
>> int dev_state),
>> +
>> +    TP_ARGS(name, local_ee, state, dev_ee, dev_state),
>> +
>> +    TP_STRUCT__entry(
>> +        __string(name, name)
>> +        __field(int, local_ee)
>> +        __field(int, state)
>> +        __field(int, dev_ee)
>> +        __field(int, dev_state)
>> +    ),
>> +
>> +    TP_fast_assign(
>> +        __assign_str(name, name);
>> +        __entry->local_ee = local_ee;
>> +        __entry->state = state;
>> +        __entry->dev_ee = dev_ee;
>> +        __entry->dev_state = dev_state;
>> +    ),
>> +
>> +    TP_printk("%s: local ee: %s state: %s device ee: %s state: %s\n",
>> +          __get_str(name),
>> +          __print_symbolic(__entry->local_ee, MHI_EE),
>> +          __print_symbolic(__entry->state, MHI_STATE),
>> +          __print_symbolic(__entry->dev_ee, MHI_EE),
>> +          __print_symbolic(__entry->dev_state, MHI_STATE))
>> +);
>> +
>> +TRACE_EVENT(mhi_tryset_pm_state,
>> +
>> +    TP_PROTO(const char *name, int pm_state),
>> +
>> +    TP_ARGS(name, pm_state),
>> +
>> +    TP_STRUCT__entry(
>> +        __string(name, name)
>> +        __field(int, pm_state)
>> +    ),
>> +
>> +    TP_fast_assign(
>> +        __assign_str(name, name);
>> +        if (pm_state)
>> +            pm_state = __fls(pm_state);
>> +        __entry->pm_state = pm_state;
>> +    ),
>> +
>> +    TP_printk("%s: PM state: %s\n", __get_str(name),
>> +          __print_symbolic(__entry->pm_state, MHI_PM_STATE))
>> +);
>> +
>> +TRACE_EVENT(mhi_process_data_event_ring,
>> +
>> +    TP_PROTO(const char *name, __le64 ptr, __le32 dword0, __le32 
>> dword1),
>> +
>> +    TP_ARGS(name, ptr, dword0, dword1),
>> +
>> +    TP_STRUCT__entry(
>> +        __string(name, name)
>> +        __field(__le64, ptr)
>> +        __field(__le32, dword0)
>> +        __field(__le32, dword1)
>> +    ),
>> +
>> +    TP_fast_assign(
>> +        __assign_str(name, name);
>> +        __entry->ptr = ptr;
>> +        __entry->dword0 = dword0;
>> +        __entry->dword1 = dword1;
>> +    ),
>> +
>> +    TP_printk("%s: Processing Event:0x%llx 0x%08x 0x%08x\n",
>> +          __get_str(name), __entry->ptr, __entry->dword0, 
>> __entry->dword1)
>> +);
>> +
>> +TRACE_EVENT(mhi_process_ctrl_ev_ring,
>> +
>> +    TP_PROTO(const char *name, u64 rp, __le64 ptr, __le32 dword0, 
>> __le32 dword1, int state),
>> +
>> +    TP_ARGS(name, rp, ptr, dword0, dword1, state),
>> +
>> +    TP_STRUCT__entry(
>> +        __string(name, name)
>> +        __field(u64, rp)
>> +        __field(__le64, ptr)
>> +        __field(__le32, dword0)
>> +        __field(__le32, dword1)
>> +        __field(int, state)
>> +    ),
>> +
>> +    TP_fast_assign(
>> +        __assign_str(name, name);
>> +        __entry->rp = rp;
>> +        __entry->ptr = ptr;
>> +        __entry->dword0 = dword0;
>> +        __entry->dword1 = dword1;
>> +        __entry->state = state;
>> +    ),
>> +
>> +    TP_printk("%s: RP:0x%llx Processing Event:0x%llx 0x%08x 0x%08x 
>> state:%s\n",
>> +          __get_str(name), __entry->rp, __entry->ptr, __entry->dword0,
>> +          __entry->dword1, __print_symbolic(__entry->state, MHI_STATE))
>> +);
>> +
>> +TRACE_EVENT(mhi_update_channel_state_start,
>> +
>> +    TP_PROTO(const char *name, int ch_num, int state),
>> +
>> +    TP_ARGS(name, ch_num, state),
>> +
>> +    TP_STRUCT__entry(
>> +        __string(name, name)
>> +        __field(int, ch_num)
>> +        __field(int, state)
>> +    ),
>> +
>> +    TP_fast_assign(
>> +        __assign_str(name, name);
>> +        __entry->ch_num = ch_num;
>> +        __entry->state = state;
>> +    ),
>> +
>> +    TP_printk("%s: ch%d: Updating state to: %s\n",
>> +          __get_str(name), __entry->ch_num,
>> +          __print_symbolic(__entry->state, MHI_CH_STATE))
>> +);
>> +
>> +TRACE_EVENT(mhi_update_channel_state_end,
>> +
>> +    TP_PROTO(const char *name, int ch_num, int state),
>> +
>> +    TP_ARGS(name, ch_num, state),
>> +
>> +    TP_STRUCT__entry(
>> +        __string(name, name)
>> +        __field(int, ch_num)
>> +        __field(int, state)
>> +    ),
>> +
>> +    TP_fast_assign(
>> +        __assign_str(name, name);
>> +        __entry->ch_num = ch_num;
>> +        __entry->state = state;
>> +    ),
>> +
>> +    TP_printk("%s: ch%d: Updated state to: %s\n",
>> +          __get_str(name), __entry->ch_num,
>> +          __print_symbolic(__entry->state, MHI_CH_STATE))
>> +);
>> +
>> +TRACE_EVENT(mhi_pm_st_transition,
>> +
>> +    TP_PROTO(const char *name, int state),
>> +
>> +    TP_ARGS(name, state),
>> +
>> +    TP_STRUCT__entry(
>> +        __string(name, name)
>> +        __field(int, state)
>> +    ),
>> +
>> +    TP_fast_assign(
>> +        __assign_str(name, name);
>> +        __entry->state = state;
>> +    ),
>> +
>> +    TP_printk("%s: Handling state transition: %s\n", __get_str(name),
>> +          __print_symbolic(__entry->state, MHI_DEV_ST_TRANSITION))
>> +);
>> +
>> +#endif
>> +#include <trace/define_trace.h>
>>
>> ---
>> base-commit: 3006adf3be79cde4d14b1800b963b82b6e5572e0
>> change-id: 20231005-ftrace_support-6869d4156139
>>
>> Best regards,
>
Jeffrey Hugo Oct. 27, 2023, 3:29 p.m. UTC | #8
On 10/23/2023 1:11 AM, Krishna Chaitanya Chundru wrote:
> 
> On 10/20/2023 8:33 PM, Jeffrey Hugo wrote:
>> On 10/13/2023 3:52 AM, Krishna chaitanya chundru wrote:
>>> This change adds ftrace support for following functions which
>>> helps in debugging the issues when there is Channel state & MHI
>>> state change and also when we receive data and control events:
>>> 1. mhi_intvec_threaded_handler
>>> 2. mhi_process_data_event_ring
>>> 3. mhi_process_ctrl_ev_ring
>>> 4. mhi_gen_tre
>>> 5. mhi_update_channel_state
>>> 6. mhi_tryset_pm_state
>>> 7. mhi_pm_st_worker
>>>
>>> Signed-off-by: Krishna chaitanya chundru <quic_krichai@quicinc.com>
>>> ---
>>> Changes in v2:
>>> - Passing the raw state into the trace event and using 
>>> __print_symbolic() as suggested by bjorn.
>>> - Change mhi_pm_st_worker to mhi_pm_st_transition as suggested by bjorn.
>>> - Fixed the kernel test rebot issues.
>>> - Link to v1: 
>>> https://lore.kernel.org/r/20231005-ftrace_support-v1-1-23a2f394fa49@quicinc.com 
>>>
>>> ---
>>>   MAINTAINERS                     |   1 +
>>>   drivers/bus/mhi/host/init.c     |   3 +
>>>   drivers/bus/mhi/host/internal.h |   1 +
>>>   drivers/bus/mhi/host/main.c     |  32 +++--
>>>   drivers/bus/mhi/host/pm.c       |   6 +-
>>>   include/trace/events/mhi_host.h | 287 
>>> ++++++++++++++++++++++++++++++++++++++++
>>>   6 files changed, 317 insertions(+), 13 deletions(-)
>>>
>>> diff --git a/MAINTAINERS b/MAINTAINERS
>>> index 35977b269d5e..4339c668a6ab 100644
>>> --- a/MAINTAINERS
>>> +++ b/MAINTAINERS
>>> @@ -13862,6 +13862,7 @@ F:    Documentation/mhi/
>>>   F:    drivers/bus/mhi/
>>>   F:    drivers/pci/endpoint/functions/pci-epf-mhi.c
>>>   F:    include/linux/mhi.h
>>> +F:    include/trace/events/mhi_host.h
>>>     MICROBLAZE ARCHITECTURE
>>>   M:    Michal Simek <monstr@monstr.eu>
>>> diff --git a/drivers/bus/mhi/host/init.c b/drivers/bus/mhi/host/init.c
>>> index f78aefd2d7a3..3afa90a204fd 100644
>>> --- a/drivers/bus/mhi/host/init.c
>>> +++ b/drivers/bus/mhi/host/init.c
>>> @@ -20,6 +20,9 @@
>>>   #include <linux/wait.h>
>>>   #include "internal.h"
>>>   +#define CREATE_TRACE_POINTS
>>> +#include <trace/events/mhi_host.h>
>>
>> This feels redundant to me.  A few lines ago we included internal.h, 
>> and internal.h includes trace/events/mhi_host.h
> 
> As Steve mentioned, this is mandatory step for creating trace points & 
> trace events.

I understand this creates the trace points, and that needs to be done in 
C code.  It dtill seems redundant because we are including the header 
twice (and I am aware trace has the special multi-header read 
functionality for this).

The duplicate include still feels weird, but I have not come up with a 
better way to structure this.

> 
>>
>>> +
>>>   static DEFINE_IDA(mhi_controller_ida);
>>>     const char * const mhi_ee_str[MHI_EE_MAX] = {
>>> diff --git a/drivers/bus/mhi/host/internal.h 
>>> b/drivers/bus/mhi/host/internal.h
>>> index 2e139e76de4c..a80a317a59a9 100644
>>> --- a/drivers/bus/mhi/host/internal.h
>>> +++ b/drivers/bus/mhi/host/internal.h
>>> @@ -7,6 +7,7 @@
>>>   #ifndef _MHI_INT_H
>>>   #define _MHI_INT_H
>>>   +#include <trace/events/mhi_host.h>
>>>   #include "../common.h"
>>>     extern struct bus_type mhi_bus_type;
>>> diff --git a/drivers/bus/mhi/host/main.c b/drivers/bus/mhi/host/main.c
>>> index dcf627b36e82..fcdb728ba49f 100644
>>> --- a/drivers/bus/mhi/host/main.c
>>> +++ b/drivers/bus/mhi/host/main.c
>>> @@ -246,6 +246,11 @@ static void *mhi_to_virtual(struct mhi_ring 
>>> *ring, dma_addr_t addr)
>>>       return (addr - ring->iommu_base) + ring->base;
>>>   }
>>>   +dma_addr_t mhi_to_physical(struct mhi_ring *ring, void *addr)
>>> +{
>>> +    return (addr - ring->base) + ring->iommu_base;
>>> +}
>>
>> This seems to be poorly named since we are using the iommu_base which 
>> suggests we are converting to an IOVA.
>>
>> Why do we need this though?  This seems like it might be a security 
>> issue, or at the very least, not preferred, and I'm struggling to 
>> figure out what value this provides to you are I when looking at the log.
>>
> I will rename the function to reflect it is converting to IOVA.
> 
> We MHI TRE we write the IOVA address, to correlate between TRE events in 
> the MHI ring and event we are processing  we want to log the IOVA address.
> 
> As we are logging only IOVA address which is provided in the devicetree 
> and not the original physical address we are not expecting any security 
> issues here.
> 
> Correct me if I was wrong.

The IOVA is not provided by DT, it is a runtime allocated value provided 
by the IOMMU, if present.  If not present, then it is a physical address.

Remember, x86 does not use devicetree.

While the IOVA (with an iommu) is not technically a physical address, 
but is treated as such by the device.  I can imagine an attacker doing 
bad things if they get a hold of the value.

Still, you haven't indicated why this is useful.

> 
>>> +
>>>   static void mhi_add_ring_element(struct mhi_controller *mhi_cntrl,
>>>                    struct mhi_ring *ring)
>>>   {
>>> @@ -491,11 +496,9 @@ irqreturn_t mhi_intvec_threaded_handler(int 
>>> irq_number, void *priv)
>>>         state = mhi_get_mhi_state(mhi_cntrl);
>>>       ee = mhi_get_exec_env(mhi_cntrl);
>>> -    dev_dbg(dev, "local ee: %s state: %s device ee: %s state: %s\n",
>>> -        TO_MHI_EXEC_STR(mhi_cntrl->ee),
>>> -        mhi_state_str(mhi_cntrl->dev_state),
>>> -        TO_MHI_EXEC_STR(ee), mhi_state_str(state));
>>>   + trace_mhi_intvec_threaded_handler(mhi_cntrl->mhi_dev->name, 
>>> mhi_cntrl->ee,
>>> +                      mhi_cntrl->dev_state, ee, state);
>>
>> Why are we removing the debug message when adding this trace?  The 
>> commit text doesn't say.  (Looks like you do this several times, 
>> assume this comment applies to all isntances)
> 
> I will add this in the commit text in my next patch.
> 
> Just a query is recommended to keep both debug message and trace events. 
> If yes we will not remove the debug messages.

I think it would be preferred to have one mechanism or the other, not 
both.  It seems like you are doing an incomplete conversion.

> 
>>
>>>       if (state == MHI_STATE_SYS_ERR) {
>>>           dev_dbg(dev, "System error detected\n");
>>>           pm_state = mhi_tryset_pm_state(mhi_cntrl,
>>> @@ -832,6 +835,12 @@ int mhi_process_ctrl_ev_ring(struct 
>>> mhi_controller *mhi_cntrl,
>>>       while (dev_rp != local_rp) {
>>>           enum mhi_pkt_type type = MHI_TRE_GET_EV_TYPE(local_rp);
>>>   + trace_mhi_process_ctrl_ev_ring(mhi_cntrl->mhi_dev->name,
>>> +                           mhi_to_physical(ev_ring, local_rp),
>>> +                           local_rp->ptr, local_rp->dword[0],
>>> +                           local_rp->dword[1],
>>> +                           MHI_TRE_GET_EV_STATE(local_rp));
>>
>> Why not just pass in the local_rp as a single parameter and have the 
>> trace implementation decode it?  (Looks like you do this several 
>> times, assume this comment applies to all isntances)
> 
> MHI_TRE_GET_EV_STATE definition is present in drivers/bus/mhi/common.h 
> which is common for both EP & MHI driver.
> 
> If we keep this macro definition again in mhi_host.h it will be 
> redundant one.

What is wrong with including the right header over in the trace to get 
the definition?  I didn't ask for it to be redefined.

If the struct definition for local_rp changes, it will probably break 
this, which will require changes to the definition and use of 
trace_mhi_process_ctrl_ev_ring().  If trace_mhi_process_ctrl_ev_ring() 
just takes the struct and decodes it, the decode logic just needs to be 
updated (in one place) when the struct definition changes.

> 
> And we are only using this way only for this trace log. So we are using 
> the macro to get the state information.

No, you do the same thing for trace_mhi_process_data_event_ring() and 
trace_mhi_gen_tre().
Krishna Chaitanya Chundru Oct. 30, 2023, 7:18 a.m. UTC | #9
On 10/27/2023 8:59 PM, Jeffrey Hugo wrote:
> On 10/23/2023 1:11 AM, Krishna Chaitanya Chundru wrote:
>>
>> On 10/20/2023 8:33 PM, Jeffrey Hugo wrote:
>>> On 10/13/2023 3:52 AM, Krishna chaitanya chundru wrote:
>>>> This change adds ftrace support for following functions which
>>>> helps in debugging the issues when there is Channel state & MHI
>>>> state change and also when we receive data and control events:
>>>> 1. mhi_intvec_threaded_handler
>>>> 2. mhi_process_data_event_ring
>>>> 3. mhi_process_ctrl_ev_ring
>>>> 4. mhi_gen_tre
>>>> 5. mhi_update_channel_state
>>>> 6. mhi_tryset_pm_state
>>>> 7. mhi_pm_st_worker
>>>>
>>>> Signed-off-by: Krishna chaitanya chundru <quic_krichai@quicinc.com>
>>>> ---
>>>> Changes in v2:
>>>> - Passing the raw state into the trace event and using 
>>>> __print_symbolic() as suggested by bjorn.
>>>> - Change mhi_pm_st_worker to mhi_pm_st_transition as suggested by 
>>>> bjorn.
>>>> - Fixed the kernel test rebot issues.
>>>> - Link to v1: 
>>>> https://lore.kernel.org/r/20231005-ftrace_support-v1-1-23a2f394fa49@quicinc.com 
>>>>
>>>> ---
>>>>   MAINTAINERS                     |   1 +
>>>>   drivers/bus/mhi/host/init.c     |   3 +
>>>>   drivers/bus/mhi/host/internal.h |   1 +
>>>>   drivers/bus/mhi/host/main.c     |  32 +++--
>>>>   drivers/bus/mhi/host/pm.c       |   6 +-
>>>>   include/trace/events/mhi_host.h | 287 
>>>> ++++++++++++++++++++++++++++++++++++++++
>>>>   6 files changed, 317 insertions(+), 13 deletions(-)
>>>>
>>>> diff --git a/MAINTAINERS b/MAINTAINERS
>>>> index 35977b269d5e..4339c668a6ab 100644
>>>> --- a/MAINTAINERS
>>>> +++ b/MAINTAINERS
>>>> @@ -13862,6 +13862,7 @@ F:    Documentation/mhi/
>>>>   F:    drivers/bus/mhi/
>>>>   F:    drivers/pci/endpoint/functions/pci-epf-mhi.c
>>>>   F:    include/linux/mhi.h
>>>> +F:    include/trace/events/mhi_host.h
>>>>     MICROBLAZE ARCHITECTURE
>>>>   M:    Michal Simek <monstr@monstr.eu>
>>>> diff --git a/drivers/bus/mhi/host/init.c b/drivers/bus/mhi/host/init.c
>>>> index f78aefd2d7a3..3afa90a204fd 100644
>>>> --- a/drivers/bus/mhi/host/init.c
>>>> +++ b/drivers/bus/mhi/host/init.c
>>>> @@ -20,6 +20,9 @@
>>>>   #include <linux/wait.h>
>>>>   #include "internal.h"
>>>>   +#define CREATE_TRACE_POINTS
>>>> +#include <trace/events/mhi_host.h>
>>>
>>> This feels redundant to me.  A few lines ago we included internal.h, 
>>> and internal.h includes trace/events/mhi_host.h
>>
>> As Steve mentioned, this is mandatory step for creating trace points 
>> & trace events.
>
> I understand this creates the trace points, and that needs to be done 
> in C code.  It dtill seems redundant because we are including the 
> header twice (and I am aware trace has the special multi-header read 
> functionality for this).
>
> The duplicate include still feels weird, but I have not come up with a 
> better way to structure this.
We will use this way for now then, we will check in parallel if there 
is  a way to avoid this and change it in the future.
>
>>
>>>
>>>> +
>>>>   static DEFINE_IDA(mhi_controller_ida);
>>>>     const char * const mhi_ee_str[MHI_EE_MAX] = {
>>>> diff --git a/drivers/bus/mhi/host/internal.h 
>>>> b/drivers/bus/mhi/host/internal.h
>>>> index 2e139e76de4c..a80a317a59a9 100644
>>>> --- a/drivers/bus/mhi/host/internal.h
>>>> +++ b/drivers/bus/mhi/host/internal.h
>>>> @@ -7,6 +7,7 @@
>>>>   #ifndef _MHI_INT_H
>>>>   #define _MHI_INT_H
>>>>   +#include <trace/events/mhi_host.h>
>>>>   #include "../common.h"
>>>>     extern struct bus_type mhi_bus_type;
>>>> diff --git a/drivers/bus/mhi/host/main.c b/drivers/bus/mhi/host/main.c
>>>> index dcf627b36e82..fcdb728ba49f 100644
>>>> --- a/drivers/bus/mhi/host/main.c
>>>> +++ b/drivers/bus/mhi/host/main.c
>>>> @@ -246,6 +246,11 @@ static void *mhi_to_virtual(struct mhi_ring 
>>>> *ring, dma_addr_t addr)
>>>>       return (addr - ring->iommu_base) + ring->base;
>>>>   }
>>>>   +dma_addr_t mhi_to_physical(struct mhi_ring *ring, void *addr)
>>>> +{
>>>> +    return (addr - ring->base) + ring->iommu_base;
>>>> +}
>>>
>>> This seems to be poorly named since we are using the iommu_base 
>>> which suggests we are converting to an IOVA.
>>>
>>> Why do we need this though?  This seems like it might be a security 
>>> issue, or at the very least, not preferred, and I'm struggling to 
>>> figure out what value this provides to you are I when looking at the 
>>> log.
>>>
>> I will rename the function to reflect it is converting to IOVA.
>>
>> We MHI TRE we write the IOVA address, to correlate between TRE events 
>> in the MHI ring and event we are processing  we want to log the IOVA 
>> address.
>>
>> As we are logging only IOVA address which is provided in the 
>> devicetree and not the original physical address we are not expecting 
>> any security issues here.
>>
>> Correct me if I was wrong.
>
> The IOVA is not provided by DT, it is a runtime allocated value 
> provided by the IOMMU, if present.  If not present, then it is a 
> physical address.
>
> Remember, x86 does not use devicetree.
>
> While the IOVA (with an iommu) is not technically a physical address, 
> but is treated as such by the device.  I can imagine an attacker doing 
> bad things if they get a hold of the value.
Sure we will remove it.
>
> Still, you haven't indicated why this is useful.

The TRE ring elements has address in the IOVA format when we want to 
correlate the address with the TRE elements in the dumps it will easier 
with this way.

Anyway we will not expose this as you suggested as it might expose 
physical address in some platforms.

>
>>
>>>> +
>>>>   static void mhi_add_ring_element(struct mhi_controller *mhi_cntrl,
>>>>                    struct mhi_ring *ring)
>>>>   {
>>>> @@ -491,11 +496,9 @@ irqreturn_t mhi_intvec_threaded_handler(int 
>>>> irq_number, void *priv)
>>>>         state = mhi_get_mhi_state(mhi_cntrl);
>>>>       ee = mhi_get_exec_env(mhi_cntrl);
>>>> -    dev_dbg(dev, "local ee: %s state: %s device ee: %s state: %s\n",
>>>> -        TO_MHI_EXEC_STR(mhi_cntrl->ee),
>>>> -        mhi_state_str(mhi_cntrl->dev_state),
>>>> -        TO_MHI_EXEC_STR(ee), mhi_state_str(state));
>>>>   + trace_mhi_intvec_threaded_handler(mhi_cntrl->mhi_dev->name, 
>>>> mhi_cntrl->ee,
>>>> +                      mhi_cntrl->dev_state, ee, state);
>>>
>>> Why are we removing the debug message when adding this trace? The 
>>> commit text doesn't say.  (Looks like you do this several times, 
>>> assume this comment applies to all isntances)
>>
>> I will add this in the commit text in my next patch.
>>
>> Just a query is recommended to keep both debug message and trace 
>> events. If yes we will not remove the debug messages.
>
> I think it would be preferred to have one mechanism or the other, not 
> both.  It seems like you are doing an incomplete conversion.
>
For now we will remove the dbg message where we added the traces and 
will mention that in the commit.
>>
>>>
>>>>       if (state == MHI_STATE_SYS_ERR) {
>>>>           dev_dbg(dev, "System error detected\n");
>>>>           pm_state = mhi_tryset_pm_state(mhi_cntrl,
>>>> @@ -832,6 +835,12 @@ int mhi_process_ctrl_ev_ring(struct 
>>>> mhi_controller *mhi_cntrl,
>>>>       while (dev_rp != local_rp) {
>>>>           enum mhi_pkt_type type = MHI_TRE_GET_EV_TYPE(local_rp);
>>>>   + trace_mhi_process_ctrl_ev_ring(mhi_cntrl->mhi_dev->name,
>>>> +                           mhi_to_physical(ev_ring, local_rp),
>>>> +                           local_rp->ptr, local_rp->dword[0],
>>>> +                           local_rp->dword[1],
>>>> +                           MHI_TRE_GET_EV_STATE(local_rp));
>>>
>>> Why not just pass in the local_rp as a single parameter and have the 
>>> trace implementation decode it?  (Looks like you do this several 
>>> times, assume this comment applies to all isntances)
>>
>> MHI_TRE_GET_EV_STATE definition is present in 
>> drivers/bus/mhi/common.h which is common for both EP & MHI driver.
>>
>> If we keep this macro definition again in mhi_host.h it will be 
>> redundant one.
>
> What is wrong with including the right header over in the trace to get 
> the definition?  I didn't ask for it to be redefined.
>
> If the struct definition for local_rp changes, it will probably break 
> this, which will require changes to the definition and use of 
> trace_mhi_process_ctrl_ev_ring().  If trace_mhi_process_ctrl_ev_ring() 
> just takes the struct and decodes it, the decode logic just needs to 
> be updated (in one place) when the struct definition changes.
>
>>
>> And we are only using this way only for this trace log. So we are 
>> using the macro to get the state information.
>
> No, you do the same thing for trace_mhi_process_data_event_ring() and 
> trace_mhi_gen_tre().

Mani, can we move common.h to include  folder from the drivers folder so 
that we can include that file in the mhi_host.h for trace events?

- Krishna Chaitanya.
diff mbox series

Patch

diff --git a/MAINTAINERS b/MAINTAINERS
index 35977b269d5e..4339c668a6ab 100644
--- a/MAINTAINERS
+++ b/MAINTAINERS
@@ -13862,6 +13862,7 @@  F:	Documentation/mhi/
 F:	drivers/bus/mhi/
 F:	drivers/pci/endpoint/functions/pci-epf-mhi.c
 F:	include/linux/mhi.h
+F:	include/trace/events/mhi_host.h
 
 MICROBLAZE ARCHITECTURE
 M:	Michal Simek <monstr@monstr.eu>
diff --git a/drivers/bus/mhi/host/init.c b/drivers/bus/mhi/host/init.c
index f78aefd2d7a3..3afa90a204fd 100644
--- a/drivers/bus/mhi/host/init.c
+++ b/drivers/bus/mhi/host/init.c
@@ -20,6 +20,9 @@ 
 #include <linux/wait.h>
 #include "internal.h"
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/mhi_host.h>
+
 static DEFINE_IDA(mhi_controller_ida);
 
 const char * const mhi_ee_str[MHI_EE_MAX] = {
diff --git a/drivers/bus/mhi/host/internal.h b/drivers/bus/mhi/host/internal.h
index 2e139e76de4c..a80a317a59a9 100644
--- a/drivers/bus/mhi/host/internal.h
+++ b/drivers/bus/mhi/host/internal.h
@@ -7,6 +7,7 @@ 
 #ifndef _MHI_INT_H
 #define _MHI_INT_H
 
+#include <trace/events/mhi_host.h>
 #include "../common.h"
 
 extern struct bus_type mhi_bus_type;
diff --git a/drivers/bus/mhi/host/main.c b/drivers/bus/mhi/host/main.c
index dcf627b36e82..fcdb728ba49f 100644
--- a/drivers/bus/mhi/host/main.c
+++ b/drivers/bus/mhi/host/main.c
@@ -246,6 +246,11 @@  static void *mhi_to_virtual(struct mhi_ring *ring, dma_addr_t addr)
 	return (addr - ring->iommu_base) + ring->base;
 }
 
+dma_addr_t mhi_to_physical(struct mhi_ring *ring, void *addr)
+{
+	return (addr - ring->base) + ring->iommu_base;
+}
+
 static void mhi_add_ring_element(struct mhi_controller *mhi_cntrl,
 				 struct mhi_ring *ring)
 {
@@ -491,11 +496,9 @@  irqreturn_t mhi_intvec_threaded_handler(int irq_number, void *priv)
 
 	state = mhi_get_mhi_state(mhi_cntrl);
 	ee = mhi_get_exec_env(mhi_cntrl);
-	dev_dbg(dev, "local ee: %s state: %s device ee: %s state: %s\n",
-		TO_MHI_EXEC_STR(mhi_cntrl->ee),
-		mhi_state_str(mhi_cntrl->dev_state),
-		TO_MHI_EXEC_STR(ee), mhi_state_str(state));
 
+	trace_mhi_intvec_threaded_handler(mhi_cntrl->mhi_dev->name, mhi_cntrl->ee,
+					  mhi_cntrl->dev_state, ee, state);
 	if (state == MHI_STATE_SYS_ERR) {
 		dev_dbg(dev, "System error detected\n");
 		pm_state = mhi_tryset_pm_state(mhi_cntrl,
@@ -832,6 +835,12 @@  int mhi_process_ctrl_ev_ring(struct mhi_controller *mhi_cntrl,
 	while (dev_rp != local_rp) {
 		enum mhi_pkt_type type = MHI_TRE_GET_EV_TYPE(local_rp);
 
+		trace_mhi_process_ctrl_ev_ring(mhi_cntrl->mhi_dev->name,
+					       mhi_to_physical(ev_ring, local_rp),
+					       local_rp->ptr, local_rp->dword[0],
+					       local_rp->dword[1],
+					       MHI_TRE_GET_EV_STATE(local_rp));
+
 		switch (type) {
 		case MHI_PKT_TYPE_BW_REQ_EVENT:
 		{
@@ -997,6 +1006,9 @@  int mhi_process_data_event_ring(struct mhi_controller *mhi_cntrl,
 	while (dev_rp != local_rp && event_quota > 0) {
 		enum mhi_pkt_type type = MHI_TRE_GET_EV_TYPE(local_rp);
 
+		trace_mhi_process_data_event_ring(mhi_cntrl->mhi_dev->name, local_rp->ptr,
+						  local_rp->dword[0], local_rp->dword[1]);
+
 		chan = MHI_TRE_GET_EV_CHID(local_rp);
 
 		WARN_ON(chan >= mhi_cntrl->max_chan);
@@ -1235,6 +1247,9 @@  int mhi_gen_tre(struct mhi_controller *mhi_cntrl, struct mhi_chan *mhi_chan,
 	mhi_tre->dword[0] = MHI_TRE_DATA_DWORD0(info->len);
 	mhi_tre->dword[1] = MHI_TRE_DATA_DWORD1(bei, eot, eob, chain);
 
+	trace_mhi_gen_tre(mhi_cntrl->mhi_dev->name, mhi_chan->chan,
+			  mhi_to_physical(tre_ring, mhi_tre),
+			  mhi_tre->ptr, mhi_tre->dword[0], mhi_tre->dword[1]);
 	/* increment WP */
 	mhi_add_ring_element(mhi_cntrl, tre_ring);
 	mhi_add_ring_element(mhi_cntrl, buf_ring);
@@ -1327,9 +1342,8 @@  static int mhi_update_channel_state(struct mhi_controller *mhi_cntrl,
 	enum mhi_cmd_type cmd = MHI_CMD_NOP;
 	int ret;
 
-	dev_dbg(dev, "%d: Updating channel state to: %s\n", mhi_chan->chan,
-		TO_CH_STATE_TYPE_STR(to_state));
-
+	trace_mhi_update_channel_state_start(mhi_cntrl->mhi_dev->name, mhi_chan->chan,
+					     to_state);
 	switch (to_state) {
 	case MHI_CH_STATE_TYPE_RESET:
 		write_lock_irq(&mhi_chan->lock);
@@ -1396,9 +1410,7 @@  static int mhi_update_channel_state(struct mhi_controller *mhi_cntrl,
 		write_unlock_irq(&mhi_chan->lock);
 	}
 
-	dev_dbg(dev, "%d: Channel state change to %s successful\n",
-		mhi_chan->chan, TO_CH_STATE_TYPE_STR(to_state));
-
+	trace_mhi_update_channel_state_end(mhi_cntrl->mhi_dev->name, mhi_chan->chan, to_state);
 exit_channel_update:
 	mhi_cntrl->runtime_put(mhi_cntrl);
 	mhi_device_put(mhi_cntrl->mhi_dev);
diff --git a/drivers/bus/mhi/host/pm.c b/drivers/bus/mhi/host/pm.c
index 8a4362d75fc4..e32afdc92fde 100644
--- a/drivers/bus/mhi/host/pm.c
+++ b/drivers/bus/mhi/host/pm.c
@@ -123,6 +123,7 @@  enum mhi_pm_state __must_check mhi_tryset_pm_state(struct mhi_controller *mhi_cn
 	if (unlikely(!(dev_state_transitions[index].to_states & state)))
 		return cur_state;
 
+	trace_mhi_tryset_pm_state(mhi_cntrl->mhi_dev->name, state);
 	mhi_cntrl->pm_state = state;
 	return mhi_cntrl->pm_state;
 }
@@ -753,7 +754,6 @@  void mhi_pm_st_worker(struct work_struct *work)
 	struct mhi_controller *mhi_cntrl = container_of(work,
 							struct mhi_controller,
 							st_worker);
-	struct device *dev = &mhi_cntrl->mhi_dev->dev;
 
 	spin_lock_irq(&mhi_cntrl->transition_lock);
 	list_splice_tail_init(&mhi_cntrl->transition_list, &head);
@@ -761,8 +761,8 @@  void mhi_pm_st_worker(struct work_struct *work)
 
 	list_for_each_entry_safe(itr, tmp, &head, node) {
 		list_del(&itr->node);
-		dev_dbg(dev, "Handling state transition: %s\n",
-			TO_DEV_STATE_TRANS_STR(itr->state));
+
+		trace_mhi_pm_st_transition(mhi_cntrl->mhi_dev->name, itr->state);
 
 		switch (itr->state) {
 		case DEV_ST_TRANSITION_PBL:
diff --git a/include/trace/events/mhi_host.h b/include/trace/events/mhi_host.h
new file mode 100644
index 000000000000..a496d99f8fad
--- /dev/null
+++ b/include/trace/events/mhi_host.h
@@ -0,0 +1,287 @@ 
+/* SPDX-License-Identifier: GPL-2.0-only */
+/*
+ * Copyright (c) 2023 Qualcomm Innovation Center, Inc. All rights reserved.
+ */
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM mhi_host
+
+#if !defined(_TRACE_EVENT_MHI_HOST_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_EVENT_MHI_HOST_H
+
+#include <linux/tracepoint.h>
+#define MHI_STATE						\
+	EM(MHI_STATE_RESET,	"RESET")			\
+	EM(MHI_STATE_READY,	"READY")			\
+	EM(MHI_STATE_M0,	"M0")				\
+	EM(MHI_STATE_M1,	"M1")				\
+	EM(MHI_STATE_M2,	"M2")				\
+	EM(MHI_STATE_M3,	"M3")				\
+	EM(MHI_STATE_M3_FAST,	"M3 FAST")			\
+	EM(MHI_STATE_BHI,	"BHI")				\
+	EMe(MHI_STATE_SYS_ERR,	"SYS ERROR")
+
+#define MHI_EE							\
+	EM(MHI_EE_PBL,		"PRIMARY BOOTLOADER")		\
+	EM(MHI_EE_SBL,		"SECONDARY BOOTLOADER")		\
+	EM(MHI_EE_AMSS,		"MISSION MODE")			\
+	EM(MHI_EE_RDDM,		"RAMDUMP DOWNLOAD MODE")	\
+	EM(MHI_EE_WFW,		"WLAN FIRMWARE")		\
+	EM(MHI_EE_PTHRU,	"PASS THROUGH")			\
+	EM(MHI_EE_EDL,		"EMERGENCY DOWNLOAD")		\
+	EM(MHI_EE_FP,		"FLASH PROGRAMMER")		\
+	EM(MHI_EE_DISABLE_TRANSITION,	"DISABLE")		\
+	EMe(MHI_EE_NOT_SUPPORTED,	"NOT SUPPORTED")
+
+#define MHI_PM_STATE							\
+	EM(MHI_PM_STATE_DISABLE,	"DISABLE")			\
+	EM(MHI_PM_STATE_POR,		"POWER ON RESET")		\
+	EM(MHI_PM_STATE_M0,		"M0")				\
+	EM(MHI_PM_STATE_M2,		"M2")				\
+	EM(MHI_PM_STATE_M3_ENTER,	"M?->M3")			\
+	EM(MHI_PM_STATE_M3,		"M3")				\
+	EM(MHI_PM_STATE_M3_EXIT,	"M3->M0")			\
+	EM(MHI_PM_STATE_FW_DL_ERR,	"Firmware Download Error")	\
+	EM(MHI_PM_STATE_SYS_ERR_DETECT,		"SYS ERROR Detect")	\
+	EM(MHI_PM_STATE_SYS_ERR_PROCESS,	"SYS ERROR Process")	\
+	EM(MHI_PM_STATE_SHUTDOWN_PROCESS,	"SHUTDOWN Process")	\
+	EMe(MHI_PM_STATE_LD_ERR_FATAL_DETECT,	"Linkdown or Error Fatal Detect")
+
+#define MHI_CH_STATE						\
+	EM(MHI_CH_STATE_TYPE_RESET, "RESET")			\
+	EM(MHI_CH_STATE_TYPE_STOP, "STOP")			\
+	EMe(MHI_CH_STATE_TYPE_START, "START")
+
+#define MHI_DEV_ST_TRANSITION						\
+	EM(DEV_ST_TRANSITION_PBL,	"PBL")				\
+	EM(DEV_ST_TRANSITION_READY,	"READY")			\
+	EM(DEV_ST_TRANSITION_SBL,	"SBL")				\
+	EM(DEV_ST_TRANSITION_MISSION_MODE,	"MISSION MODE")		\
+	EM(DEV_ST_TRANSITION_FP,		"FLASH PROGRAMMER")	\
+	EM(DEV_ST_TRANSITION_SYS_ERR,		"SYS ERROR")		\
+	EMe(DEV_ST_TRANSITION_DISABLE,		"DISABLE")
+
+/* Enums require being exported to userspace, for user tool parsing */
+#undef	EM
+#undef	EMe
+#define	EM(a, b)	TRACE_DEFINE_ENUM(a);
+#define	EMe(a, b)	TRACE_DEFINE_ENUM(a);
+
+MHI_STATE
+MHI_EE
+MHI_PM_STATE
+MHI_CH_STATE
+MHI_DEV_ST_TRANSITION
+
+/*
+ * Now redefine the EM() and EMe() macros to map the enums to the strings
+ * that will be printed in the output.
+ */
+#undef EM
+#undef EMe
+#define EM(a, b)	{a, b},
+#define EMe(a, b)	{a, b}
+
+TRACE_EVENT(mhi_gen_tre,
+
+	TP_PROTO(const char *name, int ch_num, u64 wp, __le64 tre_ptr,
+		 __le32 dword0, __le32 dword1),
+
+	TP_ARGS(name, ch_num, wp, tre_ptr, dword0, dword1),
+
+	TP_STRUCT__entry(
+		__string(name, name)
+		__field(int, ch_num)
+		__field(u64, wp)
+		__field(__le64, tre_ptr)
+		__field(__le32, dword0)
+		__field(__le32, dword1)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, name);
+		__entry->ch_num = ch_num;
+		__entry->wp = wp;
+		__entry->tre_ptr = tre_ptr;
+		__entry->dword0 = dword0;
+		__entry->dword1 = dword1;
+	),
+
+	TP_printk("%s: Chan: %d WP: 0x%llx TRE: 0x%llx 0x%08x 0x%08x\n",
+		  __get_str(name), __entry->ch_num, __entry->wp, __entry->tre_ptr,
+		  __entry->dword0, __entry->dword1)
+);
+
+TRACE_EVENT(mhi_intvec_threaded_handler,
+
+	TP_PROTO(const char *name, int local_ee, int state, int dev_ee, int dev_state),
+
+	TP_ARGS(name, local_ee, state, dev_ee, dev_state),
+
+	TP_STRUCT__entry(
+		__string(name, name)
+		__field(int, local_ee)
+		__field(int, state)
+		__field(int, dev_ee)
+		__field(int, dev_state)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, name);
+		__entry->local_ee = local_ee;
+		__entry->state = state;
+		__entry->dev_ee = dev_ee;
+		__entry->dev_state = dev_state;
+	),
+
+	TP_printk("%s: local ee: %s state: %s device ee: %s state: %s\n",
+		  __get_str(name),
+		  __print_symbolic(__entry->local_ee, MHI_EE),
+		  __print_symbolic(__entry->state, MHI_STATE),
+		  __print_symbolic(__entry->dev_ee, MHI_EE),
+		  __print_symbolic(__entry->dev_state, MHI_STATE))
+);
+
+TRACE_EVENT(mhi_tryset_pm_state,
+
+	TP_PROTO(const char *name, int pm_state),
+
+	TP_ARGS(name, pm_state),
+
+	TP_STRUCT__entry(
+		__string(name, name)
+		__field(int, pm_state)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, name);
+		if (pm_state)
+			pm_state = __fls(pm_state);
+		__entry->pm_state = pm_state;
+	),
+
+	TP_printk("%s: PM state: %s\n", __get_str(name),
+		  __print_symbolic(__entry->pm_state, MHI_PM_STATE))
+);
+
+TRACE_EVENT(mhi_process_data_event_ring,
+
+	TP_PROTO(const char *name, __le64 ptr, __le32 dword0, __le32 dword1),
+
+	TP_ARGS(name, ptr, dword0, dword1),
+
+	TP_STRUCT__entry(
+		__string(name, name)
+		__field(__le64, ptr)
+		__field(__le32, dword0)
+		__field(__le32, dword1)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, name);
+		__entry->ptr = ptr;
+		__entry->dword0 = dword0;
+		__entry->dword1 = dword1;
+	),
+
+	TP_printk("%s: Processing Event:0x%llx 0x%08x 0x%08x\n",
+		  __get_str(name), __entry->ptr, __entry->dword0, __entry->dword1)
+);
+
+TRACE_EVENT(mhi_process_ctrl_ev_ring,
+
+	TP_PROTO(const char *name, u64 rp, __le64 ptr, __le32 dword0, __le32 dword1, int state),
+
+	TP_ARGS(name, rp, ptr, dword0, dword1, state),
+
+	TP_STRUCT__entry(
+		__string(name, name)
+		__field(u64, rp)
+		__field(__le64, ptr)
+		__field(__le32, dword0)
+		__field(__le32, dword1)
+		__field(int, state)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, name);
+		__entry->rp = rp;
+		__entry->ptr = ptr;
+		__entry->dword0 = dword0;
+		__entry->dword1 = dword1;
+		__entry->state = state;
+	),
+
+	TP_printk("%s: RP:0x%llx Processing Event:0x%llx 0x%08x 0x%08x state:%s\n",
+		  __get_str(name), __entry->rp, __entry->ptr, __entry->dword0,
+		  __entry->dword1, __print_symbolic(__entry->state, MHI_STATE))
+);
+
+TRACE_EVENT(mhi_update_channel_state_start,
+
+	TP_PROTO(const char *name, int ch_num, int state),
+
+	TP_ARGS(name, ch_num, state),
+
+	TP_STRUCT__entry(
+		__string(name, name)
+		__field(int, ch_num)
+		__field(int, state)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, name);
+		__entry->ch_num = ch_num;
+		__entry->state = state;
+	),
+
+	TP_printk("%s: ch%d: Updating state to: %s\n",
+		  __get_str(name), __entry->ch_num,
+		  __print_symbolic(__entry->state, MHI_CH_STATE))
+);
+
+TRACE_EVENT(mhi_update_channel_state_end,
+
+	TP_PROTO(const char *name, int ch_num, int state),
+
+	TP_ARGS(name, ch_num, state),
+
+	TP_STRUCT__entry(
+		__string(name, name)
+		__field(int, ch_num)
+		__field(int, state)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, name);
+		__entry->ch_num = ch_num;
+		__entry->state = state;
+	),
+
+	TP_printk("%s: ch%d: Updated state to: %s\n",
+		  __get_str(name), __entry->ch_num,
+		  __print_symbolic(__entry->state, MHI_CH_STATE))
+);
+
+TRACE_EVENT(mhi_pm_st_transition,
+
+	TP_PROTO(const char *name, int state),
+
+	TP_ARGS(name, state),
+
+	TP_STRUCT__entry(
+		__string(name, name)
+		__field(int, state)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, name);
+		__entry->state = state;
+	),
+
+	TP_printk("%s: Handling state transition: %s\n", __get_str(name),
+		  __print_symbolic(__entry->state, MHI_DEV_ST_TRANSITION))
+);
+
+#endif
+#include <trace/define_trace.h>