Subject: [PATCH v8] bus: mhi: host: Add tracing support

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_mhi_states
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

Where ever the trace events are added, debug messages are removed.

Signed-off-by: Krishna chaitanya chundru <[email protected]>
---
Changes in v8:
- Pass the structure and derefernce the variables in TP_fast_assign as suggested by steve
- Link to v7: https://lore.kernel.org/r/[email protected]

Changes in v7:
- change log format as pointed by mani.
- Link to v6: https://lore.kernel.org/r/[email protected]

Changes in v6:
- use 'rp' directly as suggested by jeffrey.
- Link to v5: https://lore.kernel.org/r/[email protected]

Changes in v5:
- Use DECLARE_EVENT_CLASS for multiple events as suggested by steve.
- Instead of converting to u64 to print address, use %px to print the address to avoid
- warnings in some platforms.
- Link to v4: https://lore.kernel.org/r/[email protected]

Changes in v4:
- Fix compilation issues in previous patch which happended due to rebasing.
- In the defconfig FTRACE config is not enabled due to that the compilation issue is not
- seen in my workspace.
- Link to v3: https://lore.kernel.org/r/[email protected]

Changes in v3:
- move trace header file from include/trace/events to drivers/bus/mhi/host/ so that
- we can include driver header files.
- Use macros directly in the trace events as suggested Jeffrey Hugo.
- Reorder the structure in the events as suggested by steve to avoid holes in the buffer.
- removed the mhi_to_physical function as this can give security issues.
- removed macros to define strings as we can get those from driver headers.
- Link to v2: https://lore.kernel.org/r/[email protected]

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/[email protected]
---
drivers/bus/mhi/host/init.c | 3 +
drivers/bus/mhi/host/main.c | 19 ++--
drivers/bus/mhi/host/pm.c | 7 +-
drivers/bus/mhi/host/trace.h | 205 +++++++++++++++++++++++++++++++++++++++++++
4 files changed, 221 insertions(+), 13 deletions(-)

diff --git a/drivers/bus/mhi/host/init.c b/drivers/bus/mhi/host/init.c
index f78aefd2d7a3..6acb85f4c5f8 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.h"
+
static DEFINE_IDA(mhi_controller_ida);

