Commit 1cfd7c2e authored by Mark Brown's avatar Mark Brown

Merge series "ASoC: SOF: Improvements for debugging" from Peter Ujfalusi...

Merge series "ASoC: SOF: Improvements for debugging" from Peter Ujfalusi <peter.ujfalusi@linux.intel.com>:

Hi,

The aim of this series is to clean up, make it easier to interpret and less
'chatty' prints aimed for debugging errors.

For example currently the DSP/IPC dump is printed every time we have an IPC
timeout and it is posible to lost the first and more indicative dump to find the
rootcause.

Regards,
Peter
---
Peter Ujfalusi (18):
  ASoC: SOF: debug: Swap the dsp_dump and ipc_dump sequence for
    fw_exception
  ASoC: SOF: ipc and dsp dump: Add markers for better visibility
  ASoC: SOF: Print the dbg_dump and ipc_dump once to reduce kernel log
    noise
  ASoC: SOF: loader: Print the DSP dump if boot fails
  ASoC: SOF: intel: atom: No need to do a DSP dump in atom_run()
  ASoC: SOF: debug/ops: Move the IPC and DSP dump functions out from the
    header
  ASoC: SOF: debug: Add SOF_DBG_DUMP_OPTIONAL flag for DSP dumping
  ASoC: SOF: intel: hda-loader: Use snd_sof_dsp_dbg_dump() for DSP dump
  ASoC: SOF: Drop SOF_DBG_DUMP_FORCE_ERR_LEVEL and sof_dev_dbg_or_err
  ASoC: SOF: debug: Print out the fw_state along with the DSP dump
  ASoC: SOF: ipc: Re-enable dumps after successful IPC tx
  ASoC: SOF: ops: Force DSP panic dumps to be printed
  ASoC: SOF: Introduce macro to set the firmware state
  ASoC: SOF: intel: hda: Drop 'error' prefix from error dump functions
  ASoC: SOF: core: Clean up snd_sof_get_status() prints
  ASoC: SOF: loader: Drop SOF_DBG_DUMP_REGS flag when firmware start
    fails
  ASoC: SOF: Intel: hda-loader: Drop SOF_DBG_DUMP_REGS flag from
    dbg_dump calls
  ASoC: SOF: Intel: hda: Dump registers and stack when SOF_DBG_DUMP_REGS
    is set

Pierre-Louis Bossart (1):
  ASoC: SOF: core: debug: force all processing on primary core

 sound/soc/sof/core.c             | 24 ++++++-------
 sound/soc/sof/debug.c            | 61 ++++++++++++++++++++++++++++++--
 sound/soc/sof/intel/atom.c       |  5 +--
 sound/soc/sof/intel/hda-loader.c | 11 +++---
 sound/soc/sof/intel/hda.c        | 16 +++------
 sound/soc/sof/ipc.c              | 10 ++++--
 sound/soc/sof/loader.c           | 11 ++++--
 sound/soc/sof/ops.c              |  3 ++
 sound/soc/sof/ops.h              | 12 +------
 sound/soc/sof/pm.c               |  6 ++--
 sound/soc/sof/sof-priv.h         | 31 ++++++++++------
 sound/soc/sof/topology.c         |  6 ++++
 12 files changed, 131 insertions(+), 65 deletions(-)

