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

This change adds ftrace support for following:
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

Usage:
echo 1 > /sys/kernel/debug/tracing/events/mhi_host/enable
cat /sys/kernel/debug/tracing/trace

Signed-off-by: Krishna chaitanya chundru <[email protected]>
---
MAINTAINERS | 1 +
drivers/bus/mhi/host/init.c | 3 +
drivers/bus/mhi/host/internal.h | 1 +
drivers/bus/mhi/host/main.c | 27 ++++--
drivers/bus/mhi/host/pm.c | 7 +-
include/trace/events/mhi_host.h | 207 ++++++++++++++++++++++++++++++++++++++++
6 files changed, 234 insertions(+), 12 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 <[email protected]>
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..499590437e9b 100644
--- a/drivers/bus/mhi/host/main.c
+++ b/drivers/bus/mhi/host/main.c
@@ -491,11 +491,10 @@ 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, TO_MHI_EXEC_STR(mhi_cntrl->ee),
+ mhi_state_str(mhi_cntrl->dev_state),
+ TO_MHI_EXEC_STR(ee), mhi_state_str(state));
if (state == MHI_STATE_SYS_ERR) {
dev_dbg(dev, "System error detected\n");
pm_state = mhi_tryset_pm_state(mhi_cntrl,
@@ -832,6 +831,11 @@ 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, (u64)(local_rp),
+ local_rp->ptr, local_rp->dword[0],
+ local_rp->dword[1],
+ mhi_state_str(MHI_TRE_GET_EV_STATE(local_rp)));
+
switch (type) {
case MHI_PKT_TYPE_BW_REQ_EVENT:
{
@@ -997,6 +1001,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 +1242,8 @@ 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, (u64)(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 +1336,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_CH_STATE_TYPE_STR(to_state));
switch (to_state) {
case MHI_CH_STATE_TYPE_RESET:
write_lock_irq(&mhi_chan->lock);
@@ -1396,9 +1404,8 @@ 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_CH_STATE_TYPE_STR(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..1a0ccb8ff115 100644
--- a/drivers/bus/mhi/host/pm.c
+++ b/drivers/bus/mhi/host/pm.c
@@ -123,6 +123,8 @@ 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, to_mhi_pm_state_str(state));
+
mhi_cntrl->pm_state = state;
return mhi_cntrl->pm_state;
}
@@ -761,8 +763,9 @@ 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_worker(mhi_cntrl->mhi_dev->name,
+ TO_DEV_STATE_TRANS_STR(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..bcb2f12bc1bb
--- /dev/null
+++ b/include/trace/events/mhi_host.h
@@ -0,0 +1,207 @@
+/* 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>
+
+TRACE_EVENT(mhi_gen_tre,
+
+ TP_PROTO(const char *name, int ch_num, u64 wp, u64 tre_ptr, int dword0, int 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(u64, tre_ptr)
+ __field(int, dword0)
+ __field(int, 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, const char *local_ee, const char *state, const char *dev_ee,
+ const char *dev_state),
+
+ TP_ARGS(name, local_ee, state, dev_ee, dev_state),
+
+ TP_STRUCT__entry(
+ __string(name, name)
+ __string(local_ee, local_ee)
+ __string(state, state)
+ __string(dev_ee, dev_ee)
+ __string(dev_state, dev_state)
+ ),
+
+ TP_fast_assign(
+ __assign_str(name, name);
+ __assign_str(local_ee, local_ee);
+ __assign_str(state, state);
+ __assign_str(dev_ee, dev_ee);
+ __assign_str(dev_state, dev_state);
+ ),
+
+ TP_printk("%s: local ee: %s state: %s device ee: %s state: %s\n",
+ __get_str(name), __get_str(local_ee), __get_str(state), __get_str(dev_ee),
+ __get_str(dev_state))
+);
+
+TRACE_EVENT(mhi_tryset_pm_state,
+
+ TP_PROTO(const char *name, const char *pm_state),
+
+ TP_ARGS(name, pm_state),
+
+ TP_STRUCT__entry(
+ __string(name, name)
+ __string(pm_state, pm_state)
+ ),
+
+ TP_fast_assign(
+ __assign_str(name, name);
+ __assign_str(pm_state, pm_state);
+ ),
+
+ TP_printk("%s: PM state: %s\n", __get_str(name), __get_str(pm_state))
+);
+
+TRACE_EVENT(mhi_process_data_event_ring,
+
+ TP_PROTO(const char *name, u64 ptr, int dword0, int dword1),
+
+ TP_ARGS(name, ptr, dword0, dword1),
+
+ TP_STRUCT__entry(
+ __string(name, name)
+ __field(u64, ptr)
+ __field(int, dword0)
+ __field(int, 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, u64 ptr, int dword0, int dword1, const char *state),
+
+ TP_ARGS(name, rp, ptr, dword0, dword1, state),
+
+ TP_STRUCT__entry(
+ __string(name, name)
+ __field(u64, rp)
+ __field(u64, ptr)
+ __field(int, dword0)
+ __field(int, dword1)
+ __string(state, state)
+ ),
+
+ TP_fast_assign(
+ __assign_str(name, name);
+ __entry->rp = rp;
+ __entry->ptr = ptr;
+ __entry->dword0 = dword0;
+ __entry->dword1 = dword1;
+ __assign_str(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, __get_str(state))
+);
+
+TRACE_EVENT(mhi_update_channel_state_start,
+
+ TP_PROTO(const char *name, int ch_num, const char *state),
+
+ TP_ARGS(name, ch_num, state),
+
+ TP_STRUCT__entry(
+ __string(name, name)
+ __field(int, ch_num)
+ __string(state, state)
+ ),
+
+ TP_fast_assign(
+ __assign_str(name, name);
+ __entry->ch_num = ch_num;
+ __assign_str(state, state);
+ ),
+
+ TP_printk("%s: ch%d: Updating state to: %s\n",
+ __get_str(name), __entry->ch_num, __get_str(state))
+);
+
+TRACE_EVENT(mhi_update_channel_state_end,
+
+ TP_PROTO(const char *name, int ch_num, const char *state),
+
+ TP_ARGS(name, ch_num, state),
+
+ TP_STRUCT__entry(
+ __string(name, name)
+ __field(int, ch_num)
+ __string(state, state)
+ ),
+
+ TP_fast_assign(
+ __assign_str(name, name);
+ __entry->ch_num = ch_num;
+ __assign_str(state, state);
+ ),
+
+ TP_printk("%s: ch%d: Updated state to: %s\n",
+ __get_str(name), __entry->ch_num, __get_str(state))
+);
+
+TRACE_EVENT(mhi_pm_st_worker,
+
+ TP_PROTO(const char *name, const char *state),
+
+ TP_ARGS(name, state),
+
+ TP_STRUCT__entry(
+ __string(name, name)
+ __string(state, state)
+ ),
+
+ TP_fast_assign(
+ __assign_str(name, name);
+ __assign_str(state, state);
+ ),
+
+ TP_printk("%s: Handling state transition: %s\n", __get_str(name), __get_str(state))
+);
+
+#endif
+#include <trace/define_trace.h>

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

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


2023-10-05 17:14:33

by kernel test robot

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

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/20231005-231430
base: 3006adf3be79cde4d14b1800b963b82b6e5572e0
patch link: https://lore.kernel.org/r/20231005-ftrace_support-v1-1-23a2f394fa49%40quicinc.com
patch subject: [PATCH] bus: mhi: host: Add tracing support
config: m68k-allyesconfig (https://download.01.org/0day-ci/archive/20231006/[email protected]/config)
compiler: m68k-linux-gcc (GCC) 13.2.0
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20231006/[email protected]/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 <[email protected]>
| Closes: https://lore.kernel.org/oe-kbuild-all/[email protected]/

All warnings (new ones prefixed by >>):

drivers/bus/mhi/host/main.c: In function 'mhi_process_ctrl_ev_ring':
>> drivers/bus/mhi/host/main.c:834:74: warning: cast from pointer to integer of different size [-Wpointer-to-int-cast]
834 | trace_mhi_process_ctrl_ev_ring(mhi_cntrl->mhi_dev->name, (u64)(local_rp),
| ^
drivers/bus/mhi/host/main.c: In function 'mhi_gen_tre':
drivers/bus/mhi/host/main.c:1245:69: warning: cast from pointer to integer of different size [-Wpointer-to-int-cast]
1245 | trace_mhi_gen_tre(mhi_cntrl->mhi_dev->name, mhi_chan->chan, (u64)(mhi_tre),
| ^
--
drivers/bus/mhi/host/pm.c: In function 'mhi_pm_st_worker':
>> drivers/bus/mhi/host/pm.c:758:24: warning: unused variable 'dev' [-Wunused-variable]
758 | struct device *dev = &mhi_cntrl->mhi_dev->dev;
| ^~~


vim +834 drivers/bus/mhi/host/main.c

799
800 int mhi_process_ctrl_ev_ring(struct mhi_controller *mhi_cntrl,
801 struct mhi_event *mhi_event,
802 u32 event_quota)
803 {
804 struct mhi_ring_element *dev_rp, *local_rp;
805 struct mhi_ring *ev_ring = &mhi_event->ring;
806 struct mhi_event_ctxt *er_ctxt =
807 &mhi_cntrl->mhi_ctxt->er_ctxt[mhi_event->er_index];
808 struct mhi_chan *mhi_chan;
809 struct device *dev = &mhi_cntrl->mhi_dev->dev;
810 u32 chan;
811 int count = 0;
812 dma_addr_t ptr = le64_to_cpu(er_ctxt->rp);
813
814 /*
815 * This is a quick check to avoid unnecessary event processing
816 * in case MHI is already in error state, but it's still possible
817 * to transition to error state while processing events
818 */
819 if (unlikely(MHI_EVENT_ACCESS_INVALID(mhi_cntrl->pm_state)))
820 return -EIO;
821
822 if (!is_valid_ring_ptr(ev_ring, ptr)) {
823 dev_err(&mhi_cntrl->mhi_dev->dev,
824 "Event ring rp points outside of the event ring\n");
825 return -EIO;
826 }
827
828 dev_rp = mhi_to_virtual(ev_ring, ptr);
829 local_rp = ev_ring->rp;
830
831 while (dev_rp != local_rp) {
832 enum mhi_pkt_type type = MHI_TRE_GET_EV_TYPE(local_rp);
833
> 834 trace_mhi_process_ctrl_ev_ring(mhi_cntrl->mhi_dev->name, (u64)(local_rp),
835 local_rp->ptr, local_rp->dword[0],
836 local_rp->dword[1],
837 mhi_state_str(MHI_TRE_GET_EV_STATE(local_rp)));
838
839 switch (type) {
840 case MHI_PKT_TYPE_BW_REQ_EVENT:
841 {
842 struct mhi_link_info *link_info;
843
844 link_info = &mhi_cntrl->mhi_link_info;
845 write_lock_irq(&mhi_cntrl->pm_lock);
846 link_info->target_link_speed =
847 MHI_TRE_GET_EV_LINKSPEED(local_rp);
848 link_info->target_link_width =
849 MHI_TRE_GET_EV_LINKWIDTH(local_rp);
850 write_unlock_irq(&mhi_cntrl->pm_lock);
851 dev_dbg(dev, "Received BW_REQ event\n");
852 mhi_cntrl->status_cb(mhi_cntrl, MHI_CB_BW_REQ);
853 break;
854 }
855 case MHI_PKT_TYPE_STATE_CHANGE_EVENT:
856 {
857 enum mhi_state new_state;
858
859 new_state = MHI_TRE_GET_EV_STATE(local_rp);
860
861 dev_dbg(dev, "State change event to state: %s\n",
862 mhi_state_str(new_state));
863
864 switch (new_state) {
865 case MHI_STATE_M0:
866 mhi_pm_m0_transition(mhi_cntrl);
867 break;
868 case MHI_STATE_M1:
869 mhi_pm_m1_transition(mhi_cntrl);
870 break;
871 case MHI_STATE_M3:
872 mhi_pm_m3_transition(mhi_cntrl);
873 break;
874 case MHI_STATE_SYS_ERR:
875 {
876 enum mhi_pm_state pm_state;
877
878 dev_dbg(dev, "System error detected\n");
879 write_lock_irq(&mhi_cntrl->pm_lock);
880 pm_state = mhi_tryset_pm_state(mhi_cntrl,
881 MHI_PM_SYS_ERR_DETECT);
882 write_unlock_irq(&mhi_cntrl->pm_lock);
883 if (pm_state == MHI_PM_SYS_ERR_DETECT)
884 mhi_pm_sys_err_handler(mhi_cntrl);
885 break;
886 }
887 default:
888 dev_err(dev, "Invalid state: %s\n",
889 mhi_state_str(new_state));
890 }
891
892 break;
893 }
894 case MHI_PKT_TYPE_CMD_COMPLETION_EVENT:
895 mhi_process_cmd_completion(mhi_cntrl, local_rp);
896 break;
897 case MHI_PKT_TYPE_EE_EVENT:
898 {
899 enum dev_st_transition st = DEV_ST_TRANSITION_MAX;
900 enum mhi_ee_type event = MHI_TRE_GET_EV_EXECENV(local_rp);
901
902 dev_dbg(dev, "Received EE event: %s\n",
903 TO_MHI_EXEC_STR(event));
904 switch (event) {
905 case MHI_EE_SBL:
906 st = DEV_ST_TRANSITION_SBL;
907 break;
908 case MHI_EE_WFW:
909 case MHI_EE_AMSS:
910 st = DEV_ST_TRANSITION_MISSION_MODE;
911 break;
912 case MHI_EE_FP:
913 st = DEV_ST_TRANSITION_FP;
914 break;
915 case MHI_EE_RDDM:
916 mhi_cntrl->status_cb(mhi_cntrl, MHI_CB_EE_RDDM);
917 write_lock_irq(&mhi_cntrl->pm_lock);
918 mhi_cntrl->ee = event;
919 write_unlock_irq(&mhi_cntrl->pm_lock);
920 wake_up_all(&mhi_cntrl->state_event);
921 break;
922 default:
923 dev_err(dev,
924 "Unhandled EE event: 0x%x\n", type);
925 }
926 if (st != DEV_ST_TRANSITION_MAX)
927 mhi_queue_state_transition(mhi_cntrl, st);
928
929 break;
930 }
931 case MHI_PKT_TYPE_TX_EVENT:
932 chan = MHI_TRE_GET_EV_CHID(local_rp);
933
934 WARN_ON(chan >= mhi_cntrl->max_chan);
935
936 /*
937 * Only process the event ring elements whose channel
938 * ID is within the maximum supported range.
939 */
940 if (chan < mhi_cntrl->max_chan) {
941 mhi_chan = &mhi_cntrl->mhi_chan[chan];
942 if (!mhi_chan->configured)
943 break;
944 parse_xfer_event(mhi_cntrl, local_rp, mhi_chan);
945 }
946 break;
947 default:
948 dev_err(dev, "Unhandled event type: %d\n", type);
949 break;
950 }
951
952 mhi_recycle_ev_ring_element(mhi_cntrl, ev_ring);
953 local_rp = ev_ring->rp;
954
955 ptr = le64_to_cpu(er_ctxt->rp);
956 if (!is_valid_ring_ptr(ev_ring, ptr)) {
957 dev_err(&mhi_cntrl->mhi_dev->dev,
958 "Event ring rp points outside of the event ring\n");
959 return -EIO;
960 }
961
962 dev_rp = mhi_to_virtual(ev_ring, ptr);
963 count++;
964 }
965
966 read_lock_bh(&mhi_cntrl->pm_lock);
967
968 /* Ring EV DB only if there is any pending element to process */
969 if (likely(MHI_DB_ACCESS_VALID(mhi_cntrl)) && count)
970 mhi_ring_er_db(mhi_event);
971 read_unlock_bh(&mhi_cntrl->pm_lock);
972
973 return count;
974 }
975

--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

2023-10-05 22:41:15

by Bjorn Andersson

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

On Thu, Oct 05, 2023 at 03:55:20PM +0530, Krishna chaitanya chundru wrote:
> This change adds ftrace support for following:
> 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

This is not the best "problem description".

>
> Usage:
> echo 1 > /sys/kernel/debug/tracing/events/mhi_host/enable
> cat /sys/kernel/debug/tracing/trace

This does not need to be included in the commit message, how to use the
tracing framework is documented elsewhere.

[..]
> diff --git a/drivers/bus/mhi/host/main.c b/drivers/bus/mhi/host/main.c
> index dcf627b36e82..499590437e9b 100644
> --- a/drivers/bus/mhi/host/main.c
> +++ b/drivers/bus/mhi/host/main.c
> @@ -491,11 +491,10 @@ 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, TO_MHI_EXEC_STR(mhi_cntrl->ee),
> + mhi_state_str(mhi_cntrl->dev_state),
> + TO_MHI_EXEC_STR(ee), mhi_state_str(state));

All these helper functions that translates a state to a string, pass the
raw state into the trace event and use __print_symbolic() in your
TP_printk() instead.

This will allow you to read the state, but you can have tools act of the
numerical value.


(This comment applies to all the trace events)

> if (state == MHI_STATE_SYS_ERR) {
> dev_dbg(dev, "System error detected\n");
> pm_state = mhi_tryset_pm_state(mhi_cntrl,
[..]
> diff --git a/include/trace/events/mhi_host.h b/include/trace/events/mhi_host.h
[..]
> +
> +TRACE_EVENT(mhi_pm_st_worker,

Why is this trace event called "worker", isn't the event a
"mhi_pm_state_transition"?

Don't just name your trace event based on the function that triggers
them, but what they represent and make sure they carry useful
information to understand the system.

If you want to trace the flow through your functions, you can use e.g.
ftrace.

Regards,
Bjorn

2023-10-10 15:44:25

by kernel test robot

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

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/20231005-231430
base: 3006adf3be79cde4d14b1800b963b82b6e5572e0
patch link: https://lore.kernel.org/r/20231005-ftrace_support-v1-1-23a2f394fa49%40quicinc.com
patch subject: [PATCH] bus: mhi: host: Add tracing support
config: i386-randconfig-062-20231010 (https://download.01.org/0day-ci/archive/20231010/[email protected]/config)
compiler: gcc-9 (Debian 9.3.0-22) 9.3.0
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20231010/[email protected]/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 <[email protected]>
| Closes: https://lore.kernel.org/oe-kbuild-all/[email protected]/

sparse warnings: (new ones prefixed by >>)
>> drivers/bus/mhi/host/main.c:835:56: sparse: sparse: incorrect type in argument 3 (different base types) @@ expected unsigned long long [usertype] ptr @@ got restricted __le64 [usertype] ptr @@
drivers/bus/mhi/host/main.c:835:56: sparse: expected unsigned long long [usertype] ptr
drivers/bus/mhi/host/main.c:835:56: sparse: got restricted __le64 [usertype] ptr
>> drivers/bus/mhi/host/main.c:835:78: sparse: sparse: incorrect type in argument 4 (different base types) @@ expected int dword0 @@ got restricted __le32 @@
drivers/bus/mhi/host/main.c:835:78: sparse: expected int dword0
drivers/bus/mhi/host/main.c:835:78: sparse: got restricted __le32
>> drivers/bus/mhi/host/main.c:836:63: sparse: sparse: incorrect type in argument 5 (different base types) @@ expected int dword1 @@ got restricted __le32 @@
drivers/bus/mhi/host/main.c:836:63: sparse: expected int dword1
drivers/bus/mhi/host/main.c:836:63: sparse: got restricted __le32
drivers/bus/mhi/host/main.c:1004:85: sparse: sparse: incorrect type in argument 2 (different base types) @@ expected unsigned long long [usertype] ptr @@ got restricted __le64 [usertype] ptr @@
drivers/bus/mhi/host/main.c:1004:85: sparse: expected unsigned long long [usertype] ptr
drivers/bus/mhi/host/main.c:1004:85: sparse: got restricted __le64 [usertype] ptr
drivers/bus/mhi/host/main.c:1005:66: sparse: sparse: incorrect type in argument 3 (different base types) @@ expected int dword0 @@ got restricted __le32 @@
drivers/bus/mhi/host/main.c:1005:66: sparse: expected int dword0
drivers/bus/mhi/host/main.c:1005:66: sparse: got restricted __le32
drivers/bus/mhi/host/main.c:1005:86: sparse: sparse: incorrect type in argument 4 (different base types) @@ expected int dword1 @@ got restricted __le32 @@
drivers/bus/mhi/host/main.c:1005:86: sparse: expected int dword1
drivers/bus/mhi/host/main.c:1005:86: sparse: got restricted __le32
>> drivers/bus/mhi/host/main.c:1246:34: sparse: sparse: incorrect type in argument 4 (different base types) @@ expected unsigned long long [usertype] tre_ptr @@ got restricted __le64 [usertype] ptr @@
drivers/bus/mhi/host/main.c:1246:34: sparse: expected unsigned long long [usertype] tre_ptr
drivers/bus/mhi/host/main.c:1246:34: sparse: got restricted __le64 [usertype] ptr
drivers/bus/mhi/host/main.c:1246:55: sparse: sparse: incorrect type in argument 5 (different base types) @@ expected int dword0 @@ got restricted __le32 @@
drivers/bus/mhi/host/main.c:1246:55: sparse: expected int dword0
drivers/bus/mhi/host/main.c:1246:55: sparse: got restricted __le32
drivers/bus/mhi/host/main.c:1246:74: sparse: sparse: incorrect type in argument 6 (different base types) @@ expected int dword1 @@ got restricted __le32 @@
drivers/bus/mhi/host/main.c:1246:74: sparse: expected int dword1
drivers/bus/mhi/host/main.c:1246:74: sparse: got restricted __le32
>> drivers/bus/mhi/host/main.c:834:80: sparse: sparse: non size-preserving pointer to integer cast
drivers/bus/mhi/host/main.c:1245:75: sparse: sparse: non size-preserving pointer to integer cast

vim +835 drivers/bus/mhi/host/main.c

799
800 int mhi_process_ctrl_ev_ring(struct mhi_controller *mhi_cntrl,
801 struct mhi_event *mhi_event,
802 u32 event_quota)
803 {
804 struct mhi_ring_element *dev_rp, *local_rp;
805 struct mhi_ring *ev_ring = &mhi_event->ring;
806 struct mhi_event_ctxt *er_ctxt =
807 &mhi_cntrl->mhi_ctxt->er_ctxt[mhi_event->er_index];
808 struct mhi_chan *mhi_chan;
809 struct device *dev = &mhi_cntrl->mhi_dev->dev;
810 u32 chan;
811 int count = 0;
812 dma_addr_t ptr = le64_to_cpu(er_ctxt->rp);
813
814 /*
815 * This is a quick check to avoid unnecessary event processing
816 * in case MHI is already in error state, but it's still possible
817 * to transition to error state while processing events
818 */
819 if (unlikely(MHI_EVENT_ACCESS_INVALID(mhi_cntrl->pm_state)))
820 return -EIO;
821
822 if (!is_valid_ring_ptr(ev_ring, ptr)) {
823 dev_err(&mhi_cntrl->mhi_dev->dev,
824 "Event ring rp points outside of the event ring\n");
825 return -EIO;
826 }
827
828 dev_rp = mhi_to_virtual(ev_ring, ptr);
829 local_rp = ev_ring->rp;
830
831 while (dev_rp != local_rp) {
832 enum mhi_pkt_type type = MHI_TRE_GET_EV_TYPE(local_rp);
833
> 834 trace_mhi_process_ctrl_ev_ring(mhi_cntrl->mhi_dev->name, (u64)(local_rp),
> 835 local_rp->ptr, local_rp->dword[0],
> 836 local_rp->dword[1],
837 mhi_state_str(MHI_TRE_GET_EV_STATE(local_rp)));
838
839 switch (type) {
840 case MHI_PKT_TYPE_BW_REQ_EVENT:
841 {
842 struct mhi_link_info *link_info;
843
844 link_info = &mhi_cntrl->mhi_link_info;
845 write_lock_irq(&mhi_cntrl->pm_lock);
846 link_info->target_link_speed =
847 MHI_TRE_GET_EV_LINKSPEED(local_rp);
848 link_info->target_link_width =
849 MHI_TRE_GET_EV_LINKWIDTH(local_rp);
850 write_unlock_irq(&mhi_cntrl->pm_lock);
851 dev_dbg(dev, "Received BW_REQ event\n");
852 mhi_cntrl->status_cb(mhi_cntrl, MHI_CB_BW_REQ);
853 break;
854 }
855 case MHI_PKT_TYPE_STATE_CHANGE_EVENT:
856 {
857 enum mhi_state new_state;
858
859 new_state = MHI_TRE_GET_EV_STATE(local_rp);
860
861 dev_dbg(dev, "State change event to state: %s\n",
862 mhi_state_str(new_state));
863
864 switch (new_state) {
865 case MHI_STATE_M0:
866 mhi_pm_m0_transition(mhi_cntrl);
867 break;
868 case MHI_STATE_M1:
869 mhi_pm_m1_transition(mhi_cntrl);
870 break;
871 case MHI_STATE_M3:
872 mhi_pm_m3_transition(mhi_cntrl);
873 break;
874 case MHI_STATE_SYS_ERR:
875 {
876 enum mhi_pm_state pm_state;
877
878 dev_dbg(dev, "System error detected\n");
879 write_lock_irq(&mhi_cntrl->pm_lock);
880 pm_state = mhi_tryset_pm_state(mhi_cntrl,
881 MHI_PM_SYS_ERR_DETECT);
882 write_unlock_irq(&mhi_cntrl->pm_lock);
883 if (pm_state == MHI_PM_SYS_ERR_DETECT)
884 mhi_pm_sys_err_handler(mhi_cntrl);
885 break;
886 }
887 default:
888 dev_err(dev, "Invalid state: %s\n",
889 mhi_state_str(new_state));
890 }
891
892 break;
893 }
894 case MHI_PKT_TYPE_CMD_COMPLETION_EVENT:
895 mhi_process_cmd_completion(mhi_cntrl, local_rp);
896 break;
897 case MHI_PKT_TYPE_EE_EVENT:
898 {
899 enum dev_st_transition st = DEV_ST_TRANSITION_MAX;
900 enum mhi_ee_type event = MHI_TRE_GET_EV_EXECENV(local_rp);
901
902 dev_dbg(dev, "Received EE event: %s\n",
903 TO_MHI_EXEC_STR(event));
904 switch (event) {
905 case MHI_EE_SBL:
906 st = DEV_ST_TRANSITION_SBL;
907 break;
908 case MHI_EE_WFW:
909 case MHI_EE_AMSS:
910 st = DEV_ST_TRANSITION_MISSION_MODE;
911 break;
912 case MHI_EE_FP:
913 st = DEV_ST_TRANSITION_FP;
914 break;
915 case MHI_EE_RDDM:
916 mhi_cntrl->status_cb(mhi_cntrl, MHI_CB_EE_RDDM);
917 write_lock_irq(&mhi_cntrl->pm_lock);
918 mhi_cntrl->ee = event;
919 write_unlock_irq(&mhi_cntrl->pm_lock);
920 wake_up_all(&mhi_cntrl->state_event);
921 break;
922 default:
923 dev_err(dev,
924 "Unhandled EE event: 0x%x\n", type);
925 }
926 if (st != DEV_ST_TRANSITION_MAX)
927 mhi_queue_state_transition(mhi_cntrl, st);
928
929 break;
930 }
931 case MHI_PKT_TYPE_TX_EVENT:
932 chan = MHI_TRE_GET_EV_CHID(local_rp);
933
934 WARN_ON(chan >= mhi_cntrl->max_chan);
935
936 /*
937 * Only process the event ring elements whose channel
938 * ID is within the maximum supported range.
939 */
940 if (chan < mhi_cntrl->max_chan) {
941 mhi_chan = &mhi_cntrl->mhi_chan[chan];
942 if (!mhi_chan->configured)
943 break;
944 parse_xfer_event(mhi_cntrl, local_rp, mhi_chan);
945 }
946 break;
947 default:
948 dev_err(dev, "Unhandled event type: %d\n", type);
949 break;
950 }
951
952 mhi_recycle_ev_ring_element(mhi_cntrl, ev_ring);
953 local_rp = ev_ring->rp;
954
955 ptr = le64_to_cpu(er_ctxt->rp);
956 if (!is_valid_ring_ptr(ev_ring, ptr)) {
957 dev_err(&mhi_cntrl->mhi_dev->dev,
958 "Event ring rp points outside of the event ring\n");
959 return -EIO;
960 }
961
962 dev_rp = mhi_to_virtual(ev_ring, ptr);
963 count++;
964 }
965
966 read_lock_bh(&mhi_cntrl->pm_lock);
967
968 /* Ring EV DB only if there is any pending element to process */
969 if (likely(MHI_DB_ACCESS_VALID(mhi_cntrl)) && count)
970 mhi_ring_er_db(mhi_event);
971 read_unlock_bh(&mhi_cntrl->pm_lock);
972
973 return count;
974 }
975

--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

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


On 10/6/2023 4:10 AM, Bjorn Andersson wrote:
> On Thu, Oct 05, 2023 at 03:55:20PM +0530, Krishna chaitanya chundru wrote:
>> This change adds ftrace support for following:
>> 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
> This is not the best "problem description".
>
>> Usage:
>> echo 1 > /sys/kernel/debug/tracing/events/mhi_host/enable
>> cat /sys/kernel/debug/tracing/trace
> This does not need to be included in the commit message, how to use the
> tracing framework is documented elsewhere.
Removed this now.
> [..]
>> diff --git a/drivers/bus/mhi/host/main.c b/drivers/bus/mhi/host/main.c
>> index dcf627b36e82..499590437e9b 100644
>> --- a/drivers/bus/mhi/host/main.c
>> +++ b/drivers/bus/mhi/host/main.c
>> @@ -491,11 +491,10 @@ 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, TO_MHI_EXEC_STR(mhi_cntrl->ee),
>> + mhi_state_str(mhi_cntrl->dev_state),
>> + TO_MHI_EXEC_STR(ee), mhi_state_str(state));
> All these helper functions that translates a state to a string, pass the
> raw state into the trace event and use __print_symbolic() in your
> TP_printk() instead.
>
> This will allow you to read the state, but you can have tools act of the
> numerical value.
>
>
> (This comment applies to all the trace events)
changed the events as you suggested.
>> if (state == MHI_STATE_SYS_ERR) {
>> dev_dbg(dev, "System error detected\n");
>> pm_state = mhi_tryset_pm_state(mhi_cntrl,
> [..]
>> diff --git a/include/trace/events/mhi_host.h b/include/trace/events/mhi_host.h
> [..]
>> +
>> +TRACE_EVENT(mhi_pm_st_worker,
> Why is this trace event called "worker", isn't the event a
> "mhi_pm_state_transition"?
>
> Don't just name your trace event based on the function that triggers
> them, but what they represent and make sure they carry useful
> information to understand the system.
>
> If you want to trace the flow through your functions, you can use e.g.
> ftrace.
>
> Regards,
> Bjorn

Changed as you suggested.

- KC