const char * const mhi_ee_str[MHI_EE_MAX] = {
diff --git a/drivers/bus/mhi/host/main.c b/drivers/bus/mhi/host/main.c
index dcf627b36e82..189f4786403e 100644
--- a/drivers/bus/mhi/host/main.c
+++ b/drivers/bus/mhi/host/main.c
@@ -15,6 +15,7 @@
#include <linux/skbuff.h>
#include <linux/slab.h>
#include "internal.h"
+#include "trace.h"

int __must_check mhi_read_reg(struct mhi_controller *mhi_cntrl,
void __iomem *base, u32 offset, u32 *out)
@@ -491,11 +492,8 @@ 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_states(mhi_cntrl, 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 +830,8 @@ 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_ctrl_event(mhi_cntrl, local_rp);
+
switch (type) {
case MHI_PKT_TYPE_BW_REQ_EVENT:
{
@@ -997,6 +997,8 @@ 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_data_event(mhi_cntrl, local_rp);
+
chan = MHI_TRE_GET_EV_CHID(local_rp);

WARN_ON(chan >= mhi_cntrl->max_chan);
@@ -1235,6 +1237,7 @@ 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_chan, mhi_tre);
/* increment WP */
mhi_add_ring_element(mhi_cntrl, tre_ring);
mhi_add_ring_element(mhi_cntrl, buf_ring);
@@ -1327,9 +1330,7 @@ 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_channel_command_start(mhi_cntrl, mhi_chan, to_state);
switch (to_state) {
case MHI_CH_STATE_TYPE_RESET:
write_lock_irq(&mhi_chan->lock);
@@ -1396,9 +1397,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_channel_command_end(mhi_cntrl, mhi_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..5a2394b5b2e1 100644
--- a/drivers/bus/mhi/host/pm.c
+++ b/drivers/bus/mhi/host/pm.c
@@ -15,6 +15,7 @@
#include <linux/slab.h>
#include <linux/wait.h>
#include "internal.h"
+#include "trace.h"

/*
* Not all MHI state transitions are synchronous. Transitions like Linkdown,
@@ -123,6 +124,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, state);
mhi_cntrl->pm_state = state;
return mhi_cntrl->pm_state;
}
@@ -753,7 +755,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 +762,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, itr->state);

switch (itr->state) {
case DEV_ST_TRANSITION_PBL:
diff --git a/drivers/bus/mhi/host/trace.h b/drivers/bus/mhi/host/trace.h
new file mode 100644
index 000000000000..73c129bb91d9
--- /dev/null
+++ b/drivers/bus/mhi/host/trace.h
@@ -0,0 +1,205 @@
+/* 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>
+#include <linux/trace_seq.h>
+#include "../common.h"
+#include "internal.h"
+
+TRACE_EVENT(mhi_gen_tre,
+
+ TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan *mhi_chan,
+ struct mhi_ring_element *mhi_tre),
+
+ TP_ARGS(mhi_cntrl, mhi_chan, mhi_tre),
+
+ TP_STRUCT__entry(
+ __string(name, mhi_cntrl->mhi_dev->name)
+ __field(int, ch_num)
+ __field(void *, wp)
+ __field(__le64, tre_ptr)
+ __field(__le32, dword0)
+ __field(__le32, dword1)
+ ),
+
+ TP_fast_assign(
+ __assign_str(name, mhi_cntrl->mhi_dev->name);
+ __entry->ch_num = mhi_chan->chan;
+ __entry->wp = mhi_tre;
+ __entry->tre_ptr = mhi_tre->ptr;
+ __entry->dword0 = mhi_tre->dword[0];
+ __entry->dword1 = mhi_tre->dword[1];
+ ),
+
+ TP_printk("%s: Chan: %d Tre: 0x%p Tre buf: 0x%llx dword0: 0x%08x dword1: 0x%08x\n",
+ __get_str(name), __entry->ch_num, __entry->wp, __entry->tre_ptr,
+ __entry->dword0, __entry->dword1)
+);
+
+TRACE_EVENT(mhi_intvec_states,
+
+ TP_PROTO(struct mhi_controller *mhi_cntrl, int dev_ee, int dev_state),
+
+ TP_ARGS(mhi_cntrl, dev_ee, dev_state),
+
+ TP_STRUCT__entry(
+ __string(name, mhi_cntrl->mhi_dev->name)
+ __field(int, local_ee)
+ __field(int, state)
+ __field(int, dev_ee)
+ __field(int, dev_state)
+ ),
+
+ TP_fast_assign(
+ __assign_str(name, mhi_cntrl->mhi_dev->name);
+ __entry->local_ee = mhi_cntrl->ee;
+ __entry->state = mhi_cntrl->dev_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),
+ TO_MHI_EXEC_STR(__entry->local_ee),
+ mhi_state_str(__entry->state),
+ TO_MHI_EXEC_STR(__entry->dev_ee),
+ mhi_state_str(__entry->dev_state))
+);
+
+TRACE_EVENT(mhi_tryset_pm_state,
+
+ TP_PROTO(struct mhi_controller *mhi_cntrl, int pm_state),
+
+ TP_ARGS(mhi_cntrl, pm_state),
+
+ TP_STRUCT__entry(
+ __string(name, mhi_cntrl->mhi_dev->name)
+ __field(int, pm_state)
+ ),
+
+ TP_fast_assign(
+ __assign_str(name, mhi_cntrl->mhi_dev->name);
+ if (pm_state)
+ pm_state = __fls(pm_state);
+ __entry->pm_state = pm_state;
+ ),
+
+ TP_printk("%s: PM state: %s\n", __get_str(name),
+ to_mhi_pm_state_str(__entry->pm_state))
+);
+
+DECLARE_EVENT_CLASS(mhi_process_event_ring,
+
+ TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_ring_element *rp),
+
+ TP_ARGS(mhi_cntrl, rp),
+
+ TP_STRUCT__entry(
+ __string(name, mhi_cntrl->mhi_dev->name)
+ __field(__le32, dword0)
+ __field(__le32, dword1)
+ __field(int, state)
+ __field(__le64, ptr)
+ __field(void *, rp)
+ ),
+
+ TP_fast_assign(
+ __assign_str(name, mhi_cntrl->mhi_dev->name);
+ __entry->rp = rp;
+ __entry->ptr = rp->ptr;
+ __entry->dword0 = rp->dword[0];
+ __entry->dword1 = rp->dword[1];
+ __entry->state = MHI_TRE_GET_EV_STATE(rp);
+ ),
+
+ TP_printk("%s: Tre: 0x%p Tre buf: 0x%llx dword0: 0x%08x dword1: 0x%08x state: %s\n",
+ __get_str(name), __entry->rp, __entry->ptr, __entry->dword0,
+ __entry->dword1, mhi_state_str(__entry->state))
+);
+
+DEFINE_EVENT(mhi_process_event_ring, mhi_data_event,
+
+ TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_ring_element *rp),
+
+ TP_ARGS(mhi_cntrl, rp)
+);
+
+DEFINE_EVENT(mhi_process_event_ring, mhi_ctrl_event,
+
+ TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_ring_element *rp),
+
+ TP_ARGS(mhi_cntrl, rp)
+);
+
+DECLARE_EVENT_CLASS(mhi_update_channel_state,
+
+ TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan *mhi_chan, int state),
+
+ TP_ARGS(mhi_cntrl, mhi_chan, state),
+
+ TP_STRUCT__entry(
+ __string(name, mhi_cntrl->mhi_dev->name)
+ __field(int, ch_num)
+ __field(int, state)
+ ),
+
+ TP_fast_assign(
+ __assign_str(name, mhi_cntrl->mhi_dev->name);
+ __entry->ch_num = mhi_chan->chan;
+ __entry->state = state;
+ ),
+
+ TP_printk("%s: chan%d: Updating state to: %s\n",
+ __get_str(name), __entry->ch_num,
+ TO_CH_STATE_TYPE_STR(__entry->state))
+);
+
+DEFINE_EVENT(mhi_update_channel_state, mhi_channel_command_start,
+
+ TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan *mhi_chan, int state),
+
+ TP_ARGS(mhi_cntrl, mhi_chan, state)
+);
+
+DEFINE_EVENT(mhi_update_channel_state, mhi_channel_command_end,
+
+ TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan *mhi_chan, int state),
+
+ TP_ARGS(mhi_cntrl, mhi_chan, state)
+);
+
+TRACE_EVENT(mhi_pm_st_transition,
+
+ TP_PROTO(struct mhi_controller *mhi_cntrl, int state),
+
+ TP_ARGS(mhi_cntrl, state),
+
+ TP_STRUCT__entry(
+ __string(name, mhi_cntrl->mhi_dev->name)
+ __field(int, state)
+ ),
+
+ TP_fast_assign(
+ __assign_str(name, mhi_cntrl->mhi_dev->name);
+ __entry->state = state;
+ ),
+
+ TP_printk("%s: Handling state transition: %s\n", __get_str(name),
+ TO_DEV_STATE_TRANS_STR(__entry->state))
+);
+
+#endif
+#undef TRACE_INCLUDE_PATH
+#define TRACE_INCLUDE_PATH ../../drivers/bus/mhi/host
+#undef TRACE_INCLUDE_FILE
+#define TRACE_INCLUDE_FILE trace
+
+#include <trace/define_trace.h>

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

Best regards,
--
Krishna chaitanya chundru <[email protected]>


Subject: Re: [PATCH v8] bus: mhi: host: Add tracing support

Hi Steven,

Can you review it once.

Thanks & Regards,

Krishna Chaitanya.

On 12/7/2023 10:00 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_mhi_states
> 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
>
> Where ever the trace events are added, debug messages are removed.
>
> Signed-off-by: Krishna chaitanya chundru <[email protected]>
> ---
> Changes in v8:
> - Pass the structure and derefernce the variables in TP_fast_assign as suggested by steve
> - Link to v7: https://lore.kernel.org/r/[email protected]
>
> Changes in v7:
> - change log format as pointed by mani.
> - Link to v6: https://lore.kernel.org/r/[email protected]
>
> Changes in v6:
> - use 'rp' directly as suggested by jeffrey.
> - Link to v5: https://lore.kernel.org/r/[email protected]
>
> Changes in v5:
> - Use DECLARE_EVENT_CLASS for multiple events as suggested by steve.
> - Instead of converting to u64 to print address, use %px to print the address to avoid
> - warnings in some platforms.
> - Link to v4: https://lore.kernel.org/r/[email protected]
>
> Changes in v4:
> - Fix compilation issues in previous patch which happended due to rebasing.
> - In the defconfig FTRACE config is not enabled due to that the compilation issue is not
> - seen in my workspace.
> - Link to v3: https://lore.kernel.org/r/[email protected]
>
> Changes in v3:
> - move trace header file from include/trace/events to drivers/bus/mhi/host/ so that
> - we can include driver header files.
> - Use macros directly in the trace events as suggested Jeffrey Hugo.
> - Reorder the structure in the events as suggested by steve to avoid holes in the buffer.
> - removed the mhi_to_physical function as this can give security issues.
> - removed macros to define strings as we can get those from driver headers.
> - Link to v2: https://lore.kernel.org/r/[email protected]
>
> 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/[email protected]
> ---
> drivers/bus/mhi/host/init.c | 3 +
> drivers/bus/mhi/host/main.c | 19 ++--
> drivers/bus/mhi/host/pm.c | 7 +-
> drivers/bus/mhi/host/trace.h | 205 +++++++++++++++++++++++++++++++++++++++++++
> 4 files changed, 221 insertions(+), 13 deletions(-)
>
> diff --git a/drivers/bus/mhi/host/init.c b/drivers/bus/mhi/host/init.c
> index f78aefd2d7a3..6acb85f4c5f8 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.h"
> +
> static DEFINE_IDA(mhi_controller_ida);
>
> const char * const mhi_ee_str[MHI_EE_MAX] = {
> diff --git a/drivers/bus/mhi/host/main.c b/drivers/bus/mhi/host/main.c
> index dcf627b36e82..189f4786403e 100644
> --- a/drivers/bus/mhi/host/main.c
> +++ b/drivers/bus/mhi/host/main.c
> @@ -15,6 +15,7 @@
> #include <linux/skbuff.h>
> #include <linux/slab.h>
> #include "internal.h"
> +#include "trace.h"
>
> int __must_check mhi_read_reg(struct mhi_controller *mhi_cntrl,
> void __iomem *base, u32 offset, u32 *out)
> @@ -491,11 +492,8 @@ 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_states(mhi_cntrl, 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 +830,8 @@ 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_ctrl_event(mhi_cntrl, local_rp);
> +
> switch (type) {
> case MHI_PKT_TYPE_BW_REQ_EVENT:
> {
> @@ -997,6 +997,8 @@ 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_data_event(mhi_cntrl, local_rp);
> +
> chan = MHI_TRE_GET_EV_CHID(local_rp);
>
> WARN_ON(chan >= mhi_cntrl->max_chan);
> @@ -1235,6 +1237,7 @@ 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_chan, mhi_tre);
> /* increment WP */
> mhi_add_ring_element(mhi_cntrl, tre_ring);
> mhi_add_ring_element(mhi_cntrl, buf_ring);
> @@ -1327,9 +1330,7 @@ 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_channel_command_start(mhi_cntrl, mhi_chan, to_state);
> switch (to_state) {
> case MHI_CH_STATE_TYPE_RESET:
> write_lock_irq(&mhi_chan->lock);
> @@ -1396,9 +1397,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_channel_command_end(mhi_cntrl, mhi_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..5a2394b5b2e1 100644
> --- a/drivers/bus/mhi/host/pm.c
> +++ b/drivers/bus/mhi/host/pm.c
> @@ -15,6 +15,7 @@
> #include <linux/slab.h>
> #include <linux/wait.h>
> #include "internal.h"
> +#include "trace.h"
>
> /*
> * Not all MHI state transitions are synchronous. Transitions like Linkdown,
> @@ -123,6 +124,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, state);
> mhi_cntrl->pm_state = state;
> return mhi_cntrl->pm_state;
> }
> @@ -753,7 +755,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 +762,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, itr->state);
>
> switch (itr->state) {
> case DEV_ST_TRANSITION_PBL:
> diff --git a/drivers/bus/mhi/host/trace.h b/drivers/bus/mhi/host/trace.h
> new file mode 100644
> index 000000000000..73c129bb91d9
> --- /dev/null
> +++ b/drivers/bus/mhi/host/trace.h
> @@ -0,0 +1,205 @@
> +/* 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>
> +#include <linux/trace_seq.h>
> +#include "../common.h"
> +#include "internal.h"
> +
> +TRACE_EVENT(mhi_gen_tre,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan *mhi_chan,
> + struct mhi_ring_element *mhi_tre),
> +
> + TP_ARGS(mhi_cntrl, mhi_chan, mhi_tre),
> +
> + TP_STRUCT__entry(
> + __string(name, mhi_cntrl->mhi_dev->name)
> + __field(int, ch_num)
> + __field(void *, wp)
> + __field(__le64, tre_ptr)
> + __field(__le32, dword0)
> + __field(__le32, dword1)
> + ),
> +
> + TP_fast_assign(
> + __assign_str(name, mhi_cntrl->mhi_dev->name);
> + __entry->ch_num = mhi_chan->chan;
> + __entry->wp = mhi_tre;
> + __entry->tre_ptr = mhi_tre->ptr;
> + __entry->dword0 = mhi_tre->dword[0];
> + __entry->dword1 = mhi_tre->dword[1];
> + ),
> +
> + TP_printk("%s: Chan: %d Tre: 0x%p Tre buf: 0x%llx dword0: 0x%08x dword1: 0x%08x\n",
> + __get_str(name), __entry->ch_num, __entry->wp, __entry->tre_ptr,
> + __entry->dword0, __entry->dword1)
> +);
> +
> +TRACE_EVENT(mhi_intvec_states,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, int dev_ee, int dev_state),
> +
> + TP_ARGS(mhi_cntrl, dev_ee, dev_state),
> +
> + TP_STRUCT__entry(
> + __string(name, mhi_cntrl->mhi_dev->name)
> + __field(int, local_ee)
> + __field(int, state)
> + __field(int, dev_ee)
> + __field(int, dev_state)
> + ),
> +
> + TP_fast_assign(
> + __assign_str(name, mhi_cntrl->mhi_dev->name);
> + __entry->local_ee = mhi_cntrl->ee;
> + __entry->state = mhi_cntrl->dev_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),
> + TO_MHI_EXEC_STR(__entry->local_ee),
> + mhi_state_str(__entry->state),
> + TO_MHI_EXEC_STR(__entry->dev_ee),
> + mhi_state_str(__entry->dev_state))
> +);
> +
> +TRACE_EVENT(mhi_tryset_pm_state,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, int pm_state),
> +
> + TP_ARGS(mhi_cntrl, pm_state),
> +
> + TP_STRUCT__entry(
> + __string(name, mhi_cntrl->mhi_dev->name)
> + __field(int, pm_state)
> + ),
> +
> + TP_fast_assign(
> + __assign_str(name, mhi_cntrl->mhi_dev->name);
> + if (pm_state)
> + pm_state = __fls(pm_state);
> + __entry->pm_state = pm_state;
> + ),
> +
> + TP_printk("%s: PM state: %s\n", __get_str(name),
> + to_mhi_pm_state_str(__entry->pm_state))
> +);
> +
> +DECLARE_EVENT_CLASS(mhi_process_event_ring,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_ring_element *rp),
> +
> + TP_ARGS(mhi_cntrl, rp),
> +
> + TP_STRUCT__entry(
> + __string(name, mhi_cntrl->mhi_dev->name)
> + __field(__le32, dword0)
> + __field(__le32, dword1)
> + __field(int, state)
> + __field(__le64, ptr)
> + __field(void *, rp)
> + ),
> +
> + TP_fast_assign(
> + __assign_str(name, mhi_cntrl->mhi_dev->name);
> + __entry->rp = rp;
> + __entry->ptr = rp->ptr;
> + __entry->dword0 = rp->dword[0];
> + __entry->dword1 = rp->dword[1];
> + __entry->state = MHI_TRE_GET_EV_STATE(rp);
> + ),
> +
> + TP_printk("%s: Tre: 0x%p Tre buf: 0x%llx dword0: 0x%08x dword1: 0x%08x state: %s\n",
> + __get_str(name), __entry->rp, __entry->ptr, __entry->dword0,
> + __entry->dword1, mhi_state_str(__entry->state))
> +);
> +
> +DEFINE_EVENT(mhi_process_event_ring, mhi_data_event,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_ring_element *rp),
> +
> + TP_ARGS(mhi_cntrl, rp)
> +);
> +
> +DEFINE_EVENT(mhi_process_event_ring, mhi_ctrl_event,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_ring_element *rp),
> +
> + TP_ARGS(mhi_cntrl, rp)
> +);
> +
> +DECLARE_EVENT_CLASS(mhi_update_channel_state,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan *mhi_chan, int state),
> +
> + TP_ARGS(mhi_cntrl, mhi_chan, state),
> +
> + TP_STRUCT__entry(
> + __string(name, mhi_cntrl->mhi_dev->name)
> + __field(int, ch_num)
> + __field(int, state)
> + ),
> +
> + TP_fast_assign(
> + __assign_str(name, mhi_cntrl->mhi_dev->name);
> + __entry->ch_num = mhi_chan->chan;
> + __entry->state = state;
> + ),
> +
> + TP_printk("%s: chan%d: Updating state to: %s\n",
> + __get_str(name), __entry->ch_num,
> + TO_CH_STATE_TYPE_STR(__entry->state))
> +);
> +
> +DEFINE_EVENT(mhi_update_channel_state, mhi_channel_command_start,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan *mhi_chan, int state),
> +
> + TP_ARGS(mhi_cntrl, mhi_chan, state)
> +);
> +
> +DEFINE_EVENT(mhi_update_channel_state, mhi_channel_command_end,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan *mhi_chan, int state),
> +
> + TP_ARGS(mhi_cntrl, mhi_chan, state)
> +);
> +
> +TRACE_EVENT(mhi_pm_st_transition,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, int state),
> +
> + TP_ARGS(mhi_cntrl, state),
> +
> + TP_STRUCT__entry(
> + __string(name, mhi_cntrl->mhi_dev->name)
> + __field(int, state)
> + ),
> +
> + TP_fast_assign(
> + __assign_str(name, mhi_cntrl->mhi_dev->name);
> + __entry->state = state;
> + ),
> +
> + TP_printk("%s: Handling state transition: %s\n", __get_str(name),
> + TO_DEV_STATE_TRANS_STR(__entry->state))
> +);
> +
> +#endif
> +#undef TRACE_INCLUDE_PATH
> +#define TRACE_INCLUDE_PATH ../../drivers/bus/mhi/host
> +#undef TRACE_INCLUDE_FILE
> +#define TRACE_INCLUDE_FILE trace
> +
> +#include <trace/define_trace.h>
>
> ---
> base-commit: 3006adf3be79cde4d14b1800b963b82b6e5572e0
> change-id: 20231005-ftrace_support-6869d4156139
>
> Best regards,

Subject: Re: [PATCH v8] bus: mhi: host: Add tracing support

Hi Steven,

Can you please review this.

Thanks & Regards,

Krishna Chaitanya.

On 12/7/2023 10:00 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_mhi_states
> 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
>
> Where ever the trace events are added, debug messages are removed.
>
> Signed-off-by: Krishna chaitanya chundru <[email protected]>
> ---
> Changes in v8:
> - Pass the structure and derefernce the variables in TP_fast_assign as suggested by steve
> - Link to v7: https://lore.kernel.org/r/[email protected]
>
> Changes in v7:
> - change log format as pointed by mani.
> - Link to v6: https://lore.kernel.org/r/[email protected]
>
> Changes in v6:
> - use 'rp' directly as suggested by jeffrey.
> - Link to v5: https://lore.kernel.org/r/[email protected]
>
> Changes in v5:
> - Use DECLARE_EVENT_CLASS for multiple events as suggested by steve.
> - Instead of converting to u64 to print address, use %px to print the address to avoid
> - warnings in some platforms.
> - Link to v4: https://lore.kernel.org/r/[email protected]
>
> Changes in v4:
> - Fix compilation issues in previous patch which happended due to rebasing.
> - In the defconfig FTRACE config is not enabled due to that the compilation issue is not
> - seen in my workspace.
> - Link to v3: https://lore.kernel.org/r/[email protected]
>
> Changes in v3:
> - move trace header file from include/trace/events to drivers/bus/mhi/host/ so that
> - we can include driver header files.
> - Use macros directly in the trace events as suggested Jeffrey Hugo.
> - Reorder the structure in the events as suggested by steve to avoid holes in the buffer.
> - removed the mhi_to_physical function as this can give security issues.
> - removed macros to define strings as we can get those from driver headers.
> - Link to v2: https://lore.kernel.org/r/[email protected]
>
> 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/[email protected]
> ---
> drivers/bus/mhi/host/init.c | 3 +
> drivers/bus/mhi/host/main.c | 19 ++--
> drivers/bus/mhi/host/pm.c | 7 +-
> drivers/bus/mhi/host/trace.h | 205 +++++++++++++++++++++++++++++++++++++++++++
> 4 files changed, 221 insertions(+), 13 deletions(-)
>
> diff --git a/drivers/bus/mhi/host/init.c b/drivers/bus/mhi/host/init.c
> index f78aefd2d7a3..6acb85f4c5f8 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.h"
> +
> static DEFINE_IDA(mhi_controller_ida);
>
> const char * const mhi_ee_str[MHI_EE_MAX] = {
> diff --git a/drivers/bus/mhi/host/main.c b/drivers/bus/mhi/host/main.c
> index dcf627b36e82..189f4786403e 100644
> --- a/drivers/bus/mhi/host/main.c
> +++ b/drivers/bus/mhi/host/main.c
> @@ -15,6 +15,7 @@
> #include <linux/skbuff.h>
> #include <linux/slab.h>
> #include "internal.h"
> +#include "trace.h"
>
> int __must_check mhi_read_reg(struct mhi_controller *mhi_cntrl,
> void __iomem *base, u32 offset, u32 *out)
> @@ -491,11 +492,8 @@ 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_states(mhi_cntrl, 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 +830,8 @@ 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_ctrl_event(mhi_cntrl, local_rp);
> +
> switch (type) {
> case MHI_PKT_TYPE_BW_REQ_EVENT:
> {
> @@ -997,6 +997,8 @@ 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_data_event(mhi_cntrl, local_rp);
> +
> chan = MHI_TRE_GET_EV_CHID(local_rp);
>
> WARN_ON(chan >= mhi_cntrl->max_chan);
> @@ -1235,6 +1237,7 @@ 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_chan, mhi_tre);
> /* increment WP */
> mhi_add_ring_element(mhi_cntrl, tre_ring);
> mhi_add_ring_element(mhi_cntrl, buf_ring);
> @@ -1327,9 +1330,7 @@ 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_channel_command_start(mhi_cntrl, mhi_chan, to_state);
> switch (to_state) {
> case MHI_CH_STATE_TYPE_RESET:
> write_lock_irq(&mhi_chan->lock);
> @@ -1396,9 +1397,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_channel_command_end(mhi_cntrl, mhi_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..5a2394b5b2e1 100644
> --- a/drivers/bus/mhi/host/pm.c
> +++ b/drivers/bus/mhi/host/pm.c
> @@ -15,6 +15,7 @@
> #include <linux/slab.h>
> #include <linux/wait.h>
> #include "internal.h"
> +#include "trace.h"
>
> /*
> * Not all MHI state transitions are synchronous. Transitions like Linkdown,
> @@ -123,6 +124,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, state);
> mhi_cntrl->pm_state = state;
> return mhi_cntrl->pm_state;
> }
> @@ -753,7 +755,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 +762,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, itr->state);
>
> switch (itr->state) {
> case DEV_ST_TRANSITION_PBL:
> diff --git a/drivers/bus/mhi/host/trace.h b/drivers/bus/mhi/host/trace.h
> new file mode 100644
> index 000000000000..73c129bb91d9
> --- /dev/null
> +++ b/drivers/bus/mhi/host/trace.h
> @@ -0,0 +1,205 @@
> +/* 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>
> +#include <linux/trace_seq.h>
> +#include "../common.h"
> +#include "internal.h"
> +
> +TRACE_EVENT(mhi_gen_tre,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan *mhi_chan,
> + struct mhi_ring_element *mhi_tre),
> +
> + TP_ARGS(mhi_cntrl, mhi_chan, mhi_tre),
> +
> + TP_STRUCT__entry(
> + __string(name, mhi_cntrl->mhi_dev->name)
> + __field(int, ch_num)
> + __field(void *, wp)
> + __field(__le64, tre_ptr)
> + __field(__le32, dword0)
> + __field(__le32, dword1)
> + ),
> +
> + TP_fast_assign(
> + __assign_str(name, mhi_cntrl->mhi_dev->name);
> + __entry->ch_num = mhi_chan->chan;
> + __entry->wp = mhi_tre;
> + __entry->tre_ptr = mhi_tre->ptr;
> + __entry->dword0 = mhi_tre->dword[0];
> + __entry->dword1 = mhi_tre->dword[1];
> + ),
> +
> + TP_printk("%s: Chan: %d Tre: 0x%p Tre buf: 0x%llx dword0: 0x%08x dword1: 0x%08x\n",
> + __get_str(name), __entry->ch_num, __entry->wp, __entry->tre_ptr,
> + __entry->dword0, __entry->dword1)
> +);
> +
> +TRACE_EVENT(mhi_intvec_states,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, int dev_ee, int dev_state),
> +
> + TP_ARGS(mhi_cntrl, dev_ee, dev_state),
> +
> + TP_STRUCT__entry(
> + __string(name, mhi_cntrl->mhi_dev->name)
> + __field(int, local_ee)
> + __field(int, state)
> + __field(int, dev_ee)
> + __field(int, dev_state)
> + ),
> +
> + TP_fast_assign(
> + __assign_str(name, mhi_cntrl->mhi_dev->name);
> + __entry->local_ee = mhi_cntrl->ee;
> + __entry->state = mhi_cntrl->dev_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),
> + TO_MHI_EXEC_STR(__entry->local_ee),
> + mhi_state_str(__entry->state),
> + TO_MHI_EXEC_STR(__entry->dev_ee),
> + mhi_state_str(__entry->dev_state))
> +);
> +
> +TRACE_EVENT(mhi_tryset_pm_state,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, int pm_state),
> +
> + TP_ARGS(mhi_cntrl, pm_state),
> +
> + TP_STRUCT__entry(
> + __string(name, mhi_cntrl->mhi_dev->name)
> + __field(int, pm_state)
> + ),
> +
> + TP_fast_assign(
> + __assign_str(name, mhi_cntrl->mhi_dev->name);
> + if (pm_state)
> + pm_state = __fls(pm_state);
> + __entry->pm_state = pm_state;
> + ),
> +
> + TP_printk("%s: PM state: %s\n", __get_str(name),
> + to_mhi_pm_state_str(__entry->pm_state))
> +);
> +
> +DECLARE_EVENT_CLASS(mhi_process_event_ring,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_ring_element *rp),
> +
> + TP_ARGS(mhi_cntrl, rp),
> +
> + TP_STRUCT__entry(
> + __string(name, mhi_cntrl->mhi_dev->name)
> + __field(__le32, dword0)
> + __field(__le32, dword1)
> + __field(int, state)
> + __field(__le64, ptr)
> + __field(void *, rp)
> + ),
> +
> + TP_fast_assign(
> + __assign_str(name, mhi_cntrl->mhi_dev->name);
> + __entry->rp = rp;
> + __entry->ptr = rp->ptr;
> + __entry->dword0 = rp->dword[0];
> + __entry->dword1 = rp->dword[1];
> + __entry->state = MHI_TRE_GET_EV_STATE(rp);
> + ),
> +
> + TP_printk("%s: Tre: 0x%p Tre buf: 0x%llx dword0: 0x%08x dword1: 0x%08x state: %s\n",
> + __get_str(name), __entry->rp, __entry->ptr, __entry->dword0,
> + __entry->dword1, mhi_state_str(__entry->state))
> +);
> +
> +DEFINE_EVENT(mhi_process_event_ring, mhi_data_event,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_ring_element *rp),
> +
> + TP_ARGS(mhi_cntrl, rp)
> +);
> +
> +DEFINE_EVENT(mhi_process_event_ring, mhi_ctrl_event,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_ring_element *rp),
> +
> + TP_ARGS(mhi_cntrl, rp)
> +);
> +
> +DECLARE_EVENT_CLASS(mhi_update_channel_state,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan *mhi_chan, int state),
> +
> + TP_ARGS(mhi_cntrl, mhi_chan, state),
> +
> + TP_STRUCT__entry(
> + __string(name, mhi_cntrl->mhi_dev->name)
> + __field(int, ch_num)
> + __field(int, state)
> + ),
> +
> + TP_fast_assign(
> + __assign_str(name, mhi_cntrl->mhi_dev->name);
> + __entry->ch_num = mhi_chan->chan;
> + __entry->state = state;
> + ),
> +
> + TP_printk("%s: chan%d: Updating state to: %s\n",
> + __get_str(name), __entry->ch_num,
> + TO_CH_STATE_TYPE_STR(__entry->state))
> +);
> +
> +DEFINE_EVENT(mhi_update_channel_state, mhi_channel_command_start,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan *mhi_chan, int state),
> +
> + TP_ARGS(mhi_cntrl, mhi_chan, state)
> +);
> +
> +DEFINE_EVENT(mhi_update_channel_state, mhi_channel_command_end,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan *mhi_chan, int state),
> +
> + TP_ARGS(mhi_cntrl, mhi_chan, state)
> +);
> +
> +TRACE_EVENT(mhi_pm_st_transition,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, int state),
> +
> + TP_ARGS(mhi_cntrl, state),
> +
> + TP_STRUCT__entry(
> + __string(name, mhi_cntrl->mhi_dev->name)
> + __field(int, state)
> + ),
> +
> + TP_fast_assign(
> + __assign_str(name, mhi_cntrl->mhi_dev->name);
> + __entry->state = state;
> + ),
> +
> + TP_printk("%s: Handling state transition: %s\n", __get_str(name),
> + TO_DEV_STATE_TRANS_STR(__entry->state))
> +);
> +
> +#endif
> +#undef TRACE_INCLUDE_PATH
> +#define TRACE_INCLUDE_PATH ../../drivers/bus/mhi/host
> +#undef TRACE_INCLUDE_FILE
> +#define TRACE_INCLUDE_FILE trace
> +
> +#include <trace/define_trace.h>
>
> ---
> base-commit: 3006adf3be79cde4d14b1800b963b82b6e5572e0
> change-id: 20231005-ftrace_support-6869d4156139
>
> Best regards,

2024-01-04 16:00:35

by Steven Rostedt

[permalink] [raw]
Subject: Re: [PATCH v8] bus: mhi: host: Add tracing support

On Thu, 7 Dec 2023 10:00:47 +0530
Krishna chaitanya chundru <[email protected]> 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_mhi_states
> 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
>
> Where ever the trace events are added, debug messages are removed.
>
> Signed-off-by: Krishna chaitanya chundru <[email protected]>
> ---
> Changes in v8:
> - Pass the structure and derefernce the variables in TP_fast_assign as suggested by steve
> - Link to v7: https://lore.kernel.org/r/[email protected]

So this looks good from a tracing POV.

Reviewed-by: Steven Rostedt (Google) <[email protected]>

But I do have some more comments that could be done by new patches.



> +TRACE_EVENT(mhi_intvec_states,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, int dev_ee, int dev_state),
> +
> + TP_ARGS(mhi_cntrl, dev_ee, dev_state),
> +
> + TP_STRUCT__entry(
> + __string(name, mhi_cntrl->mhi_dev->name)
> + __field(int, local_ee)
> + __field(int, state)
> + __field(int, dev_ee)
> + __field(int, dev_state)
> + ),
> +
> + TP_fast_assign(
> + __assign_str(name, mhi_cntrl->mhi_dev->name);
> + __entry->local_ee = mhi_cntrl->ee;
> + __entry->state = mhi_cntrl->dev_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),
> + TO_MHI_EXEC_STR(__entry->local_ee),
> + mhi_state_str(__entry->state),
> + TO_MHI_EXEC_STR(__entry->dev_ee),
> + mhi_state_str(__entry->dev_state))

So the above may have issues with user space parsing.

For one, that mhi_state_str() is:

static inline const char *mhi_state_str(enum mhi_state state)
{
switch (state) {
case MHI_STATE_RESET:
return "RESET";
case MHI_STATE_READY:
return "READY";
case MHI_STATE_M0:
return "M0";
case MHI_STATE_M1:
return "M1";
case MHI_STATE_M2:
return "M2";
case MHI_STATE_M3:
return "M3";
case MHI_STATE_M3_FAST:
return "M3 FAST";
case MHI_STATE_BHI:
return "BHI";
case MHI_STATE_SYS_ERR:
return "SYS ERROR";
default:
return "Unknown state";
}
};

Which if this could be changed into:

#define MHI_STATE_LIST \
EM(RESET, "RESET") \
EM(READY, "READY") \
EM(M0, "M0") \
EM(M1, "M1") \
EM(M2, "M2") \
EM(M3, "M3") \
EM(M3_FAST, "M3_FAST") \
EM(BHI, "BHI") \
EMe(SYS_ERR, "SYS ERROR")

#undef EM
#undef EMe

#define EM(a, b) case MHI_STATE_##a: return b;
#define EMe(a, b) case MHI_STATE_##a: return b;

static inline const char *mhi_state_str(enum mhi_state state)
{
switch (state) {
MHI_STATE_LIST
default:
return "Unknown state";
}

Then you could use that macro in the trace header:

#undef EM
#undef EMe

#define EM(a, b) TRACE_DEFINE_ENUM(MHI_STATE_##a);
#define EMe(a, b) TRACE_DEFINE_ENUM(MHI_STATE_##a);

MHI_STATE_LIST

And in the print fmts:

#undef EM
#undef EMe

#define EM(a, b) { MHI_STATE_##a, b },
#define EMe(a, b) { MHI_STATE_##a, b }


TP_printk("%s: local ee: %s state: %s device ee: %s state: %s\n",
__get_str(name),
TO_MHI_EXEC_STR(__entry->local_ee),

__print_symbolic(__entry->state), MHI_STATE_LIST),

TO_MHI_EXEC_STR(__entry->dev_ee),

__print_symbolic(__entry->dev_state, MHI_STATE_LIST))


And that will be exported to user space in the
/sys/kernel/tracing/events/*/*/format file, as:

__print_symbolic(REC->state, {
{ MHI_STATE_RESET, "RESET"},
{ MHI_STATE_READY, "READY"},
{ MHI_STATE_M0, "M0"},
{ MHI_STATE_M1, "M1"},
{ MHI_STATE_M2, "M2"},
{ MHI_STATE_M3, "M3"},
{ MHI_STATE_M3_FAST, "M3 FAST"},
{ MHI_STATE_BHI, "BHI"},
{ MHI_STATE_SYS_ERR, "SYS ERROR"} }

Which libtracevent knows how to parse. Oh, it wouldn't even show the enum
names as the TRACE_DEFINE_ENUM() above, would tell the kernel to replace
them with their actual numeric values. That way, when trace-cmd or perf
reads the raw data, it knows how to print it.

Now what about those TO_MHI_EXEC_STR() macros? They are not the same. They are:

#define TO_MHI_EXEC_STR(ee) (((ee) >= MHI_EE_MAX) ? \
"INVALID_EE" : mhi_ee_str[ee])

Where that mhi_ee_str[] is:

const char * const mhi_ee_str[MHI_EE_MAX] = {
[MHI_EE_PBL] = "PRIMARY BOOTLOADER",
[MHI_EE_SBL] = "SECONDARY BOOTLOADER",
[MHI_EE_AMSS] = "MISSION MODE",
[MHI_EE_RDDM] = "RAMDUMP DOWNLOAD MODE",
[MHI_EE_WFW] = "WLAN FIRMWARE",
[MHI_EE_PTHRU] = "PASS THROUGH",
[MHI_EE_EDL] = "EMERGENCY DOWNLOAD",
[MHI_EE_FP] = "FLASH PROGRAMMER",
[MHI_EE_DISABLE_TRANSITION] = "DISABLE",
[MHI_EE_NOT_SUPPORTED] = "NOT SUPPORTED",
};

Which would require doing the same thing for that as well.

#define MHI_EE_LIST \
EM(PBL, "PRIMARY BOOTLOADER") \
EM(SBL, "SECONDARY BOOTLOADER") \
EM(AMSS, "MISSION MODE") \
EM(RDDM, "RAMDUMP DOWNLOAD MODE")\
EM(WFW, "WLAN FIRMWARE") \
EM(PTHRU, "PASS THROUGH") \
EM(EDL, "EMERGENCY DOWNLOAD") \
EM(FP, "FLASH PROGRAMMER") \
EM(DISABLE_TRANSITION, "DISABLE") \
EMe(NOT_SUPPORTED, "NOT SUPPORTED")

And have:

#undef EM
#undef EMe

#define EM(a, b) [MHI_EE_##a] = b,
#define EMe(a, b) [MHI_EE_##a] = b,

const char * const mhi_ee_str[MHI_EE_MAX] = {
MHI_EE_LIST
};

and so on. That way the user space parsing will know how to properly parse
these events.

Note, if you don't want to modify the other files, you can still just all
the above to the trace.h file and it will still properly map the enums to
the strings. That is, don't modify the mhi_ee_str(), but instead just add
the MHI_EE_LIST macro in the trace header, and use the __print_symbolic()
with it.

I only mentioned modifying the strings to make it consistent if new strings
are added.

-- Steve


> +);
> +
> +TRACE_EVENT(mhi_tryset_pm_state,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, int pm_state),
> +
> + TP_ARGS(mhi_cntrl, pm_state),
> +
> + TP_STRUCT__entry(
> + __string(name, mhi_cntrl->mhi_dev->name)
> + __field(int, pm_state)
> + ),
> +
> + TP_fast_assign(
> + __assign_str(name, mhi_cntrl->mhi_dev->name);
> + if (pm_state)
> + pm_state = __fls(pm_state);
> + __entry->pm_state = pm_state;
> + ),
> +
> + TP_printk("%s: PM state: %s\n", __get_str(name),
> + to_mhi_pm_state_str(__entry->pm_state))
> +);
> +
> +DECLARE_EVENT_CLASS(mhi_process_event_ring,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct
> mhi_ring_element *rp), +
> + TP_ARGS(mhi_cntrl, rp),
> +
> + TP_STRUCT__entry(
> + __string(name, mhi_cntrl->mhi_dev->name)
> + __field(__le32, dword0)
> + __field(__le32, dword1)
> + __field(int, state)
> + __field(__le64, ptr)
> + __field(void *, rp)
> + ),
> +
> + TP_fast_assign(
> + __assign_str(name, mhi_cntrl->mhi_dev->name);
> + __entry->rp = rp;
> + __entry->ptr = rp->ptr;
> + __entry->dword0 = rp->dword[0];
> + __entry->dword1 = rp->dword[1];
> + __entry->state = MHI_TRE_GET_EV_STATE(rp);
> + ),
> +
> + TP_printk("%s: Tre: 0x%p Tre buf: 0x%llx dword0: 0x%08x dword1:
> 0x%08x state: %s\n",
> + __get_str(name), __entry->rp, __entry->ptr,
> __entry->dword0,
> + __entry->dword1, mhi_state_str(__entry->state))
> +);
> +
> +DEFINE_EVENT(mhi_process_event_ring, mhi_data_event,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct
> mhi_ring_element *rp), +
> + TP_ARGS(mhi_cntrl, rp)
> +);
> +
> +DEFINE_EVENT(mhi_process_event_ring, mhi_ctrl_event,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct
> mhi_ring_element *rp), +
> + TP_ARGS(mhi_cntrl, rp)
> +);
> +
> +DECLARE_EVENT_CLASS(mhi_update_channel_state,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan
> *mhi_chan, int state), +
> + TP_ARGS(mhi_cntrl, mhi_chan, state),
> +
> + TP_STRUCT__entry(
> + __string(name, mhi_cntrl->mhi_dev->name)
> + __field(int, ch_num)
> + __field(int, state)
> + ),
> +
> + TP_fast_assign(
> + __assign_str(name, mhi_cntrl->mhi_dev->name);
> + __entry->ch_num = mhi_chan->chan;
> + __entry->state = state;
> + ),
> +
> + TP_printk("%s: chan%d: Updating state to: %s\n",
> + __get_str(name), __entry->ch_num,
> + TO_CH_STATE_TYPE_STR(__entry->state))
> +);
> +
> +DEFINE_EVENT(mhi_update_channel_state, mhi_channel_command_start,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan
> *mhi_chan, int state), +
> + TP_ARGS(mhi_cntrl, mhi_chan, state)
> +);
> +
> +DEFINE_EVENT(mhi_update_channel_state, mhi_channel_command_end,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan
> *mhi_chan, int state), +
> + TP_ARGS(mhi_cntrl, mhi_chan, state)
> +);
> +
> +TRACE_EVENT(mhi_pm_st_transition,
> +
> + TP_PROTO(struct mhi_controller *mhi_cntrl, int state),
> +
> + TP_ARGS(mhi_cntrl, state),
> +
> + TP_STRUCT__entry(
> + __string(name, mhi_cntrl->mhi_dev->name)
> + __field(int, state)
> + ),
> +
> + TP_fast_assign(
> + __assign_str(name, mhi_cntrl->mhi_dev->name);
> + __entry->state = state;
> + ),
> +
> + TP_printk("%s: Handling state transition: %s\n", __get_str(name),
> + TO_DEV_STATE_TRANS_STR(__entry->state))
> +);
> +
> +#endif
> +#undef TRACE_INCLUDE_PATH
> +#define TRACE_INCLUDE_PATH ../../drivers/bus/mhi/host
> +#undef TRACE_INCLUDE_FILE
> +#define TRACE_INCLUDE_FILE trace
> +
> +#include <trace/define_trace.h>
>
> ---
> base-commit: 3006adf3be79cde4d14b1800b963b82b6e5572e0
> change-id: 20231005-ftrace_support-6869d4156139
>
> Best regards,


Subject: Re: [PATCH v8] bus: mhi: host: Add tracing support


On 1/4/2024 9:31 PM, Steven Rostedt wrote:
> On Thu, 7 Dec 2023 10:00:47 +0530
> Krishna chaitanya chundru <[email protected]> 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_mhi_states
>> 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
>>
>> Where ever the trace events are added, debug messages are removed.
>>
>> Signed-off-by: Krishna chaitanya chundru <[email protected]>
>> ---
>> Changes in v8:
>> - Pass the structure and derefernce the variables in TP_fast_assign as suggested by steve
>> - Link to v7: https://lore.kernel.org/r/[email protected]
> So this looks good from a tracing POV.
>
> Reviewed-by: Steven Rostedt (Google) <[email protected]>
>
> But I do have some more comments that could be done by new patches.
>
>
>
>> +TRACE_EVENT(mhi_intvec_states,
>> +
>> + TP_PROTO(struct mhi_controller *mhi_cntrl, int dev_ee, int dev_state),
>> +
>> + TP_ARGS(mhi_cntrl, dev_ee, dev_state),
>> +
>> + TP_STRUCT__entry(
>> + __string(name, mhi_cntrl->mhi_dev->name)
>> + __field(int, local_ee)
>> + __field(int, state)
>> + __field(int, dev_ee)
>> + __field(int, dev_state)
>> + ),
>> +
>> + TP_fast_assign(
>> + __assign_str(name, mhi_cntrl->mhi_dev->name);
>> + __entry->local_ee = mhi_cntrl->ee;
>> + __entry->state = mhi_cntrl->dev_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),
>> + TO_MHI_EXEC_STR(__entry->local_ee),
>> + mhi_state_str(__entry->state),
>> + TO_MHI_EXEC_STR(__entry->dev_ee),
>> + mhi_state_str(__entry->dev_state))
> So the above may have issues with user space parsing.
>
> For one, that mhi_state_str() is:
>
> static inline const char *mhi_state_str(enum mhi_state state)
> {
> switch (state) {
> case MHI_STATE_RESET:
> return "RESET";
> case MHI_STATE_READY:
> return "READY";
> case MHI_STATE_M0:
> return "M0";
> case MHI_STATE_M1:
> return "M1";
> case MHI_STATE_M2:
> return "M2";
> case MHI_STATE_M3:
> return "M3";
> case MHI_STATE_M3_FAST:
> return "M3 FAST";
> case MHI_STATE_BHI:
> return "BHI";
> case MHI_STATE_SYS_ERR:
> return "SYS ERROR";
> default:
> return "Unknown state";
> }
> };
>
> Which if this could be changed into:
>
> #define MHI_STATE_LIST \
> EM(RESET, "RESET") \
> EM(READY, "READY") \
> EM(M0, "M0") \
> EM(M1, "M1") \
> EM(M2, "M2") \
> EM(M3, "M3") \
> EM(M3_FAST, "M3_FAST") \
> EM(BHI, "BHI") \
> EMe(SYS_ERR, "SYS ERROR")
>
> #undef EM
> #undef EMe
>
> #define EM(a, b) case MHI_STATE_##a: return b;
> #define EMe(a, b) case MHI_STATE_##a: return b;
>
> static inline const char *mhi_state_str(enum mhi_state state)
> {
> switch (state) {
> MHI_STATE_LIST
> default:
> return "Unknown state";
> }
>
> Then you could use that macro in the trace header:
>
> #undef EM
> #undef EMe
>
> #define EM(a, b) TRACE_DEFINE_ENUM(MHI_STATE_##a);
> #define EMe(a, b) TRACE_DEFINE_ENUM(MHI_STATE_##a);
>
> MHI_STATE_LIST
>
> And in the print fmts:
>
> #undef EM
> #undef EMe
>
> #define EM(a, b) { MHI_STATE_##a, b },
> #define EMe(a, b) { MHI_STATE_##a, b }
>
>
> TP_printk("%s: local ee: %s state: %s device ee: %s state: %s\n",
> __get_str(name),
> TO_MHI_EXEC_STR(__entry->local_ee),
>
> __print_symbolic(__entry->state), MHI_STATE_LIST),
>
> TO_MHI_EXEC_STR(__entry->dev_ee),
>
> __print_symbolic(__entry->dev_state, MHI_STATE_LIST))
>
>
> And that will be exported to user space in the
> /sys/kernel/tracing/events/*/*/format file, as:
>
> __print_symbolic(REC->state, {
> { MHI_STATE_RESET, "RESET"},
> { MHI_STATE_READY, "READY"},
> { MHI_STATE_M0, "M0"},
> { MHI_STATE_M1, "M1"},
> { MHI_STATE_M2, "M2"},
> { MHI_STATE_M3, "M3"},
> { MHI_STATE_M3_FAST, "M3 FAST"},
> { MHI_STATE_BHI, "BHI"},
> { MHI_STATE_SYS_ERR, "SYS ERROR"} }
>
> Which libtracevent knows how to parse. Oh, it wouldn't even show the enum
> names as the TRACE_DEFINE_ENUM() above, would tell the kernel to replace
> them with their actual numeric values. That way, when trace-cmd or perf
> reads the raw data, it knows how to print it.
>
> Now what about those TO_MHI_EXEC_STR() macros? They are not the same. They are:
>
> #define TO_MHI_EXEC_STR(ee) (((ee) >= MHI_EE_MAX) ? \
> "INVALID_EE" : mhi_ee_str[ee])
>
> Where that mhi_ee_str[] is:
>
> const char * const mhi_ee_str[MHI_EE_MAX] = {
> [MHI_EE_PBL] = "PRIMARY BOOTLOADER",
> [MHI_EE_SBL] = "SECONDARY BOOTLOADER",
> [MHI_EE_AMSS] = "MISSION MODE",
> [MHI_EE_RDDM] = "RAMDUMP DOWNLOAD MODE",
> [MHI_EE_WFW] = "WLAN FIRMWARE",
> [MHI_EE_PTHRU] = "PASS THROUGH",
> [MHI_EE_EDL] = "EMERGENCY DOWNLOAD",
> [MHI_EE_FP] = "FLASH PROGRAMMER",
> [MHI_EE_DISABLE_TRANSITION] = "DISABLE",
> [MHI_EE_NOT_SUPPORTED] = "NOT SUPPORTED",
> };
>
> Which would require doing the same thing for that as well.
>
> #define MHI_EE_LIST \
> EM(PBL, "PRIMARY BOOTLOADER") \
> EM(SBL, "SECONDARY BOOTLOADER") \
> EM(AMSS, "MISSION MODE") \
> EM(RDDM, "RAMDUMP DOWNLOAD MODE")\
> EM(WFW, "WLAN FIRMWARE") \
> EM(PTHRU, "PASS THROUGH") \
> EM(EDL, "EMERGENCY DOWNLOAD") \
> EM(FP, "FLASH PROGRAMMER") \
> EM(DISABLE_TRANSITION, "DISABLE") \
> EMe(NOT_SUPPORTED, "NOT SUPPORTED")
>
> And have:
>
> #undef EM
> #undef EMe
>
> #define EM(a, b) [MHI_EE_##a] = b,
> #define EMe(a, b) [MHI_EE_##a] = b,
>
> const char * const mhi_ee_str[MHI_EE_MAX] = {
> MHI_EE_LIST
> };
>
> and so on. That way the user space parsing will know how to properly parse
> these events.
>
> Note, if you don't want to modify the other files, you can still just all
> the above to the trace.h file and it will still properly map the enums to
> the strings. That is, don't modify the mhi_ee_str(), but instead just add
> the MHI_EE_LIST macro in the trace header, and use the __print_symbolic()
> with it.
>
> I only mentioned modifying the strings to make it consistent if new strings
> are added.
>
> -- Steve

Thanks steve for the these inputs, we will try these and will update as
suggested in the next patch.

- Krishna chaitanya

>
>> +);
>> +
>> +TRACE_EVENT(mhi_tryset_pm_state,
>> +
>> + TP_PROTO(struct mhi_controller *mhi_cntrl, int pm_state),
>> +
>> + TP_ARGS(mhi_cntrl, pm_state),
>> +
>> + TP_STRUCT__entry(
>> + __string(name, mhi_cntrl->mhi_dev->name)
>> + __field(int, pm_state)
>> + ),
>> +
>> + TP_fast_assign(
>> + __assign_str(name, mhi_cntrl->mhi_dev->name);
>> + if (pm_state)
>> + pm_state = __fls(pm_state);
>> + __entry->pm_state = pm_state;
>> + ),
>> +
>> + TP_printk("%s: PM state: %s\n", __get_str(name),
>> + to_mhi_pm_state_str(__entry->pm_state))
>> +);
>> +
>> +DECLARE_EVENT_CLASS(mhi_process_event_ring,
>> +
>> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct
>> mhi_ring_element *rp), +
>> + TP_ARGS(mhi_cntrl, rp),
>> +
>> + TP_STRUCT__entry(
>> + __string(name, mhi_cntrl->mhi_dev->name)
>> + __field(__le32, dword0)
>> + __field(__le32, dword1)
>> + __field(int, state)
>> + __field(__le64, ptr)
>> + __field(void *, rp)
>> + ),
>> +
>> + TP_fast_assign(
>> + __assign_str(name, mhi_cntrl->mhi_dev->name);
>> + __entry->rp = rp;
>> + __entry->ptr = rp->ptr;
>> + __entry->dword0 = rp->dword[0];
>> + __entry->dword1 = rp->dword[1];
>> + __entry->state = MHI_TRE_GET_EV_STATE(rp);
>> + ),
>> +
>> + TP_printk("%s: Tre: 0x%p Tre buf: 0x%llx dword0: 0x%08x dword1:
>> 0x%08x state: %s\n",
>> + __get_str(name), __entry->rp, __entry->ptr,
>> __entry->dword0,
>> + __entry->dword1, mhi_state_str(__entry->state))
>> +);
>> +
>> +DEFINE_EVENT(mhi_process_event_ring, mhi_data_event,
>> +
>> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct
>> mhi_ring_element *rp), +
>> + TP_ARGS(mhi_cntrl, rp)
>> +);
>> +
>> +DEFINE_EVENT(mhi_process_event_ring, mhi_ctrl_event,
>> +
>> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct
>> mhi_ring_element *rp), +
>> + TP_ARGS(mhi_cntrl, rp)
>> +);
>> +
>> +DECLARE_EVENT_CLASS(mhi_update_channel_state,
>> +
>> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan
>> *mhi_chan, int state), +
>> + TP_ARGS(mhi_cntrl, mhi_chan, state),
>> +
>> + TP_STRUCT__entry(
>> + __string(name, mhi_cntrl->mhi_dev->name)
>> + __field(int, ch_num)
>> + __field(int, state)
>> + ),
>> +
>> + TP_fast_assign(
>> + __assign_str(name, mhi_cntrl->mhi_dev->name);
>> + __entry->ch_num = mhi_chan->chan;
>> + __entry->state = state;
>> + ),
>> +
>> + TP_printk("%s: chan%d: Updating state to: %s\n",
>> + __get_str(name), __entry->ch_num,
>> + TO_CH_STATE_TYPE_STR(__entry->state))
>> +);
>> +
>> +DEFINE_EVENT(mhi_update_channel_state, mhi_channel_command_start,
>> +
>> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan
>> *mhi_chan, int state), +
>> + TP_ARGS(mhi_cntrl, mhi_chan, state)
>> +);
>> +
>> +DEFINE_EVENT(mhi_update_channel_state, mhi_channel_command_end,
>> +
>> + TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan
>> *mhi_chan, int state), +
>> + TP_ARGS(mhi_cntrl, mhi_chan, state)
>> +);
>> +
>> +TRACE_EVENT(mhi_pm_st_transition,
>> +
>> + TP_PROTO(struct mhi_controller *mhi_cntrl, int state),
>> +
>> + TP_ARGS(mhi_cntrl, state),
>> +
>> + TP_STRUCT__entry(
>> + __string(name, mhi_cntrl->mhi_dev->name)
>> + __field(int, state)
>> + ),
>> +
>> + TP_fast_assign(
>> + __assign_str(name, mhi_cntrl->mhi_dev->name);
>> + __entry->state = state;
>> + ),
>> +
>> + TP_printk("%s: Handling state transition: %s\n", __get_str(name),
>> + TO_DEV_STATE_TRANS_STR(__entry->state))
>> +);
>> +
>> +#endif
>> +#undef TRACE_INCLUDE_PATH
>> +#define TRACE_INCLUDE_PATH ../../drivers/bus/mhi/host
>> +#undef TRACE_INCLUDE_FILE
>> +#define TRACE_INCLUDE_FILE trace
>> +
>> +#include <trace/define_trace.h>
>>
>> ---
>> base-commit: 3006adf3be79cde4d14b1800b963b82b6e5572e0
>> change-id: 20231005-ftrace_support-6869d4156139
>>
>> Best regards,