--
2.33.0
parents 43b05869 3ad7b8f4
......@@ -67,7 +67,7 @@ void snd_sof_get_status(struct snd_sof_dev *sdev, u32 panic_code,
/* is firmware dead ? */
if ((panic_code & SOF_IPC_PANIC_MAGIC_MASK) != SOF_IPC_PANIC_MAGIC) {
dev_err(sdev->dev, "error: unexpected fault 0x%8.8x trace 0x%8.8x\n",
dev_err(sdev->dev, "unexpected fault %#010x trace %#010x\n",
panic_code, tracep_code);
return; /* no fault ? */
}
......@@ -76,20 +76,20 @@ void snd_sof_get_status(struct snd_sof_dev *sdev, u32 panic_code,
for (i = 0; i < ARRAY_SIZE(panic_msg); i++) {
if (panic_msg[i].id == code) {
dev_err(sdev->dev, "error: %s\n", panic_msg[i].msg);
dev_err(sdev->dev, "error: trace point %8.8x\n",
tracep_code);
dev_err(sdev->dev, "reason: %s (%#x)\n", panic_msg[i].msg,
code & SOF_IPC_PANIC_CODE_MASK);
dev_err(sdev->dev, "trace point: %#010x\n", tracep_code);
goto out;
}
}
/* unknown error */
dev_err(sdev->dev, "error: unknown reason %8.8x\n", panic_code);
dev_err(sdev->dev, "error: trace point %8.8x\n", tracep_code);
dev_err(sdev->dev, "unknown panic code: %#x\n", code & SOF_IPC_PANIC_CODE_MASK);
dev_err(sdev->dev, "trace point: %#010x\n", tracep_code);
out:
dev_err(sdev->dev, "error: panic at %s:%d\n",
panic_info->filename, panic_info->linenum);
dev_err(sdev->dev, "panic at %s:%d\n", panic_info->filename,
panic_info->linenum);
sof_oops(sdev, oops);
sof_stack(sdev, oops, stack, stack_words);
}
......@@ -147,7 +147,7 @@ static int sof_probe_continue(struct snd_sof_dev *sdev)
return ret;
}
sdev->fw_state = SOF_FW_BOOT_PREPARE;
sof_set_fw_state(sdev, SOF_FW_BOOT_PREPARE);
/* check machine info */
ret = sof_machine_check(sdev);
......@@ -189,7 +189,7 @@ static int sof_probe_continue(struct snd_sof_dev *sdev)
goto fw_load_err;
}
sdev->fw_state = SOF_FW_BOOT_IN_PROGRESS;
sof_set_fw_state(sdev, SOF_FW_BOOT_IN_PROGRESS);
/*
* Boot the firmware. The FW boot status will be modified
......@@ -265,7 +265,7 @@ static int sof_probe_continue(struct snd_sof_dev *sdev)
snd_sof_remove(sdev);
/* all resources freed, update state to match */
sdev->fw_state = SOF_FW_BOOT_NOT_STARTED;
sof_set_fw_state(sdev, SOF_FW_BOOT_NOT_STARTED);
sdev->first_boot = true;
return ret;
......@@ -300,7 +300,7 @@ int snd_sof_device_probe(struct device *dev, struct snd_sof_pdata *plat_data)
sdev->pdata = plat_data;
sdev->first_boot = true;
sdev->fw_state = SOF_FW_BOOT_NOT_STARTED;
sof_set_fw_state(sdev, SOF_FW_BOOT_NOT_STARTED);
#if IS_ENABLED(CONFIG_SND_SOC_SOF_DEBUG_PROBES)
sdev->extractor_stream_tag = SOF_PROBE_INVALID_NODE_ID;
#endif
......
......@@ -822,18 +822,75 @@ void snd_sof_free_debug(struct snd_sof_dev *sdev)
}
EXPORT_SYMBOL_GPL(snd_sof_free_debug);
static const struct soc_fw_state_info {
enum snd_sof_fw_state state;
const char *name;
} fw_state_dbg[] = {
{SOF_FW_BOOT_NOT_STARTED, "SOF_FW_BOOT_NOT_STARTED"},
{SOF_FW_BOOT_PREPARE, "SOF_FW_BOOT_PREPARE"},
{SOF_FW_BOOT_IN_PROGRESS, "SOF_FW_BOOT_IN_PROGRESS"},
{SOF_FW_BOOT_FAILED, "SOF_FW_BOOT_FAILED"},
{SOF_FW_BOOT_READY_FAILED, "SOF_FW_BOOT_READY_FAILED"},
{SOF_FW_BOOT_COMPLETE, "SOF_FW_BOOT_COMPLETE"},
};
static void snd_sof_dbg_print_fw_state(struct snd_sof_dev *sdev)
{
int i;
for (i = 0; i < ARRAY_SIZE(fw_state_dbg); i++) {
if (sdev->fw_state == fw_state_dbg[i].state) {
dev_err(sdev->dev, "fw_state: %s (%d)\n", fw_state_dbg[i].name, i);
return;
}
}
dev_err(sdev->dev, "fw_state: UNKNOWN (%d)\n", sdev->fw_state);
}
void snd_sof_dsp_dbg_dump(struct snd_sof_dev *sdev, u32 flags)
{
bool print_all = !!(sof_core_debug & SOF_DBG_PRINT_ALL_DUMPS);
if (flags & SOF_DBG_DUMP_OPTIONAL && !print_all)
return;
if (sof_ops(sdev)->dbg_dump && !sdev->dbg_dump_printed) {
dev_err(sdev->dev, "------------[ DSP dump start ]------------\n");
snd_sof_dbg_print_fw_state(sdev);
sof_ops(sdev)->dbg_dump(sdev, flags);
dev_err(sdev->dev, "------------[ DSP dump end ]------------\n");
if (!print_all)
sdev->dbg_dump_printed = true;
}
}
EXPORT_SYMBOL(snd_sof_dsp_dbg_dump);
static void snd_sof_ipc_dump(struct snd_sof_dev *sdev)
{
if (sof_ops(sdev)->ipc_dump && !sdev->ipc_dump_printed) {
dev_err(sdev->dev, "------------[ IPC dump start ]------------\n");
sof_ops(sdev)->ipc_dump(sdev);
dev_err(sdev->dev, "------------[ IPC dump end ]------------\n");
if (!(sof_core_debug & SOF_DBG_PRINT_ALL_DUMPS))
sdev->ipc_dump_printed = true;
}
}
void snd_sof_handle_fw_exception(struct snd_sof_dev *sdev)
{
if (IS_ENABLED(CONFIG_SND_SOC_SOF_DEBUG_RETAIN_DSP_CONTEXT) ||
(sof_core_debug & SOF_DBG_RETAIN_CTX)) {
/* should we prevent DSP entering D3 ? */
dev_info(sdev->dev, "info: preventing DSP entering D3 state to preserve context\n");
if (!sdev->ipc_dump_printed)
dev_info(sdev->dev,
"preventing DSP entering D3 state to preserve context\n");
pm_runtime_get_noresume(sdev->dev);
}
/* dump vital information to the logs */
snd_sof_dsp_dbg_dump(sdev, SOF_DBG_DUMP_REGS | SOF_DBG_DUMP_MBOX);
snd_sof_ipc_dump(sdev);
snd_sof_dsp_dbg_dump(sdev, SOF_DBG_DUMP_REGS | SOF_DBG_DUMP_MBOX);
snd_sof_trace_notify_for_error(sdev);
}
EXPORT_SYMBOL(snd_sof_handle_fw_exception);
......@@ -283,11 +283,8 @@ int atom_run(struct snd_sof_dev *sdev)
break;
msleep(100);
}
if (tries < 0) {
dev_err(sdev->dev, "error: unable to run DSP firmware\n");
atom_dump(sdev, SOF_DBG_DUMP_REGS | SOF_DBG_DUMP_MBOX);
if (tries < 0)
return -ENODEV;
}
/* return init core mask */
return 1;
......
......@@ -177,13 +177,13 @@ static int cl_dsp_init(struct snd_sof_dev *sdev, int stream_tag)
__func__);
err:
flags = SOF_DBG_DUMP_REGS | SOF_DBG_DUMP_PCI | SOF_DBG_DUMP_MBOX;
flags = SOF_DBG_DUMP_PCI | SOF_DBG_DUMP_MBOX | SOF_DBG_DUMP_OPTIONAL;
/* force error log level after max boot attempts */
/* after max boot attempts make sure that the dump is printed */
if (hda->boot_iteration == HDA_FW_BOOT_ATTEMPTS)
flags |= SOF_DBG_DUMP_FORCE_ERR_LEVEL;
flags &= ~SOF_DBG_DUMP_OPTIONAL;
hda_dsp_dump(sdev, flags);
snd_sof_dsp_dbg_dump(sdev, flags);
snd_sof_dsp_core_power_down(sdev, chip->host_managed_cores_mask);
return ret;
......@@ -414,8 +414,7 @@ int hda_dsp_cl_boot_firmware(struct snd_sof_dev *sdev)
if (!ret) {
dev_dbg(sdev->dev, "Firmware download successful, booting...\n");
} else {
hda_dsp_dump(sdev, SOF_DBG_DUMP_REGS | SOF_DBG_DUMP_PCI | SOF_DBG_DUMP_MBOX |
SOF_DBG_DUMP_FORCE_ERR_LEVEL);
snd_sof_dsp_dbg_dump(sdev, SOF_DBG_DUMP_PCI | SOF_DBG_DUMP_MBOX);
dev_err(sdev->dev, "error: load fw failed ret: %d\n", ret);
}
......
......@@ -532,8 +532,7 @@ static void hda_dsp_dump_ext_rom_status(struct snd_sof_dev *sdev, u32 flags)
len += snprintf(msg + len, sizeof(msg) - len, " 0x%x", value);
}
sof_dev_dbg_or_err(sdev->dev, flags & SOF_DBG_DUMP_FORCE_ERR_LEVEL,
"extended rom status: %s", msg);
dev_err(sdev->dev, "extended rom status: %s", msg);
}
......@@ -546,8 +545,7 @@ void hda_dsp_dump(struct snd_sof_dev *sdev, u32 flags)
/* print ROM/FW status */
hda_dsp_get_status(sdev);
/* print panic info if FW boot is complete. Otherwise, print the extended ROM status */
if (sdev->fw_state == SOF_FW_BOOT_COMPLETE) {
if (flags & SOF_DBG_DUMP_REGS) {
u32 status = snd_sof_dsp_read(sdev, HDA_DSP_BAR, HDA_DSP_SRAM_REG_FW_STATUS);
u32 panic = snd_sof_dsp_read(sdev, HDA_DSP_BAR, HDA_DSP_SRAM_REG_FW_TRACEP);
......@@ -576,12 +574,9 @@ void hda_ipc_irq_dump(struct snd_sof_dev *sdev)
ppsts = snd_sof_dsp_read(sdev, HDA_DSP_PP_BAR, SOF_HDA_REG_PP_PPSTS);
rirbsts = snd_hdac_chip_readb(bus, RIRBSTS);
dev_err(sdev->dev,
"error: hda irq intsts 0x%8.8x intlctl 0x%8.8x rirb %2.2x\n",
dev_err(sdev->dev, "hda irq intsts 0x%8.8x intlctl 0x%8.8x rirb %2.2x\n",
intsts, intctl, rirbsts);
dev_err(sdev->dev,
"error: dsp irq ppsts 0x%8.8x adspis 0x%8.8x\n",
ppsts, adspis);
dev_err(sdev->dev, "dsp irq ppsts 0x%8.8x adspis 0x%8.8x\n", ppsts, adspis);
}
void hda_ipc_dump(struct snd_sof_dev *sdev)
......@@ -599,8 +594,7 @@ void hda_ipc_dump(struct snd_sof_dev *sdev)
/* dump the IPC regs */
/* TODO: parse the raw msg */
dev_err(sdev->dev,
"error: host status 0x%8.8x dsp status 0x%8.8x mask 0x%8.8x\n",
dev_err(sdev->dev, "host status 0x%8.8x dsp status 0x%8.8x mask 0x%8.8x\n",
hipcie, hipct, hipcctl);
}
......
......@@ -267,6 +267,12 @@ static int tx_wait_done(struct snd_sof_ipc *ipc, struct snd_sof_ipc_msg *msg,
memcpy(reply_data, msg->reply_data,
msg->reply_size);
}
/* re-enable dumps after successful IPC tx */
if (sdev->ipc_dump_printed) {
sdev->dbg_dump_printed = false;
sdev->ipc_dump_printed = false;
}
}
return ret;
......@@ -452,9 +458,9 @@ void snd_sof_ipc_msgs_rx(struct snd_sof_dev *sdev)
if (sdev->fw_state == SOF_FW_BOOT_IN_PROGRESS) {
err = sof_ops(sdev)->fw_ready(sdev, cmd);
if (err < 0)
sdev->fw_state = SOF_FW_BOOT_READY_FAILED;
sof_set_fw_state(sdev, SOF_FW_BOOT_READY_FAILED);
else
sdev->fw_state = SOF_FW_BOOT_COMPLETE;
sof_set_fw_state(sdev, SOF_FW_BOOT_COMPLETE);
/* wake up firmware loader */
wake_up(&sdev->boot_wait);
......
......@@ -791,6 +791,10 @@ int snd_sof_run_firmware(struct snd_sof_dev *sdev)
init_waitqueue_head(&sdev->boot_wait);
/* (re-)enable dsp dump */
sdev->dbg_dump_printed = false;
sdev->ipc_dump_printed = false;
/* create read-only fw_version debugfs to store boot version info */
if (sdev->first_boot) {
ret = snd_sof_debugfs_buf_item(sdev, &sdev->fw_version,
......@@ -815,7 +819,8 @@ int snd_sof_run_firmware(struct snd_sof_dev *sdev)
/* boot the firmware on the DSP */
ret = snd_sof_dsp_run(sdev);
if (ret < 0) {
dev_err(sdev->dev, "error: failed to reset DSP\n");
dev_err(sdev->dev, "error: failed to start DSP\n");
snd_sof_dsp_dbg_dump(sdev, SOF_DBG_DUMP_MBOX | SOF_DBG_DUMP_PCI);
return ret;
}
......@@ -831,8 +836,8 @@ int snd_sof_run_firmware(struct snd_sof_dev *sdev)
if (ret == 0) {
dev_err(sdev->dev, "error: firmware boot failure\n");
snd_sof_dsp_dbg_dump(sdev, SOF_DBG_DUMP_REGS | SOF_DBG_DUMP_MBOX |
SOF_DBG_DUMP_TEXT | SOF_DBG_DUMP_PCI | SOF_DBG_DUMP_FORCE_ERR_LEVEL);
sdev->fw_state = SOF_FW_BOOT_FAILED;
SOF_DBG_DUMP_TEXT | SOF_DBG_DUMP_PCI);
sof_set_fw_state(sdev, SOF_FW_BOOT_FAILED);
return -EIO;
}
......
......@@ -157,6 +157,9 @@ void snd_sof_dsp_panic(struct snd_sof_dev *sdev, u32 offset)
dev_dbg(sdev->dev, "panic: dsp_oops_offset %zu offset %d\n",
sdev->dsp_oops_offset, offset);
/* We want to see the DSP panic! */
sdev->dbg_dump_printed = false;
snd_sof_dsp_dbg_dump(sdev, SOF_DBG_DUMP_REGS | SOF_DBG_DUMP_MBOX);
snd_sof_trace_notify_for_error(sdev);
}
......
......@@ -241,17 +241,7 @@ snd_sof_dsp_set_power_state(struct snd_sof_dev *sdev,
}
/* debug */
static inline void snd_sof_dsp_dbg_dump(struct snd_sof_dev *sdev, u32 flags)
{
if (sof_ops(sdev)->dbg_dump)
sof_ops(sdev)->dbg_dump(sdev, flags);
}
static inline void snd_sof_ipc_dump(struct snd_sof_dev *sdev)
{
if (sof_ops(sdev)->ipc_dump)
sof_ops(sdev)->ipc_dump(sdev);
}
void snd_sof_dsp_dbg_dump(struct snd_sof_dev *sdev, u32 flags);
static inline int snd_sof_debugfs_add_region_item(struct snd_sof_dev *sdev,
enum snd_sof_fw_blk_type blk_type, u32 offset, size_t size,
......
......@@ -122,7 +122,7 @@ static int sof_resume(struct device *dev, bool runtime_resume)
old_state == SOF_DSP_PM_D0)
return 0;
sdev->fw_state = SOF_FW_BOOT_PREPARE;
sof_set_fw_state(sdev, SOF_FW_BOOT_PREPARE);
/* load the firmware */
ret = snd_sof_load_firmware(sdev);
......@@ -133,7 +133,7 @@ static int sof_resume(struct device *dev, bool runtime_resume)
return ret;
}
sdev->fw_state = SOF_FW_BOOT_IN_PROGRESS;
sof_set_fw_state(sdev, SOF_FW_BOOT_IN_PROGRESS);
/*
* Boot the firmware. The FW boot status will be modified
......@@ -257,7 +257,7 @@ static int sof_suspend(struct device *dev, bool runtime_suspend)
return ret;
/* reset FW state */
sdev->fw_state = SOF_FW_BOOT_NOT_STARTED;
sof_set_fw_state(sdev, SOF_FW_BOOT_NOT_STARTED);
sdev->enabled_cores_mask = 0;
return ret;
......
......@@ -30,13 +30,16 @@
#define SOF_DBG_DYNAMIC_PIPELINES_ENABLE BIT(4) /* 0: use static pipelines
* 1: use dynamic pipelines
*/
#define SOF_DBG_DISABLE_MULTICORE BIT(5) /* schedule all pipelines/widgets
* on primary core
*/
#define SOF_DBG_PRINT_ALL_DUMPS BIT(6) /* Print all ipc and dsp dumps */
#define SOF_DBG_DUMP_REGS BIT(0)
#define SOF_DBG_DUMP_MBOX BIT(1)
#define SOF_DBG_DUMP_TEXT BIT(2)
#define SOF_DBG_DUMP_PCI BIT(3)
#define SOF_DBG_DUMP_FORCE_ERR_LEVEL BIT(4) /* used to dump dsp status with error log level */
#define SOF_DBG_DUMP_OPTIONAL BIT(4) /* only dump if SOF_DBG_PRINT_ALL_DUMPS is set */
/* global debug state set by SOF_DBG_ flags */
extern int sof_core_debug;
......@@ -418,6 +421,8 @@ struct snd_sof_dev {
/* debug */
struct dentry *debugfs_root;
struct list_head dfsentry_list;
bool dbg_dump_printed;
bool ipc_dump_printed;
/* firmware loader */
struct snd_dma_buffer dmab;
......@@ -556,6 +561,19 @@ static inline void sof_oops(struct snd_sof_dev *sdev, void *oops)
extern const struct dsp_arch_ops sof_xtensa_arch_ops;
/*
* Firmware state tracking
*/
static inline void sof_set_fw_state(struct snd_sof_dev *sdev,
enum snd_sof_fw_state new_state)
{
if (sdev->fw_state == new_state)
return;
dev_dbg(sdev->dev, "fw_state change: %d -> %d\n", sdev->fw_state, new_state);
sdev->fw_state = new_state;
}
/*
* Utilities
*/
......@@ -587,13 +605,4 @@ int intel_pcm_close(struct snd_sof_dev *sdev,
struct snd_pcm_substream *substream);
int sof_machine_check(struct snd_sof_dev *sdev);
#define sof_dev_dbg_or_err(dev, is_err, fmt, ...) \
do { \
if (is_err) \
dev_err(dev, "error: " fmt, __VA_ARGS__); \
else \
dev_dbg(dev, fmt, __VA_ARGS__); \
} while (0)
#endif
......@@ -1758,6 +1758,9 @@ static int sof_widget_load_pipeline(struct snd_soc_component *scomp, int index,
goto err;
}
if (sof_core_debug & SOF_DBG_DISABLE_MULTICORE)
pipeline->core = SOF_DSP_PRIMARY_CORE;
if (sof_core_debug & SOF_DBG_DYNAMIC_PIPELINES_OVERRIDE)
swidget->dynamic_pipeline_widget = sof_core_debug &
SOF_DBG_DYNAMIC_PIPELINES_ENABLE;
......@@ -2355,6 +2358,9 @@ static int sof_widget_ready(struct snd_soc_component *scomp, int index,
return ret;
}
if (sof_core_debug & SOF_DBG_DISABLE_MULTICORE)
comp.core = SOF_DSP_PRIMARY_CORE;
swidget->core = comp.core;
ret = sof_parse_tokens(scomp, &swidget->comp_ext, comp_ext_tokens,
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment