diff --git a/asoc/codecs/audio-ext-clk-up.c b/asoc/codecs/audio-ext-clk-up.c index c2c3074daa..d724850053 100644 --- a/asoc/codecs/audio-ext-clk-up.c +++ b/asoc/codecs/audio-ext-clk-up.c @@ -71,6 +71,8 @@ static int audio_ext_clk_prepare(struct clk_hw *hw) if ((clk_priv->clk_src >= AUDIO_EXT_CLK_LPASS) && (clk_priv->clk_src < AUDIO_EXT_CLK_LPASS_MAX)) { clk_priv->clk_cfg.enable = 1; + trace_printk("%s: vote for %d clock\n", + __func__, clk_priv->clk_src); ret = afe_set_lpass_clk_cfg(IDX_RSVD_3, &clk_priv->clk_cfg); if (ret < 0) { pr_err_ratelimited("%s afe_set_digital_codec_core_clock failed\n", @@ -113,6 +115,8 @@ static void audio_ext_clk_unprepare(struct clk_hw *hw) if ((clk_priv->clk_src >= AUDIO_EXT_CLK_LPASS) && (clk_priv->clk_src < AUDIO_EXT_CLK_LPASS_MAX)) { clk_priv->clk_cfg.enable = 0; + trace_printk("%s: unvote for %d clock\n", + __func__, clk_priv->clk_src); ret = afe_set_lpass_clk_cfg(IDX_RSVD_3, &clk_priv->clk_cfg); if (ret < 0) pr_err_ratelimited("%s: afe_set_lpass_clk_cfg failed, ret = %d\n", @@ -147,6 +151,8 @@ static int lpass_hw_vote_prepare(struct clk_hw *hw) int ret; if (clk_priv->clk_src == AUDIO_EXT_CLK_LPASS_CORE_HW_VOTE) { + trace_printk("%s: vote for %d clock\n", + __func__, clk_priv->clk_src); ret = afe_vote_lpass_core_hw(AFE_LPASS_CORE_HW_MACRO_BLOCK, "LPASS_HW_MACRO", &clk_priv->lpass_core_hwvote_client_handle); @@ -158,6 +164,8 @@ static int lpass_hw_vote_prepare(struct clk_hw *hw) } if (clk_priv->clk_src == AUDIO_EXT_CLK_LPASS_AUDIO_HW_VOTE) { + trace_printk("%s: vote for %d clock\n", + __func__, clk_priv->clk_src); ret = afe_vote_lpass_core_hw(AFE_LPASS_CORE_HW_DCODEC_BLOCK, "LPASS_HW_DCODEC", &clk_priv->lpass_audio_hwvote_client_handle); @@ -177,6 +185,8 @@ static void lpass_hw_vote_unprepare(struct clk_hw *hw) int ret = 0; if (clk_priv->clk_src == AUDIO_EXT_CLK_LPASS_CORE_HW_VOTE) { + trace_printk("%s: unvote for %d clock\n", + __func__, clk_priv->clk_src); ret = afe_unvote_lpass_core_hw( AFE_LPASS_CORE_HW_MACRO_BLOCK, clk_priv->lpass_core_hwvote_client_handle); @@ -187,6 +197,8 @@ static void lpass_hw_vote_unprepare(struct clk_hw *hw) } if (clk_priv->clk_src == AUDIO_EXT_CLK_LPASS_AUDIO_HW_VOTE) { + trace_printk("%s: unvote for %d clock\n", + __func__, clk_priv->clk_src); ret = afe_unvote_lpass_core_hw( AFE_LPASS_CORE_HW_DCODEC_BLOCK, clk_priv->lpass_audio_hwvote_client_handle); diff --git a/asoc/codecs/bolero/bolero-cdc.c b/asoc/codecs/bolero/bolero-cdc.c index 37120f7e84..ec2a304034 100644 --- a/asoc/codecs/bolero/bolero-cdc.c +++ b/asoc/codecs/bolero/bolero-cdc.c @@ -834,6 +834,7 @@ static int bolero_ssr_enable(struct device *dev, void *data) priv->component, BOLERO_MACRO_EVT_CLK_RESET, 0x0); } + trace_printk("%s: clk count reset\n", __func__); regcache_cache_only(priv->regmap, false); mutex_lock(&priv->clk_lock); priv->dev_up = true; @@ -844,6 +845,7 @@ static int bolero_ssr_enable(struct device *dev, void *data) /* Add a 100usec sleep to ensure last register write is done */ usleep_range(100,110); bolero_clk_rsc_enable_all_clocks(priv->clk_dev, false); + trace_printk("%s: regcache_sync done\n", __func__); /* call ssr event for supported macros */ for (macro_idx = START_MACRO; macro_idx < MAX_MACRO; macro_idx++) { if (!priv->macro_params[macro_idx].event_handler) @@ -852,6 +854,7 @@ static int bolero_ssr_enable(struct device *dev, void *data) priv->component, BOLERO_MACRO_EVT_SSR_UP, 0x0); } + trace_printk("%s: SSR up events processed by all macros\n", __func__); bolero_cdc_notifier_call(priv, BOLERO_WCD_EVT_SSR_UP); return 0; } @@ -1393,6 +1396,8 @@ int bolero_runtime_resume(struct device *dev) } } priv->core_hw_vote_count++; + trace_printk("%s: hw vote count %d\n", + __func__, priv->core_hw_vote_count); audio_vote: if (priv->lpass_audio_hw_vote == NULL) { @@ -1409,6 +1414,8 @@ audio_vote: } } priv->core_audio_vote_count++; + trace_printk("%s: audio vote count %d\n", + __func__, priv->core_audio_vote_count); done: mutex_unlock(&priv->vote_lock); @@ -1431,6 +1438,8 @@ int bolero_runtime_suspend(struct device *dev) dev_dbg(dev, "%s: Invalid lpass core hw node\n", __func__); } + trace_printk("%s: hw vote count %d\n", + __func__, priv->core_hw_vote_count); if (priv->lpass_audio_hw_vote != NULL) { if (--priv->core_audio_vote_count == 0) @@ -1441,6 +1450,8 @@ int bolero_runtime_suspend(struct device *dev) dev_dbg(dev, "%s: Invalid lpass audio hw node\n", __func__); } + trace_printk("%s: audio vote count %d\n", + __func__, priv->core_audio_vote_count); mutex_unlock(&priv->vote_lock); return 0; diff --git a/asoc/codecs/bolero/bolero-clk-rsc.c b/asoc/codecs/bolero/bolero-clk-rsc.c index 13cc98840a..7e28c5bfeb 100644 --- a/asoc/codecs/bolero/bolero-clk-rsc.c +++ b/asoc/codecs/bolero/bolero-clk-rsc.c @@ -129,6 +129,8 @@ int bolero_rsc_clk_reset(struct device *dev, int clk_id) } dev_dbg(priv->dev, "%s: clock reset after ssr, count %d\n", __func__, count); + + trace_printk("%s: clock reset after ssr, count %d\n", __func__, count); while (count--) { clk_prepare_enable(priv->clk[clk_id]); clk_prepare_enable(priv->clk[clk_id + NPL_CLK_OFFSET]); @@ -238,6 +240,7 @@ static int bolero_clk_rsc_mux1_clk_request(struct bolero_clk_rsc *priv, char __iomem *clk_muxsel = NULL; int ret = 0; int default_clk_id = priv->default_clk_id[clk_id]; + u32 muxsel = 0; clk_muxsel = bolero_clk_rsc_get_clk_muxsel(priv, clk_id); if (!clk_muxsel) { @@ -280,6 +283,9 @@ static int bolero_clk_rsc_mux1_clk_request(struct bolero_clk_rsc *priv, */ if (clk_id != VA_CORE_CLK) { iowrite32(0x1, clk_muxsel); + muxsel = ioread32(clk_muxsel); + trace_printk("%s: muxsel value after enable: %d\n", + __func__, muxsel); bolero_clk_rsc_mux0_clk_request(priv, default_clk_id, false); @@ -308,6 +314,9 @@ static int bolero_clk_rsc_mux1_clk_request(struct bolero_clk_rsc *priv, * care in DSP itself. */ iowrite32(0x0, clk_muxsel); + muxsel = ioread32(clk_muxsel); + trace_printk("%s: muxsel value after disable: %d\n", + __func__, muxsel); } } if (priv->clk[clk_id + NPL_CLK_OFFSET]) @@ -529,6 +538,7 @@ int bolero_clk_rsc_request_clock(struct device *dev, if (!priv->dev_up && enable) { dev_err_ratelimited(priv->dev, "%s: SSR is in progress..\n", __func__); + trace_printk("%s: SSR is in progress..\n", __func__); ret = -EINVAL; goto err; } @@ -558,6 +568,9 @@ int bolero_clk_rsc_request_clock(struct device *dev, dev_dbg(priv->dev, "%s: clk_cnt: %d for requested clk: %d, enable: %d\n", __func__, priv->clk_cnt[clk_id_req], clk_id_req, enable); + trace_printk("%s: clk_cnt: %d for requested clk: %d, enable: %d\n", + __func__, priv->clk_cnt[clk_id_req], clk_id_req, + enable); mutex_unlock(&priv->rsc_clk_lock); diff --git a/asoc/codecs/bolero/rx-macro.c b/asoc/codecs/bolero/rx-macro.c index ccb560ac1c..45b9009210 100644 --- a/asoc/codecs/bolero/rx-macro.c +++ b/asoc/codecs/bolero/rx-macro.c @@ -1299,6 +1299,8 @@ static int rx_macro_mclk_enable(struct rx_macro_priv *rx_priv, } } exit: + trace_printk("%s: mclk_enable = %u, dapm = %d clk_users= %d\n", + __func__, mclk_enable, dapm, rx_priv->rx_mclk_users); mutex_unlock(&rx_priv->mclk_lock); return ret; } @@ -1384,6 +1386,7 @@ static int rx_macro_event_handler(struct snd_soc_component *component, rx_macro_wcd_clsh_imped_config(component, data, false); break; case BOLERO_MACRO_EVT_SSR_DOWN: + trace_printk("%s, enter SSR down\n", __func__); rx_priv->dev_up = false; if (rx_priv->swr_ctrl_data) { swrm_wcd_notify( @@ -1404,6 +1407,7 @@ static int rx_macro_event_handler(struct snd_soc_component *component, } break; case BOLERO_MACRO_EVT_SSR_UP: + trace_printk("%s, enter SSR up\n", __func__); rx_priv->dev_up = true; /* reset swr after ssr/pdr */ rx_priv->reset_swr = true; @@ -3658,6 +3662,8 @@ static int rx_swrm_clock(void *handle, bool enable) mutex_lock(&rx_priv->swr_clk_lock); + trace_printk("%s: swrm clock %s\n", + __func__, (enable ? "enable" : "disable")); dev_dbg(rx_priv->dev, "%s: swrm clock %s\n", __func__, (enable ? "enable" : "disable")); if (enable) { @@ -3724,6 +3730,8 @@ static int rx_swrm_clock(void *handle, bool enable) } } } + trace_printk("%s: swrm clock users %d\n", + __func__, rx_priv->swr_clk_users); dev_dbg(rx_priv->dev, "%s: swrm clock users %d\n", __func__, rx_priv->swr_clk_users); exit: diff --git a/asoc/codecs/bolero/tx-macro.c b/asoc/codecs/bolero/tx-macro.c index fb25c686eb..d411c274b0 100644 --- a/asoc/codecs/bolero/tx-macro.c +++ b/asoc/codecs/bolero/tx-macro.c @@ -374,6 +374,7 @@ static int tx_macro_event_handler(struct snd_soc_component *component, switch (event) { case BOLERO_MACRO_EVT_SSR_DOWN: + trace_printk("%s, enter SSR down\n", __func__); if (tx_priv->swr_ctrl_data) { swrm_wcd_notify( tx_priv->swr_ctrl_data[0].tx_swr_pdev, @@ -393,6 +394,7 @@ static int tx_macro_event_handler(struct snd_soc_component *component, } break; case BOLERO_MACRO_EVT_SSR_UP: + trace_printk("%s, enter SSR up\n", __func__); /* reset swr after ssr/pdr */ tx_priv->reset_swr = true; if (tx_priv->swr_ctrl_data) @@ -2475,6 +2477,9 @@ static int tx_macro_tx_va_mclk_enable(struct tx_macro_priv *tx_priv, { int ret = 0, clk_tx_ret = 0; + trace_printk("%s: clock type %s, enable: %s tx_mclk_users: %d\n", + __func__, (clk_type ? "VA_MCLK" : "TX_MCLK"), + (enable ? "enable" : "disable"), tx_priv->tx_mclk_users); dev_dbg(tx_priv->dev, "%s: clock type %s, enable: %s tx_mclk_users: %d\n", __func__, (clk_type ? "VA_MCLK" : "TX_MCLK"), @@ -2482,6 +2487,7 @@ static int tx_macro_tx_va_mclk_enable(struct tx_macro_priv *tx_priv, if (enable) { if (tx_priv->swr_clk_users == 0) { + trace_printk("%s: tx swr clk users 0\n", __func__); ret = msm_cdc_pinctrl_select_active_state( tx_priv->tx_swr_gpio_p); if (ret < 0) { @@ -2497,6 +2503,7 @@ static int tx_macro_tx_va_mclk_enable(struct tx_macro_priv *tx_priv, TX_CORE_CLK, true); if (clk_type == TX_MCLK) { + trace_printk("%s: requesting TX_MCLK\n", __func__); ret = tx_macro_mclk_enable(tx_priv, 1); if (ret < 0) { if (tx_priv->swr_clk_users == 0) @@ -2509,6 +2516,7 @@ static int tx_macro_tx_va_mclk_enable(struct tx_macro_priv *tx_priv, } } if (clk_type == VA_MCLK) { + trace_printk("%s: requesting VA_MCLK\n", __func__); ret = bolero_clk_rsc_request_clock(tx_priv->dev, TX_CORE_CLK, VA_CORE_CLK, @@ -2540,6 +2548,8 @@ static int tx_macro_tx_va_mclk_enable(struct tx_macro_priv *tx_priv, if (tx_priv->swr_clk_users == 0) { dev_dbg(tx_priv->dev, "%s: reset_swr: %d\n", __func__, tx_priv->reset_swr); + trace_printk("%s: reset_swr: %d\n", + __func__, tx_priv->reset_swr); if (tx_priv->reset_swr) regmap_update_bits(regmap, BOLERO_CDC_TX_CLK_RST_CTRL_SWR_CONTROL, @@ -2633,6 +2643,7 @@ done: TX_CORE_CLK, false); exit: + trace_printk("%s: exit\n", __func__); return ret; } @@ -2709,6 +2720,10 @@ static int tx_macro_swrm_clock(void *handle, bool enable) } mutex_lock(&tx_priv->swr_clk_lock); + trace_printk("%s: swrm clock %s tx_swr_clk_cnt: %d va_swr_clk_cnt: %d\n", + __func__, + (enable ? "enable" : "disable"), + tx_priv->tx_swr_clk_cnt, tx_priv->va_swr_clk_cnt); dev_dbg(tx_priv->dev, "%s: swrm clock %s tx_swr_clk_cnt: %d va_swr_clk_cnt: %d\n", __func__, (enable ? "enable" : "disable"), @@ -2771,6 +2786,9 @@ static int tx_macro_swrm_clock(void *handle, bool enable) } } + trace_printk("%s: swrm clock users %d tx_clk_sts_cnt: %d va_clk_sts_cnt: %d\n", + __func__, tx_priv->swr_clk_users, tx_priv->tx_clk_status, + tx_priv->va_clk_status); dev_dbg(tx_priv->dev, "%s: swrm clock users %d tx_clk_sts_cnt: %d va_clk_sts_cnt: %d\n", __func__, tx_priv->swr_clk_users, tx_priv->tx_clk_status, diff --git a/asoc/codecs/bolero/va-macro.c b/asoc/codecs/bolero/va-macro.c index bdd33e77b4..d86324fead 100644 --- a/asoc/codecs/bolero/va-macro.c +++ b/asoc/codecs/bolero/va-macro.c @@ -298,6 +298,7 @@ static int va_macro_event_handler(struct snd_soc_component *component, __func__); break; case BOLERO_MACRO_EVT_SSR_UP: + trace_printk("%s, enter SSR up\n", __func__); /* enable&disable VA_CORE_CLK to reset GFMUX reg */ ret = bolero_clk_rsc_request_clock(va_priv->dev, va_priv->default_clk_id, diff --git a/asoc/codecs/bolero/wsa-macro.c b/asoc/codecs/bolero/wsa-macro.c index aa41f15a32..d5808e7f37 100644 --- a/asoc/codecs/bolero/wsa-macro.c +++ b/asoc/codecs/bolero/wsa-macro.c @@ -994,6 +994,7 @@ static int wsa_macro_event_handler(struct snd_soc_component *component, switch (event) { case BOLERO_MACRO_EVT_SSR_DOWN: + trace_printk("%s, enter SSR down\n", __func__); if (wsa_priv->swr_ctrl_data) { swrm_wcd_notify( wsa_priv->swr_ctrl_data[0].wsa_swr_pdev, @@ -1013,6 +1014,7 @@ static int wsa_macro_event_handler(struct snd_soc_component *component, } break; case BOLERO_MACRO_EVT_SSR_UP: + trace_printk("%s, enter SSR up\n", __func__); /* reset swr after ssr/pdr */ wsa_priv->reset_swr = true; /* enable&disable WSA_CORE_CLK to reset GFMUX reg */ @@ -2830,6 +2832,9 @@ static int wsa_swrm_clock(void *handle, bool enable) mutex_lock(&wsa_priv->swr_clk_lock); + trace_printk("%s: %s swrm clock %s\n", + dev_name(wsa_priv->dev), __func__, + (enable ? "enable" : "disable")); dev_dbg(wsa_priv->dev, "%s: swrm clock %s\n", __func__, (enable ? "enable" : "disable")); if (enable) { @@ -2895,6 +2900,9 @@ static int wsa_swrm_clock(void *handle, bool enable) } } } + trace_printk("%s: %s swrm clock users: %d\n", + dev_name(wsa_priv->dev), __func__, + wsa_priv->swr_clk_users); dev_dbg(wsa_priv->dev, "%s: swrm clock users %d\n", __func__, wsa_priv->swr_clk_users); exit: diff --git a/asoc/msm-dai-q6-v2.c b/asoc/msm-dai-q6-v2.c index e9d354b8af..bf9c4c5b59 100644 --- a/asoc/msm-dai-q6-v2.c +++ b/asoc/msm-dai-q6-v2.c @@ -1285,6 +1285,7 @@ static int msm_dai_q6_island_mode_put(struct snd_kcontrol *kcontrol, u16 port_id = (u16)kcontrol->private_value; pr_debug("%s: island mode = %d\n", __func__, value); + trace_printk("%s: island mode = %d\n", __func__, value); afe_set_island_mode_cfg(port_id, value); return 0; diff --git a/asoc/msm-pcm-routing-v2.c b/asoc/msm-pcm-routing-v2.c index 63fc72c70c..cd00e68170 100644 --- a/asoc/msm-pcm-routing-v2.c +++ b/asoc/msm-pcm-routing-v2.c @@ -29790,8 +29790,8 @@ static int msm_routing_send_device_pp_params(int port_id, int copp_idx, pr_debug("%s: port_id %d, copp_idx %d\n", __func__, port_id, copp_idx); if (port_id != HDMI_RX && port_id != DISPLAY_PORT_RX) { - pr_err("%s: Device pp params on invalid port %d\n", - __func__, port_id); + pr_err("%s: Device pp params on invalid port %d, copp_idx %d, fe_id %d\n", + __func__, port_id, copp_idx, fe_id); return -EINVAL; } diff --git a/dsp/q6afe.c b/dsp/q6afe.c index a7bd829670..49f2182d8a 100644 --- a/dsp/q6afe.c +++ b/dsp/q6afe.c @@ -1084,6 +1084,8 @@ static int afe_apr_send_pkt(void *data, wait_queue_head_t *wait) pr_err_ratelimited("%s: request timedout\n", __func__); ret = -ETIMEDOUT; + trace_printk("%s: wait for ADSP response timed out\n", + __func__); } else if (atomic_read(&this_afe.status) > 0) { pr_err("%s: DSP returned error[%s]\n", __func__, adsp_err_get_err_str(atomic_read( @@ -2235,7 +2237,7 @@ static int afe_send_hw_delay(u16 port_id, u32 rate) __func__, port_id, ret); fail_cmd: - pr_debug("%s: port_id 0x%x rate %u delay_usec %d status %d\n", + pr_info("%s: port_id 0x%x rate %u delay_usec %d status %d\n", __func__, port_id, rate, delay_entry.delay_usec, ret); return ret; } @@ -2259,6 +2261,8 @@ static struct cal_block_data *afe_find_cal_topo_id_by_port( /* Skip cal_block if it is already marked stale */ if (cal_utils_is_cal_stale(cal_block)) continue; + pr_info("%s: port id: 0x%x, dev_acdb_id: %d\n", __func__, + port_id, this_afe.dev_acdb_id[afe_port_index]); path = ((afe_get_port_type(port_id) == MSM_AFE_PORT_TYPE_TX)?(TX_DEVICE):(RX_DEVICE)); afe_top = @@ -2267,14 +2271,14 @@ static struct cal_block_data *afe_find_cal_topo_id_by_port( if (this_afe.dev_acdb_id[afe_port_index] > 0) { if (afe_top->acdb_id == this_afe.dev_acdb_id[afe_port_index]) { - pr_debug("%s: top_id:%x acdb_id:%d afe_port_id:%d\n", + pr_info("%s: top_id:%x acdb_id:%d afe_port_id:0x%x\n", __func__, afe_top->topology, afe_top->acdb_id, q6audio_get_port_id(port_id)); return cal_block; } } else { - pr_debug("%s: top_id:%x acdb_id:%d afe_port:%d\n", + pr_info("%s: top_id:%x acdb_id:%d afe_port:0x%x\n", __func__, afe_top->topology, afe_top->acdb_id, q6audio_get_port_id(port_id)); return cal_block; @@ -2331,9 +2335,9 @@ static int afe_get_cal_topology_id(u16 port_id, u32 *topology_id, *topology_id = (u32)afe_top_info->topology; cal_utils_mark_cal_used(cal_block); - pr_debug("%s: port_id = %u acdb_id = %d topology_id = %u ret=%d\n", + pr_info("%s: port_id = 0x%x acdb_id = %d topology_id = 0x%x cal_type_index=%d ret=%d\n", __func__, port_id, afe_top_info->acdb_id, - afe_top_info->topology, ret); + afe_top_info->topology, cal_type_index, ret); unlock: mutex_unlock(&this_afe.cal_data[cal_type_index]->lock); return ret; @@ -2388,7 +2392,7 @@ static int afe_send_port_topology_id(u16 port_id) this_afe.topology[index] = topology_id; rtac_update_afe_topology(port_id); done: - pr_debug("%s: AFE set topology id 0x%x enable for port 0x%x ret %d\n", + pr_info("%s: AFE set topology id 0x%x enable for port 0x%x ret %d\n", __func__, topology_id, port_id, ret); return ret; @@ -2461,6 +2465,8 @@ int afe_send_port_island_mode(u16 port_id) } pr_debug("%s: AFE set island mode 0x%x enable for port 0x%x ret %d\n", __func__, island_mode, port_id, ret); + trace_printk("%s: AFE set island mode 0x%x enable for port 0x%x ret %d\n", + __func__, island_mode, port_id, ret); return ret; } EXPORT_SYMBOL(afe_send_port_island_mode); @@ -2623,7 +2629,7 @@ static struct cal_block_data *afe_find_cal(int cal_index, int port_id) struct audio_cal_info_afe *afe_cal_info = NULL; int afe_port_index = q6audio_get_port_index(port_id); - pr_debug("%s: cal_index %d port_id %d port_index %d\n", __func__, + pr_info("%s: cal_index %d port_id 0x%x port_index %d\n", __func__, cal_index, port_id, afe_port_index); if (afe_port_index < 0) { pr_err("%s: Error getting AFE port index %d\n", @@ -2635,16 +2641,21 @@ static struct cal_block_data *afe_find_cal(int cal_index, int port_id) &this_afe.cal_data[cal_index]->cal_blocks) { cal_block = list_entry(ptr, struct cal_block_data, list); afe_cal_info = cal_block->cal_info; + pr_info("%s: acdb_id %d dev_acdb_id %d sample_rate %d afe_sample_rates %d\n", + __func__, afe_cal_info->acdb_id, + this_afe.dev_acdb_id[afe_port_index], + afe_cal_info->sample_rate, + this_afe.afe_sample_rates[afe_port_index]); if ((afe_cal_info->acdb_id == this_afe.dev_acdb_id[afe_port_index]) && (afe_cal_info->sample_rate == this_afe.afe_sample_rates[afe_port_index])) { - pr_debug("%s: cal block is a match, size is %zd\n", + pr_info("%s: cal block is a match, size is %zd\n", __func__, cal_block->cal_data.size); goto exit; } } - pr_debug("%s: no matching cal_block found\n", __func__); + pr_info("%s: no matching cal_block found\n", __func__); cal_block = NULL; exit: @@ -2657,7 +2668,7 @@ static int send_afe_cal_type(int cal_index, int port_id) int ret; int afe_port_index = q6audio_get_port_index(port_id); - pr_debug("%s:\n", __func__); + pr_info("%s: cal_index is %d\n", __func__, cal_index); if (this_afe.cal_data[cal_index] == NULL) { pr_warn("%s: cal_index %d not allocated!\n", @@ -2674,7 +2685,9 @@ static int send_afe_cal_type(int cal_index, int port_id) } mutex_lock(&this_afe.cal_data[cal_index]->lock); - + pr_info("%s: dev_acdb_id[%d] is %d\n", + __func__, afe_port_index, + this_afe.dev_acdb_id[afe_port_index]); if (((cal_index == AFE_COMMON_RX_CAL) || (cal_index == AFE_COMMON_TX_CAL) || (cal_index == AFE_LSM_TX_CAL)) && @@ -2690,7 +2703,7 @@ static int send_afe_cal_type(int cal_index, int port_id) goto unlock; } - pr_debug("%s: Sending cal_index cal %d\n", __func__, cal_index); + pr_info("%s: Sending cal_index cal %d\n", __func__, cal_index); ret = remap_cal_data(cal_block, cal_index); if (ret) { @@ -2701,7 +2714,7 @@ static int send_afe_cal_type(int cal_index, int port_id) } ret = afe_send_cal_block(port_id, cal_block); if (ret < 0) - pr_debug("%s: No cal sent for cal_index %d, port_id = 0x%x! ret %d\n", + pr_err("%s: No cal sent for cal_index %d, port_id = 0x%x! ret %d\n", __func__, cal_index, port_id, ret); cal_utils_mark_cal_used(cal_block); @@ -3776,6 +3789,8 @@ void afe_set_island_mode_cfg(u16 port_id, u32 enable_flag) port_index = afe_get_port_index(port_id); this_afe.island_mode[port_index] = enable_flag; + trace_printk("%s: set island mode cfg 0x%x for port 0x%x\n", + __func__, this_afe.island_mode[port_index], port_id); } EXPORT_SYMBOL(afe_set_island_mode_cfg); @@ -4584,7 +4599,7 @@ static int __afe_port_start(u16 port_id, union afe_port_config *afe_config, port_id = VIRTUAL_ID_TO_PORTID(port_id); } - pr_debug("%s: port id: 0x%x\n", __func__, port_id); + pr_info("%s: port id: 0x%x\n", __func__, port_id); index = q6audio_get_port_index(port_id); if (index < 0 || index >= AFE_MAX_PORTS) { @@ -7605,7 +7620,7 @@ int afe_close(int port_id) ret = -EINVAL; goto fail_cmd; } - pr_debug("%s: port_id = 0x%x\n", __func__, port_id); + pr_info("%s: port_id = 0x%x\n", __func__, port_id); if ((port_id == RT_PROXY_DAI_001_RX) || (port_id == RT_PROXY_DAI_002_TX)) { pr_debug("%s: before decrementing pcm_afe_instance %d\n", @@ -7792,6 +7807,15 @@ int afe_set_lpass_clock(u16 port_id, struct afe_clk_cfg *cfg) cfg->clk_root, cfg->clk_set_mode, cfg->reserved, q6audio_get_port_id(port_id)); + trace_printk("%s: Minor version =0x%x clk val1 = %d\n" + "clk val2 = %d, clk src = 0x%x\n" + "clk root = 0x%x clk mode = 0x%x resrv = 0x%x\n" + "port id = 0x%x\n", + __func__, cfg->i2s_cfg_minor_version, + cfg->clk_val1, cfg->clk_val2, cfg->clk_src, + cfg->clk_root, cfg->clk_set_mode, + cfg->reserved, q6audio_get_port_id(port_id)); + ret = q6afe_pack_and_set_param_in_band(port_id, q6audio_get_port_index(port_id), param_hdr, (u8 *) &clk_cfg); @@ -7844,12 +7868,21 @@ int afe_set_lpass_clk_cfg(int index, struct afe_clk_set *cfg) cfg->clk_id, cfg->clk_freq_in_hz, cfg->clk_attri, cfg->clk_root, cfg->enable); + trace_printk("%s: Minor version =0x%x clk id = %d\n" + "clk freq (Hz) = %d, clk attri = 0x%x\n" + "clk root = 0x%x clk enable = 0x%x\n", + __func__, cfg->clk_set_minor_version, + cfg->clk_id, cfg->clk_freq_in_hz, cfg->clk_attri, + cfg->clk_root, cfg->enable); + ret = q6afe_svc_pack_and_set_param_in_band(index, param_hdr, (u8 *) cfg); - if (ret < 0) + if (ret < 0) { pr_err_ratelimited("%s: AFE clk cfg failed with ret %d\n", + __func__, ret); + trace_printk("%s: AFE clk cfg failed with ret %d\n", __func__, ret); - + } mutex_unlock(&this_afe.afe_clk_lock); return ret; } @@ -9357,6 +9390,8 @@ int afe_vote_lpass_core_hw(uint32_t hw_block_id, char *client_name, pr_debug("%s: lpass core hw vote opcode[0x%x] hw id[0x%x]\n", __func__, cmd_ptr->hdr.opcode, cmd_ptr->hw_block_id); + trace_printk("%s: lpass core hw vote opcode[0x%x] hw id[0x%x]\n", + __func__, cmd_ptr->hdr.opcode, cmd_ptr->hw_block_id); *client_handle = 0; ret = afe_apr_send_clk_pkt((uint32_t *)cmd_ptr, @@ -9396,6 +9431,7 @@ int afe_unvote_lpass_core_hw(uint32_t hw_block_id, uint32_t client_handle) if (!this_afe.lpass_hw_core_client_hdl[hw_block_id]) { pr_debug("%s: SSR in progress, return\n", __func__); + trace_printk("%s: SSR in progress, return\n", __func__); goto done; } @@ -9415,6 +9451,9 @@ int afe_unvote_lpass_core_hw(uint32_t hw_block_id, uint32_t client_handle) pr_debug("%s: lpass core hw unvote opcode[0x%x] hw id[0x%x]\n", __func__, cmd_ptr->hdr.opcode, cmd_ptr->hw_block_id); + trace_printk("%s: lpass core hw unvote opcode[0x%x] hw id[0x%x]\n", + __func__, cmd_ptr->hdr.opcode, cmd_ptr->hw_block_id); + if (cmd_ptr->client_handle <= 0) { pr_err("%s: invalid client handle\n", __func__); ret = -EINVAL; diff --git a/soc/pinctrl-lpi.c b/soc/pinctrl-lpi.c index 566013710c..fdcaeab449 100644 --- a/soc/pinctrl-lpi.c +++ b/soc/pinctrl-lpi.c @@ -497,6 +497,7 @@ int lpi_pinctrl_suspend(struct device *dev) { int ret = 0; + trace_printk("%s: system suspend\n", __func__); dev_dbg(dev, "%s: system suspend\n", __func__); if ((!pm_runtime_enabled(dev) || !pm_runtime_suspended(dev))) { @@ -533,6 +534,7 @@ static struct notifier_block service_nb = { static void lpi_pinctrl_ssr_disable(struct device *dev, void *data) { + trace_printk("%s: enter\n", __func__); lpi_dev_up = false; lpi_pinctrl_suspend(dev); } @@ -857,6 +859,7 @@ int lpi_pinctrl_runtime_resume(struct device *dev) int ret = 0; struct clk *hw_vote = state->lpass_core_hw_vote; + trace_printk("%s: enter\n", __func__); if (state->lpass_core_hw_vote == NULL) { dev_dbg(dev, "%s: Invalid core hw node\n", __func__); if (state->lpass_audio_hw_vote == NULL) { @@ -882,6 +885,7 @@ int lpi_pinctrl_runtime_resume(struct device *dev) exit: mutex_unlock(&state->core_hw_vote_lock); + trace_printk("%s: exit\n", __func__); return 0; } @@ -890,6 +894,7 @@ int lpi_pinctrl_runtime_suspend(struct device *dev) struct lpi_gpio_state *state = dev_get_drvdata(dev); struct clk *hw_vote = state->lpass_core_hw_vote; + trace_printk("%s: enter\n", __func__); if (state->lpass_core_hw_vote == NULL) { dev_dbg(dev, "%s: Invalid core hw node\n", __func__); if (state->lpass_audio_hw_vote == NULL) { @@ -905,6 +910,7 @@ int lpi_pinctrl_runtime_suspend(struct device *dev) state->core_hw_vote_status = false; } mutex_unlock(&state->core_hw_vote_lock); + trace_printk("%s: exit\n", __func__); return 0; } diff --git a/soc/swr-mstr-ctrl.c b/soc/swr-mstr-ctrl.c index 3a33f82780..b4de2d3252 100644 --- a/soc/swr-mstr-ctrl.c +++ b/soc/swr-mstr-ctrl.c @@ -479,6 +479,8 @@ static int swrm_clk_request(struct swr_mstr_ctrl *swrm, bool enable) } swrm->clk_ref_count++; if (swrm->clk_ref_count == 1) { + trace_printk("%s: clock enable count %d", + __func__, swrm->clk_ref_count); ret = swrm->clk(swrm->handle, true); if (ret) { dev_err_ratelimited(swrm->dev, @@ -488,6 +490,8 @@ static int swrm_clk_request(struct swr_mstr_ctrl *swrm, bool enable) } } } else if (--swrm->clk_ref_count == 0) { + trace_printk("%s: clock disable count %d", + __func__, swrm->clk_ref_count); swrm->clk(swrm->handle, false); complete(&swrm->clk_off_complete); } @@ -1738,6 +1742,7 @@ static irqreturn_t swr_mstr_interrupt(int irq, void *dev) struct swr_master *mstr = &swrm->master; int retry = 5; + trace_printk("%s enter\n", __func__); if (unlikely(swrm_lock_sleep(swrm) == false)) { dev_err(swrm->dev, "%s Failed to hold suspend\n", __func__); return IRQ_NONE; @@ -1764,6 +1769,7 @@ static irqreturn_t swr_mstr_interrupt(int irq, void *dev) intr_sts_masked = intr_sts & swrm->intr_mask; dev_dbg(swrm->dev, "%s: status: 0x%x \n", __func__, intr_sts_masked); + trace_printk("%s: status: 0x%x \n", __func__, intr_sts_masked); handle_irq: for (i = 0; i < SWRM_INTERRUPT_MAX; i++) { value = intr_sts_masked & (1 << i); @@ -1967,6 +1973,7 @@ err_audio_hw_vote: exit: mutex_unlock(&swrm->reslock); swrm_unlock_sleep(swrm); + trace_printk("%s exit\n", __func__); return ret; } @@ -1980,6 +1987,7 @@ static irqreturn_t swrm_wakeup_interrupt(int irq, void *dev) return IRQ_NONE; } + trace_printk("%s enter\n", __func__); mutex_lock(&swrm->devlock); if (!swrm->dev_up) { if (swrm->wake_irq > 0) { @@ -2018,6 +2026,7 @@ static irqreturn_t swrm_wakeup_interrupt(int irq, void *dev) pm_runtime_put_autosuspend(swrm->dev); swrm_unlock_sleep(swrm); exit: + trace_printk("%s exit\n", __func__); return ret; } @@ -2032,6 +2041,7 @@ static void swrm_wakeup_work(struct work_struct *work) return; } + trace_printk("%s enter\n", __func__); mutex_lock(&swrm->devlock); if (!swrm->dev_up) { mutex_unlock(&swrm->devlock); @@ -2047,6 +2057,7 @@ static void swrm_wakeup_work(struct work_struct *work) pm_runtime_put_autosuspend(swrm->dev); swrm_unlock_sleep(swrm); exit: + trace_printk("%s exit\n", __func__); pm_relax(swrm->dev); } @@ -2151,6 +2162,8 @@ static void swrm_device_wakeup_vote(struct swr_master *mstr) } dev_dbg(swrm->dev, "%s: hw_clk_en: %d audio_core_clk_en: %d\n", __func__, swrm->hw_core_clk_en, swrm->aud_core_clk_en); + trace_printk("%s: hw_clk_en: %d audio_core_clk_en: %d\n", + __func__, swrm->hw_core_clk_en, swrm->aud_core_clk_en); pm_runtime_get_sync(swrm->dev); } @@ -2168,6 +2181,8 @@ static void swrm_device_wakeup_unvote(struct swr_master *mstr) dev_dbg(swrm->dev, "%s: hw_clk_en: %d audio_core_clk_en: %d\n", __func__, swrm->hw_core_clk_en, swrm->aud_core_clk_en); + trace_printk("%s: hw_clk_en: %d audio_core_clk_en: %d\n", + __func__, swrm->hw_core_clk_en, swrm->aud_core_clk_en); --swrm->aud_core_clk_en; if (swrm->aud_core_clk_en < 0) swrm->aud_core_clk_en = 0; @@ -2727,6 +2742,8 @@ static int swrm_runtime_resume(struct device *dev) dev_dbg(dev, "%s: pm_runtime: resume, state:%d\n", __func__, swrm->state); + trace_printk("%s: pm_runtime: resume, state:%d\n", + __func__, swrm->state); mutex_lock(&swrm->reslock); if (swrm_request_hw_vote(swrm, LPASS_HW_CORE, true)) { @@ -2777,6 +2794,9 @@ static int swrm_runtime_resume(struct device *dev) dev_dbg(dev, "%s slave device up not implemented\n", __func__); + trace_printk( + "%s slave device up not implemented\n", + __func__); ret = 0; } else if (ret) { dev_err(dev, @@ -2838,6 +2858,8 @@ exit: auto_suspend_timer); mutex_unlock(&swrm->reslock); + trace_printk("%s: pm_runtime: resume done, state:%d\n", + __func__, swrm->state); return ret; } @@ -2852,6 +2874,8 @@ static int swrm_runtime_suspend(struct device *dev) struct swr_device *swr_dev; int current_state = 0; + trace_printk("%s: pm_runtime: suspend state: %d\n", + __func__, swrm->state); dev_dbg(dev, "%s: pm_runtime: suspend state: %d\n", __func__, swrm->state); mutex_lock(&swrm->reslock); @@ -2876,10 +2900,13 @@ static int swrm_runtime_suspend(struct device *dev) if ((current_state != SWR_MSTR_SSR) && swrm_is_port_en(&swrm->master)) { dev_dbg(dev, "%s ports are enabled\n", __func__); + trace_printk("%s ports are enabled\n", __func__); ret = -EBUSY; goto exit; } if (!swrm->clk_stop_mode0_supp || swrm->state == SWR_MSTR_SSR) { + dev_err(dev, "%s: clk stop mode not supported or SSR entry\n", + __func__); mutex_unlock(&swrm->reslock); enable_bank_switch(swrm, 0, SWR_ROW_50, SWR_MIN_COL); mutex_lock(&swrm->reslock); @@ -2890,15 +2917,23 @@ static int swrm_runtime_suspend(struct device *dev) if (ret == -ENODEV) { dev_dbg_ratelimited(dev, "%s slave device down not implemented\n", - __func__); + __func__); + trace_printk( + "%s slave device down not implemented\n", + __func__); ret = 0; } else if (ret) { dev_err(dev, "%s: failed to shutdown swr dev %d\n", __func__, swr_dev->dev_num); + trace_printk( + "%s: failed to shutdown swr dev %d\n", + __func__, swr_dev->dev_num); goto exit; } } + trace_printk("%s: clk stop mode not supported or SSR exit\n", + __func__); } else { /* Mask bus clash interrupt */ swrm->intr_mask &= ~((u32)0x08); @@ -2944,6 +2979,8 @@ exit: if (!hw_core_err) swrm_request_hw_vote(swrm, LPASS_HW_CORE, false); mutex_unlock(&swrm->reslock); + trace_printk("%s: pm_runtime: suspend done state: %d\n", + __func__, swrm->state); return ret; } #endif /* CONFIG_PM */ @@ -2955,6 +2992,7 @@ static int swrm_device_suspend(struct device *dev) int ret = 0; dev_dbg(dev, "%s: swrm state: %d\n", __func__, swrm->state); + trace_printk("%s: swrm state: %d\n", __func__, swrm->state); if (!pm_runtime_enabled(dev) || !pm_runtime_suspended(dev)) { ret = swrm_runtime_suspend(dev); if (!ret) { @@ -2973,6 +3011,7 @@ static int swrm_device_down(struct device *dev) struct swr_mstr_ctrl *swrm = platform_get_drvdata(pdev); dev_dbg(dev, "%s: swrm state: %d\n", __func__, swrm->state); + trace_printk("%s: swrm state: %d\n", __func__, swrm->state); mutex_lock(&swrm->force_down_lock); swrm->state = SWR_MSTR_SSR; @@ -3146,6 +3185,7 @@ int swrm_wcd_notify(struct platform_device *pdev, u32 id, void *data) } break; case SWR_DEVICE_SSR_DOWN: + trace_printk("%s: swr device down called\n", __func__); mutex_lock(&swrm->devlock); swrm->dev_up = false; mutex_unlock(&swrm->devlock); @@ -3155,6 +3195,7 @@ int swrm_wcd_notify(struct platform_device *pdev, u32 id, void *data) break; case SWR_DEVICE_SSR_UP: /* wait for clk voting to be zero */ + trace_printk("%s: swr device up called\n", __func__); reinit_completion(&swrm->clk_off_complete); if (swrm->clk_ref_count && !wait_for_completion_timeout(&swrm->clk_off_complete, @@ -3168,6 +3209,7 @@ int swrm_wcd_notify(struct platform_device *pdev, u32 id, void *data) break; case SWR_DEVICE_DOWN: dev_dbg(swrm->dev, "%s: swr master down called\n", __func__); + trace_printk("%s: swr master down called\n", __func__); mutex_lock(&swrm->mlock); if (swrm->state == SWR_MSTR_DOWN) dev_dbg(swrm->dev, "%s:SWR master is already Down:%d\n", @@ -3178,6 +3220,7 @@ int swrm_wcd_notify(struct platform_device *pdev, u32 id, void *data) break; case SWR_DEVICE_UP: dev_dbg(swrm->dev, "%s: swr master up called\n", __func__); + trace_printk("%s: swr master up called\n", __func__); mutex_lock(&swrm->devlock); if (!swrm->dev_up) { dev_dbg(swrm->dev, "SSR not complete yet\n");