2024-01-05 05:17:48

by Baochen Qiang

[permalink] [raw]
Subject: Re: [PATCH v8] bus: mhi: host: Add tracing support



On 1/4/2024 12:47 PM, Krishna Chaitanya Chundru wrote:
> Hi Steven,
>
> Can you please review this.
>
> Thanks & Regards,
>
> Krishna Chaitanya.
>
> On 12/7/2023 10:00 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_mhi_states
>> 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
>>
>> Where ever the trace events are added, debug messages are removed.
Is there a reason why debug messages have to be removed? From the view
of MHI controller, we often need MHI logs to debug, so is it possbile to
preserve those logs?
>>
>> Signed-off-by: Krishna chaitanya chundru <[email protected]>
>> ---
>> Changes in v8:
>> - Pass the structure and derefernce the variables in TP_fast_assign as
>> suggested by steve
>> - Link to v7:
>> https://lore.kernel.org/r/[email protected]
>>
>> Changes in v7:
>> - change log format as pointed by mani.
>> - Link to v6:
>> https://lore.kernel.org/r/[email protected]
>>
>> Changes in v6:
>> - use 'rp' directly as suggested by jeffrey.
>> - Link to v5:
>> https://lore.kernel.org/r/[email protected]
>>
>> Changes in v5:
>> - Use DECLARE_EVENT_CLASS for multiple events as suggested by steve.
>> - Instead of converting to u64 to print address, use %px to print the
>> address to avoid
>> - warnings in some platforms.
>> - Link to v4:
>> https://lore.kernel.org/r/[email protected]
>>
>> Changes in v4:
>> - Fix compilation issues in previous patch which happended due to
>> rebasing.
>> - In the defconfig FTRACE config is not enabled due to that the
>> compilation issue is not
>> - seen in my workspace.
>> - Link to v3:
>> https://lore.kernel.org/r/[email protected]
>>
>> Changes in v3:
>> - move trace header file from include/trace/events to
>> drivers/bus/mhi/host/ so that
>> - we can include driver header files.
>> - Use macros directly in the trace events as suggested Jeffrey Hugo.
>> - Reorder the structure in the events as suggested by steve to avoid
>> holes in the buffer.
>> - removed the mhi_to_physical function as this can give security issues.
>> - removed macros to define strings as we can get those from driver
>> headers.
>> - Link to v2:
>> https://lore.kernel.org/r/[email protected]
>>
>> 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/[email protected]
>> ---
>>   drivers/bus/mhi/host/init.c  |   3 +
>>   drivers/bus/mhi/host/main.c  |  19 ++--
>>   drivers/bus/mhi/host/pm.c    |   7 +-
>>   drivers/bus/mhi/host/trace.h | 205
>> +++++++++++++++++++++++++++++++++++++++++++
>>   4 files changed, 221 insertions(+), 13 deletions(-)
>>
>> diff --git a/drivers/bus/mhi/host/init.c b/drivers/bus/mhi/host/init.c
>> index f78aefd2d7a3..6acb85f4c5f8 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.h"
>> +
>>   static DEFINE_IDA(mhi_controller_ida);
>>   const char * const mhi_ee_str[MHI_EE_MAX] = {
>> diff --git a/drivers/bus/mhi/host/main.c b/drivers/bus/mhi/host/main.c
>> index dcf627b36e82..189f4786403e 100644
>> --- a/drivers/bus/mhi/host/main.c
>> +++ b/drivers/bus/mhi/host/main.c
>> @@ -15,6 +15,7 @@
>>   #include <linux/skbuff.h>
>>   #include <linux/slab.h>
>>   #include "internal.h"
>> +#include "trace.h"
>>   int __must_check mhi_read_reg(struct mhi_controller *mhi_cntrl,
>>                     void __iomem *base, u32 offset, u32 *out)
>> @@ -491,11 +492,8 @@ 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_states(mhi_cntrl, 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 +830,8 @@ 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_ctrl_event(mhi_cntrl, local_rp);
>> +
>>           switch (type) {
>>           case MHI_PKT_TYPE_BW_REQ_EVENT:
>>           {
>> @@ -997,6 +997,8 @@ 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_data_event(mhi_cntrl, local_rp);
>> +
>>           chan = MHI_TRE_GET_EV_CHID(local_rp);
>>           WARN_ON(chan >= mhi_cntrl->max_chan);
>> @@ -1235,6 +1237,7 @@ 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_chan, mhi_tre);
>>       /* increment WP */
>>       mhi_add_ring_element(mhi_cntrl, tre_ring);
>>       mhi_add_ring_element(mhi_cntrl, buf_ring);
>> @@ -1327,9 +1330,7 @@ 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_channel_command_start(mhi_cntrl, mhi_chan, to_state);
>>       switch (to_state) {
>>       case MHI_CH_STATE_TYPE_RESET:
>>           write_lock_irq(&mhi_chan->lock);
>> @@ -1396,9 +1397,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_channel_command_end(mhi_cntrl, mhi_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..5a2394b5b2e1 100644
>> --- a/drivers/bus/mhi/host/pm.c
>> +++ b/drivers/bus/mhi/host/pm.c
>> @@ -15,6 +15,7 @@
>>   #include <linux/slab.h>
>>   #include <linux/wait.h>
>>   #include "internal.h"
>> +#include "trace.h"
>>   /*
>>    * Not all MHI state transitions are synchronous. Transitions like
>> Linkdown,
>> @@ -123,6 +124,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, state);
>>       mhi_cntrl->pm_state = state;
>>       return mhi_cntrl->pm_state;
>>   }
>> @@ -753,7 +755,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 +762,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, itr->state);
>>           switch (itr->state) {
>>           case DEV_ST_TRANSITION_PBL:
>> diff --git a/drivers/bus/mhi/host/trace.h b/drivers/bus/mhi/host/trace.h
>> new file mode 100644
>> index 000000000000..73c129bb91d9
>> --- /dev/null
>> +++ b/drivers/bus/mhi/host/trace.h
>> @@ -0,0 +1,205 @@
>> +/* 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>
>> +#include <linux/trace_seq.h>
>> +#include "../common.h"
>> +#include "internal.h"
>> +
>> +TRACE_EVENT(mhi_gen_tre,
>> +
>> +    TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan
>> *mhi_chan,
>> +         struct mhi_ring_element *mhi_tre),
>> +
>> +    TP_ARGS(mhi_cntrl, mhi_chan, mhi_tre),
>> +
>> +    TP_STRUCT__entry(
>> +        __string(name, mhi_cntrl->mhi_dev->name)
>> +        __field(int, ch_num)
>> +        __field(void *, wp)
>> +        __field(__le64, tre_ptr)
>> +        __field(__le32, dword0)
>> +        __field(__le32, dword1)
>> +    ),
>> +
>> +    TP_fast_assign(
>> +        __assign_str(name, mhi_cntrl->mhi_dev->name);
>> +        __entry->ch_num = mhi_chan->chan;
>> +        __entry->wp = mhi_tre;
>> +        __entry->tre_ptr = mhi_tre->ptr;
>> +        __entry->dword0 = mhi_tre->dword[0];
>> +        __entry->dword1 = mhi_tre->dword[1];
>> +    ),
>> +
>> +    TP_printk("%s: Chan: %d Tre: 0x%p Tre buf: 0x%llx dword0: 0x%08x
>> dword1: 0x%08x\n",
>> +          __get_str(name), __entry->ch_num, __entry->wp,
>> __entry->tre_ptr,
>> +          __entry->dword0, __entry->dword1)
>> +);
>> +
>> +TRACE_EVENT(mhi_intvec_states,
>> +
>> +    TP_PROTO(struct mhi_controller *mhi_cntrl, int dev_ee, int
>> dev_state),
>> +
>> +    TP_ARGS(mhi_cntrl, dev_ee, dev_state),
>> +
>> +    TP_STRUCT__entry(
>> +        __string(name, mhi_cntrl->mhi_dev->name)
>> +        __field(int, local_ee)
>> +        __field(int, state)
>> +        __field(int, dev_ee)
>> +        __field(int, dev_state)
>> +    ),
>> +
>> +    TP_fast_assign(
>> +        __assign_str(name, mhi_cntrl->mhi_dev->name);
>> +        __entry->local_ee = mhi_cntrl->ee;
>> +        __entry->state = mhi_cntrl->dev_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),
>> +          TO_MHI_EXEC_STR(__entry->local_ee),
>> +          mhi_state_str(__entry->state),
>> +          TO_MHI_EXEC_STR(__entry->dev_ee),
>> +          mhi_state_str(__entry->dev_state))
>> +);
>> +
>> +TRACE_EVENT(mhi_tryset_pm_state,
>> +
>> +    TP_PROTO(struct mhi_controller *mhi_cntrl, int pm_state),
>> +
>> +    TP_ARGS(mhi_cntrl, pm_state),
>> +
>> +    TP_STRUCT__entry(
>> +        __string(name, mhi_cntrl->mhi_dev->name)
>> +        __field(int, pm_state)
>> +    ),
>> +
>> +    TP_fast_assign(
>> +        __assign_str(name, mhi_cntrl->mhi_dev->name);
>> +        if (pm_state)
>> +            pm_state = __fls(pm_state);
>> +        __entry->pm_state = pm_state;
>> +    ),
>> +
>> +    TP_printk("%s: PM state: %s\n", __get_str(name),
>> +          to_mhi_pm_state_str(__entry->pm_state))
>> +);
>> +
>> +DECLARE_EVENT_CLASS(mhi_process_event_ring,
>> +
>> +    TP_PROTO(struct mhi_controller *mhi_cntrl, struct
>> mhi_ring_element *rp),
>> +
>> +    TP_ARGS(mhi_cntrl, rp),
>> +
>> +    TP_STRUCT__entry(
>> +        __string(name, mhi_cntrl->mhi_dev->name)
>> +        __field(__le32, dword0)
>> +        __field(__le32, dword1)
>> +        __field(int, state)
>> +        __field(__le64, ptr)
>> +        __field(void *, rp)
>> +    ),
>> +
>> +    TP_fast_assign(
>> +        __assign_str(name, mhi_cntrl->mhi_dev->name);
>> +        __entry->rp = rp;
>> +        __entry->ptr = rp->ptr;
>> +        __entry->dword0 = rp->dword[0];
>> +        __entry->dword1 = rp->dword[1];
>> +        __entry->state = MHI_TRE_GET_EV_STATE(rp);
>> +    ),
>> +
>> +    TP_printk("%s: Tre: 0x%p Tre buf: 0x%llx dword0: 0x%08x dword1:
>> 0x%08x state: %s\n",
>> +          __get_str(name), __entry->rp, __entry->ptr, __entry->dword0,
>> +          __entry->dword1, mhi_state_str(__entry->state))
>> +);
>> +
>> +DEFINE_EVENT(mhi_process_event_ring, mhi_data_event,
>> +
>> +    TP_PROTO(struct mhi_controller *mhi_cntrl, struct
>> mhi_ring_element *rp),
>> +
>> +    TP_ARGS(mhi_cntrl, rp)
>> +);
>> +
>> +DEFINE_EVENT(mhi_process_event_ring, mhi_ctrl_event,
>> +
>> +    TP_PROTO(struct mhi_controller *mhi_cntrl, struct
>> mhi_ring_element *rp),
>> +
>> +    TP_ARGS(mhi_cntrl, rp)
>> +);
>> +
>> +DECLARE_EVENT_CLASS(mhi_update_channel_state,
>> +
>> +    TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan
>> *mhi_chan, int state),
>> +
>> +    TP_ARGS(mhi_cntrl, mhi_chan, state),
>> +
>> +    TP_STRUCT__entry(
>> +        __string(name, mhi_cntrl->mhi_dev->name)
>> +        __field(int, ch_num)
>> +        __field(int, state)
>> +    ),
>> +
>> +    TP_fast_assign(
>> +        __assign_str(name, mhi_cntrl->mhi_dev->name);
>> +        __entry->ch_num = mhi_chan->chan;
>> +        __entry->state = state;
>> +    ),
>> +
>> +    TP_printk("%s: chan%d: Updating state to: %s\n",
>> +          __get_str(name), __entry->ch_num,
>> +          TO_CH_STATE_TYPE_STR(__entry->state))
>> +);
>> +
>> +DEFINE_EVENT(mhi_update_channel_state, mhi_channel_command_start,
>> +
>> +    TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan
>> *mhi_chan, int state),
>> +
>> +    TP_ARGS(mhi_cntrl, mhi_chan, state)
>> +);
>> +
>> +DEFINE_EVENT(mhi_update_channel_state, mhi_channel_command_end,
>> +
>> +    TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan
>> *mhi_chan, int state),
>> +
>> +    TP_ARGS(mhi_cntrl, mhi_chan, state)
>> +);
>> +
>> +TRACE_EVENT(mhi_pm_st_transition,
>> +
>> +    TP_PROTO(struct mhi_controller *mhi_cntrl, int state),
>> +
>> +    TP_ARGS(mhi_cntrl, state),
>> +
>> +    TP_STRUCT__entry(
>> +        __string(name, mhi_cntrl->mhi_dev->name)
>> +        __field(int, state)
>> +    ),
>> +
>> +    TP_fast_assign(
>> +        __assign_str(name, mhi_cntrl->mhi_dev->name);
>> +        __entry->state = state;
>> +    ),
>> +
>> +    TP_printk("%s: Handling state transition: %s\n", __get_str(name),
>> +          TO_DEV_STATE_TRANS_STR(__entry->state))
>> +);
>> +
>> +#endif
>> +#undef TRACE_INCLUDE_PATH
>> +#define TRACE_INCLUDE_PATH ../../drivers/bus/mhi/host
>> +#undef TRACE_INCLUDE_FILE
>> +#define TRACE_INCLUDE_FILE trace
>> +
>> +#include <trace/define_trace.h>
>>
>> ---
>> base-commit: 3006adf3be79cde4d14b1800b963b82b6e5572e0
>> change-id: 20231005-ftrace_support-6869d4156139
>>
>> Best regards,
>

Subject: Re: [PATCH v8] bus: mhi: host: Add tracing support


On 1/5/2024 10:47 AM, Baochen Qiang wrote:
>
>
> On 1/4/2024 12:47 PM, Krishna Chaitanya Chundru wrote:
>> Hi Steven,
>>
>> Can you please review this.
>>
>> Thanks & Regards,
>>
>> Krishna Chaitanya.
>>
>> On 12/7/2023 10:00 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_mhi_states
>>> 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
>>>
>>> Where ever the trace events are added, debug messages are removed.
> Is there a reason why debug messages have to be removed? From the view
> of MHI controller, we often need MHI logs to debug, so is it possbile
> to preserve those logs?

The trace is being replaced by the debug message and it would be
preferred to have one mechanism or the other, not both.

you will still see these logs in traces.

- Krishna Chaitanya.

>>>
>>> Signed-off-by: Krishna chaitanya chundru <[email protected]>
>>> ---
>>> Changes in v8:
>>> - Pass the structure and derefernce the variables in TP_fast_assign
>>> as suggested by steve
>>> - Link to v7:
>>> https://lore.kernel.org/r/[email protected]
>>>
>>> Changes in v7:
>>> - change log format as pointed by mani.
>>> - Link to v6:
>>> https://lore.kernel.org/r/[email protected]
>>>
>>> Changes in v6:
>>> - use 'rp' directly as suggested by jeffrey.
>>> - Link to v5:
>>> https://lore.kernel.org/r/[email protected]
>>>
>>> Changes in v5:
>>> - Use DECLARE_EVENT_CLASS for multiple events as suggested by steve.
>>> - Instead of converting to u64 to print address, use %px to print
>>> the address to avoid
>>> - warnings in some platforms.
>>> - Link to v4:
>>> https://lore.kernel.org/r/[email protected]
>>>
>>> Changes in v4:
>>> - Fix compilation issues in previous patch which happended due to
>>> rebasing.
>>> - In the defconfig FTRACE config is not enabled due to that the
>>> compilation issue is not
>>> - seen in my workspace.
>>> - Link to v3:
>>> https://lore.kernel.org/r/[email protected]
>>>
>>> Changes in v3:
>>> - move trace header file from include/trace/events to
>>> drivers/bus/mhi/host/ so that
>>> - we can include driver header files.
>>> - Use macros directly in the trace events as suggested Jeffrey Hugo.
>>> - Reorder the structure in the events as suggested by steve to avoid
>>> holes in the buffer.
>>> - removed the mhi_to_physical function as this can give security
>>> issues.
>>> - removed macros to define strings as we can get those from driver
>>> headers.
>>> - Link to v2:
>>> https://lore.kernel.org/r/[email protected]
>>>
>>> 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/[email protected]
>>> ---
>>>   drivers/bus/mhi/host/init.c  |   3 +
>>>   drivers/bus/mhi/host/main.c  |  19 ++--
>>>   drivers/bus/mhi/host/pm.c    |   7 +-
>>>   drivers/bus/mhi/host/trace.h | 205
>>> +++++++++++++++++++++++++++++++++++++++++++
>>>   4 files changed, 221 insertions(+), 13 deletions(-)
>>>
>>> diff --git a/drivers/bus/mhi/host/init.c b/drivers/bus/mhi/host/init.c
>>> index f78aefd2d7a3..6acb85f4c5f8 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.h"
>>> +
>>>   static DEFINE_IDA(mhi_controller_ida);
>>>   const char * const mhi_ee_str[MHI_EE_MAX] = {
>>> diff --git a/drivers/bus/mhi/host/main.c b/drivers/bus/mhi/host/main.c
>>> index dcf627b36e82..189f4786403e 100644
>>> --- a/drivers/bus/mhi/host/main.c
>>> +++ b/drivers/bus/mhi/host/main.c
>>> @@ -15,6 +15,7 @@
>>>   #include <linux/skbuff.h>
>>>   #include <linux/slab.h>
>>>   #include "internal.h"
>>> +#include "trace.h"
>>>   int __must_check mhi_read_reg(struct mhi_controller *mhi_cntrl,
>>>                     void __iomem *base, u32 offset, u32 *out)
>>> @@ -491,11 +492,8 @@ 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_states(mhi_cntrl, 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 +830,8 @@ 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_ctrl_event(mhi_cntrl, local_rp);
>>> +
>>>           switch (type) {
>>>           case MHI_PKT_TYPE_BW_REQ_EVENT:
>>>           {
>>> @@ -997,6 +997,8 @@ 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_data_event(mhi_cntrl, local_rp);
>>> +
>>>           chan = MHI_TRE_GET_EV_CHID(local_rp);
>>>           WARN_ON(chan >= mhi_cntrl->max_chan);
>>> @@ -1235,6 +1237,7 @@ 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_chan, mhi_tre);
>>>       /* increment WP */
>>>       mhi_add_ring_element(mhi_cntrl, tre_ring);
>>>       mhi_add_ring_element(mhi_cntrl, buf_ring);
>>> @@ -1327,9 +1330,7 @@ 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_channel_command_start(mhi_cntrl, mhi_chan, to_state);
>>>       switch (to_state) {
>>>       case MHI_CH_STATE_TYPE_RESET:
>>>           write_lock_irq(&mhi_chan->lock);
>>> @@ -1396,9 +1397,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_channel_command_end(mhi_cntrl, mhi_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..5a2394b5b2e1 100644
>>> --- a/drivers/bus/mhi/host/pm.c
>>> +++ b/drivers/bus/mhi/host/pm.c
>>> @@ -15,6 +15,7 @@
>>>   #include <linux/slab.h>
>>>   #include <linux/wait.h>
>>>   #include "internal.h"
>>> +#include "trace.h"
>>>   /*
>>>    * Not all MHI state transitions are synchronous. Transitions like
>>> Linkdown,
>>> @@ -123,6 +124,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, state);
>>>       mhi_cntrl->pm_state = state;
>>>       return mhi_cntrl->pm_state;
>>>   }
>>> @@ -753,7 +755,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 +762,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, itr->state);
>>>           switch (itr->state) {
>>>           case DEV_ST_TRANSITION_PBL:
>>> diff --git a/drivers/bus/mhi/host/trace.h
>>> b/drivers/bus/mhi/host/trace.h
>>> new file mode 100644
>>> index 000000000000..73c129bb91d9
>>> --- /dev/null
>>> +++ b/drivers/bus/mhi/host/trace.h
>>> @@ -0,0 +1,205 @@
>>> +/* 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>
>>> +#include <linux/trace_seq.h>
>>> +#include "../common.h"
>>> +#include "internal.h"
>>> +
>>> +TRACE_EVENT(mhi_gen_tre,
>>> +
>>> +    TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan
>>> *mhi_chan,
>>> +         struct mhi_ring_element *mhi_tre),
>>> +
>>> +    TP_ARGS(mhi_cntrl, mhi_chan, mhi_tre),
>>> +
>>> +    TP_STRUCT__entry(
>>> +        __string(name, mhi_cntrl->mhi_dev->name)
>>> +        __field(int, ch_num)
>>> +        __field(void *, wp)
>>> +        __field(__le64, tre_ptr)
>>> +        __field(__le32, dword0)
>>> +        __field(__le32, dword1)
>>> +    ),
>>> +
>>> +    TP_fast_assign(
>>> +        __assign_str(name, mhi_cntrl->mhi_dev->name);
>>> +        __entry->ch_num = mhi_chan->chan;
>>> +        __entry->wp = mhi_tre;
>>> +        __entry->tre_ptr = mhi_tre->ptr;
>>> +        __entry->dword0 = mhi_tre->dword[0];
>>> +        __entry->dword1 = mhi_tre->dword[1];
>>> +    ),
>>> +
>>> +    TP_printk("%s: Chan: %d Tre: 0x%p Tre buf: 0x%llx dword0:
>>> 0x%08x dword1: 0x%08x\n",
>>> +          __get_str(name), __entry->ch_num, __entry->wp,
>>> __entry->tre_ptr,
>>> +          __entry->dword0, __entry->dword1)
>>> +);
>>> +
>>> +TRACE_EVENT(mhi_intvec_states,
>>> +
>>> +    TP_PROTO(struct mhi_controller *mhi_cntrl, int dev_ee, int
>>> dev_state),
>>> +
>>> +    TP_ARGS(mhi_cntrl, dev_ee, dev_state),
>>> +
>>> +    TP_STRUCT__entry(
>>> +        __string(name, mhi_cntrl->mhi_dev->name)
>>> +        __field(int, local_ee)
>>> +        __field(int, state)
>>> +        __field(int, dev_ee)
>>> +        __field(int, dev_state)
>>> +    ),
>>> +
>>> +    TP_fast_assign(
>>> +        __assign_str(name, mhi_cntrl->mhi_dev->name);
>>> +        __entry->local_ee = mhi_cntrl->ee;
>>> +        __entry->state = mhi_cntrl->dev_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),
>>> +          TO_MHI_EXEC_STR(__entry->local_ee),
>>> +          mhi_state_str(__entry->state),
>>> +          TO_MHI_EXEC_STR(__entry->dev_ee),
>>> +          mhi_state_str(__entry->dev_state))
>>> +);
>>> +
>>> +TRACE_EVENT(mhi_tryset_pm_state,
>>> +
>>> +    TP_PROTO(struct mhi_controller *mhi_cntrl, int pm_state),
>>> +
>>> +    TP_ARGS(mhi_cntrl, pm_state),
>>> +
>>> +    TP_STRUCT__entry(
>>> +        __string(name, mhi_cntrl->mhi_dev->name)
>>> +        __field(int, pm_state)
>>> +    ),
>>> +
>>> +    TP_fast_assign(
>>> +        __assign_str(name, mhi_cntrl->mhi_dev->name);
>>> +        if (pm_state)
>>> +            pm_state = __fls(pm_state);
>>> +        __entry->pm_state = pm_state;
>>> +    ),
>>> +
>>> +    TP_printk("%s: PM state: %s\n", __get_str(name),
>>> +          to_mhi_pm_state_str(__entry->pm_state))
>>> +);
>>> +
>>> +DECLARE_EVENT_CLASS(mhi_process_event_ring,
>>> +
>>> +    TP_PROTO(struct mhi_controller *mhi_cntrl, struct
>>> mhi_ring_element *rp),
>>> +
>>> +    TP_ARGS(mhi_cntrl, rp),
>>> +
>>> +    TP_STRUCT__entry(
>>> +        __string(name, mhi_cntrl->mhi_dev->name)
>>> +        __field(__le32, dword0)
>>> +        __field(__le32, dword1)
>>> +        __field(int, state)
>>> +        __field(__le64, ptr)
>>> +        __field(void *, rp)
>>> +    ),
>>> +
>>> +    TP_fast_assign(
>>> +        __assign_str(name, mhi_cntrl->mhi_dev->name);
>>> +        __entry->rp = rp;
>>> +        __entry->ptr = rp->ptr;
>>> +        __entry->dword0 = rp->dword[0];
>>> +        __entry->dword1 = rp->dword[1];
>>> +        __entry->state = MHI_TRE_GET_EV_STATE(rp);
>>> +    ),
>>> +
>>> +    TP_printk("%s: Tre: 0x%p Tre buf: 0x%llx dword0: 0x%08x dword1:
>>> 0x%08x state: %s\n",
>>> +          __get_str(name), __entry->rp, __entry->ptr, __entry->dword0,
>>> +          __entry->dword1, mhi_state_str(__entry->state))
>>> +);
>>> +
>>> +DEFINE_EVENT(mhi_process_event_ring, mhi_data_event,
>>> +
>>> +    TP_PROTO(struct mhi_controller *mhi_cntrl, struct
>>> mhi_ring_element *rp),
>>> +
>>> +    TP_ARGS(mhi_cntrl, rp)
>>> +);
>>> +
>>> +DEFINE_EVENT(mhi_process_event_ring, mhi_ctrl_event,
>>> +
>>> +    TP_PROTO(struct mhi_controller *mhi_cntrl, struct
>>> mhi_ring_element *rp),
>>> +
>>> +    TP_ARGS(mhi_cntrl, rp)
>>> +);
>>> +
>>> +DECLARE_EVENT_CLASS(mhi_update_channel_state,
>>> +
>>> +    TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan
>>> *mhi_chan, int state),
>>> +
>>> +    TP_ARGS(mhi_cntrl, mhi_chan, state),
>>> +
>>> +    TP_STRUCT__entry(
>>> +        __string(name, mhi_cntrl->mhi_dev->name)
>>> +        __field(int, ch_num)
>>> +        __field(int, state)
>>> +    ),
>>> +
>>> +    TP_fast_assign(
>>> +        __assign_str(name, mhi_cntrl->mhi_dev->name);
>>> +        __entry->ch_num = mhi_chan->chan;
>>> +        __entry->state = state;
>>> +    ),
>>> +
>>> +    TP_printk("%s: chan%d: Updating state to: %s\n",
>>> +          __get_str(name), __entry->ch_num,
>>> +          TO_CH_STATE_TYPE_STR(__entry->state))
>>> +);
>>> +
>>> +DEFINE_EVENT(mhi_update_channel_state, mhi_channel_command_start,
>>> +
>>> +    TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan
>>> *mhi_chan, int state),
>>> +
>>> +    TP_ARGS(mhi_cntrl, mhi_chan, state)
>>> +);
>>> +
>>> +DEFINE_EVENT(mhi_update_channel_state, mhi_channel_command_end,
>>> +
>>> +    TP_PROTO(struct mhi_controller *mhi_cntrl, struct mhi_chan
>>> *mhi_chan, int state),
>>> +
>>> +    TP_ARGS(mhi_cntrl, mhi_chan, state)
>>> +);
>>> +
>>> +TRACE_EVENT(mhi_pm_st_transition,
>>> +
>>> +    TP_PROTO(struct mhi_controller *mhi_cntrl, int state),
>>> +
>>> +    TP_ARGS(mhi_cntrl, state),
>>> +
>>> +    TP_STRUCT__entry(
>>> +        __string(name, mhi_cntrl->mhi_dev->name)
>>> +        __field(int, state)
>>> +    ),
>>> +
>>> +    TP_fast_assign(
>>> +        __assign_str(name, mhi_cntrl->mhi_dev->name);
>>> +        __entry->state = state;
>>> +    ),
>>> +
>>> +    TP_printk("%s: Handling state transition: %s\n", __get_str(name),
>>> +          TO_DEV_STATE_TRANS_STR(__entry->state))
>>> +);
>>> +
>>> +#endif
>>> +#undef TRACE_INCLUDE_PATH
>>> +#define TRACE_INCLUDE_PATH ../../drivers/bus/mhi/host
>>> +#undef TRACE_INCLUDE_FILE
>>> +#define TRACE_INCLUDE_FILE trace
>>> +
>>> +#include <trace/define_trace.h>
>>>
>>> ---
>>> base-commit: 3006adf3be79cde4d14b1800b963b82b6e5572e0
>>> change-id: 20231005-ftrace_support-6869d4156139
>>>
>>> Best regards,
>>