From 894886ab1ebc9a361ae5e1d801ceb9d071a6fd0a Mon Sep 17 00:00:00 2001 From: Liam Girdwood Date: Wed, 14 Nov 2018 17:10:33 +0000 Subject: [PATCH 1/2] ipc: trace: standardise trace output and improve trace debug Improve trace for IPC. Signed-off-by: Liam Girdwood --- src/ipc/byt-ipc.c | 25 +++--- src/ipc/cnl-ipc.c | 25 +++--- src/ipc/handler.c | 208 +++++++++++++++++++++------------------------- src/ipc/hsw-ipc.c | 25 +++--- src/ipc/pmc-ipc.c | 20 ++--- src/ipc/sue-ipc.c | 6 +- 6 files changed, 143 insertions(+), 166 deletions(-) diff --git a/src/ipc/byt-ipc.c b/src/ipc/byt-ipc.c index 764c76a8d01d..b1da00312035 100644 --- a/src/ipc/byt-ipc.c +++ b/src/ipc/byt-ipc.c @@ -58,13 +58,13 @@ static void do_notify(void) uint32_t flags; struct ipc_msg *msg; - tracev_ipc("Not"); - spin_lock_irq(&_ipc->lock, flags); msg = _ipc->shared_ctx->dsp_msg; if (msg == NULL) goto out; + trace_ipc("ipc: not rx -> 0x%x", msg->header); + /* copy the data returned from DSP */ if (msg->rx_size && msg->rx_size < SOF_IPC_MSG_MAX_SIZE) mailbox_dspbox_read(msg->rx_data, 0, msg->rx_size); @@ -88,12 +88,13 @@ static void do_notify(void) static void irq_handler(void *arg) { uint32_t isr; - - tracev_ipc("IRQ"); + uint32_t msg = 0; /* Interrupt arrived, check src */ isr = shim_read(SHIM_ISRD); + tracev_ipc("ipc: irq isr 0x%x", isr); + if (isr & SHIM_ISRD_DONE) { /* Mask Done interrupt before return */ @@ -108,12 +109,17 @@ static void irq_handler(void *arg) shim_write(SHIM_IMRD, shim_read(SHIM_IMRD) | SHIM_IMRD_BUSY); interrupt_clear(PLATFORM_IPC_INTERRUPT); + msg = shim_read(SHIM_IPCXL); + /* TODO: place message in Q and process later */ /* It's not Q ATM, may overwrite */ if (_ipc->host_pending) { - trace_ipc_error("Pen"); + trace_ipc_error("ipc: dropping msg 0x%x", msg); + trace_ipc_error(" isr 0x%x imrd 0x%x ipcxh 0x%x", + isr, shim_read(SHIM_IMRD), + shim_read(SHIM_IPCXH)); } else { - _ipc->host_msg = shim_read(SHIM_IPCXL); + _ipc->host_msg = msg; _ipc->host_pending = 1; ipc_schedule_process(_ipc); } @@ -127,7 +133,7 @@ void ipc_platform_do_cmd(struct ipc *ipc) uint32_t ipcxh; int32_t err; - tracev_ipc("Cmd"); + trace_ipc("ipc: msg rx -> 0x%x", ipc->host_msg); /* perform command and return any error */ err = ipc_cmd(); @@ -159,12 +165,9 @@ void ipc_platform_do_cmd(struct ipc *ipc) /* are we about to enter D3 ? */ if (iipc->pm_prepare_D3) { while (1) { - trace_ipc("pme"); wait_for_interrupt(0); } } - - tracev_ipc("CmD"); } void ipc_platform_send_msg(struct ipc *ipc) @@ -190,7 +193,7 @@ void ipc_platform_send_msg(struct ipc *ipc) mailbox_dspbox_write(0, msg->tx_data, msg->tx_size); list_item_del(&msg->list); ipc->shared_ctx->dsp_msg = msg; - tracev_ipc("Msg"); + tracev_ipc("ipc: msg tx -> 0x%x", msg->header); /* now interrupt host to tell it we have message sent */ shim_write(SHIM_IPCDL, msg->header); diff --git a/src/ipc/cnl-ipc.c b/src/ipc/cnl-ipc.c index 881340a7d3ed..33042c1efab7 100644 --- a/src/ipc/cnl-ipc.c +++ b/src/ipc/cnl-ipc.c @@ -50,14 +50,9 @@ #include #include #include -//<<<<<<< HEAD #include - -//======= -//#include -//#include #include -//>>>>>>> Added SRAM power gating on D3 entry for cAVS 1.8 (i.e. Cannonlake). + extern struct ipc *_ipc; /* test code to check working IRQ */ @@ -67,14 +62,13 @@ static void irq_handler(void *arg) uint32_t dipcida; uint32_t msg = 0; - tracev_ipc("IRQ"); - dipctdr = ipc_read(IPC_DIPCTDR); dipcida = ipc_read(IPC_DIPCIDA); + tracev_ipc("ipc: irq dipctdr 0x%x dipcida 0x%x", dipctdr, dipcida); + /* new message from host */ if (dipctdr & IPC_DIPCTDR_BUSY) { - tracev_ipc("Nms"); /* mask Busy interrupt */ ipc_write(IPC_DIPCCTL, ipc_read(IPC_DIPCCTL) & ~IPC_DIPCCTL_IPCTBIE); @@ -84,7 +78,10 @@ static void irq_handler(void *arg) /* TODO: place message in Q and process later */ /* It's not Q ATM, may overwrite */ if (_ipc->host_pending) { - trace_ipc_error("Pen"); + trace_ipc_error("ipc: dropping msg 0x%x", msg); + trace_ipc_error(" dipctdr 0x%x dipcida 0x%x dipcctl 0x%x", + dipctdr, dipcida, + ipc_read(IPC_DIPCCTL)); } else { _ipc->host_msg = msg; _ipc->host_pending = 1; @@ -94,7 +91,7 @@ static void irq_handler(void *arg) /* reply message(done) from host */ if (dipcida & IPC_DIPCIDA_DONE) { - tracev_ipc("Rpy"); + /* mask Done interrupt */ ipc_write(IPC_DIPCCTL, ipc_read(IPC_DIPCCTL) & ~IPC_DIPCCTL_IPCIDIE); @@ -113,7 +110,7 @@ void ipc_platform_do_cmd(struct ipc *ipc) struct sof_ipc_reply reply; int32_t err; - trace_ipc("Cmd"); + trace_ipc("ipc: msg rx -> 0x%x", ipc->host_msg); /* perform command and return any error */ err = ipc_cmd(); @@ -154,8 +151,6 @@ void ipc_platform_do_cmd(struct ipc *ipc) wait_for_interrupt(0); #endif } - - tracev_ipc("CmD"); } void ipc_platform_send_msg(struct ipc *ipc) @@ -181,7 +176,7 @@ void ipc_platform_send_msg(struct ipc *ipc) mailbox_dspbox_write(0, msg->tx_data, msg->tx_size); list_item_del(&msg->list); ipc->shared_ctx->dsp_msg = msg; - tracev_ipc("Msg"); + tracev_ipc("ipc: msg tx -> 0x%x", msg->header); /* now interrupt host to tell it we have message sent */ ipc_write(IPC_DIPCIDD, 0); diff --git a/src/ipc/handler.c b/src/ipc/handler.c index a830e0733fd3..8cb9a186222b 100644 --- a/src/ipc/handler.c +++ b/src/ipc/handler.c @@ -85,8 +85,7 @@ static inline struct sof_ipc_hdr *mailbox_validate(void) /* validate component header */ if (hdr->size > SOF_IPC_MSG_MAX_SIZE) { - trace_ipc_error("mailbox_validate() error: Invalid size of " - "component header."); + trace_ipc_error("ipc: msg too big at 0x%x", hdr->size); return NULL; } @@ -184,28 +183,25 @@ static int ipc_stream_pcm_params(uint32_t stream) struct comp_dev *cd; int err, posn_offset; - trace_ipc("ipc_stream_pcm_params()"); + trace_ipc("ipc: comp %d -> params", pcm_params->comp_id); /* sanity check size */ if (IPC_INVALID_SIZE(pcm_params)) { - trace_ipc_error("ipc_stream_pcm_params() error: Invalid size of" - "IPC pcm params."); + trace_ipc_error("ipc:_invalid IPC size 0x%x got 0x%x", + sizeof(*pcm_params), pcm_params->hdr.size); return -EINVAL; } /* get the pcm_dev */ pcm_dev = ipc_get_comp(_ipc, pcm_params->comp_id); if (pcm_dev == NULL) { - trace_ipc_error("ipc_stream_pcm_params() error: Requested " - "pcm_dev ID = %u not found.", - pcm_params->comp_id); + trace_ipc_error("ipc: comp %d not found", pcm_params->comp_id); return -ENODEV; } /* sanity check comp */ if (pcm_dev->cd->pipeline == NULL) { - trace_ipc_error("ipc_stream_pcm_params() error: Requested " - "pcm_dev ID = %u has no pipeline associated.", + trace_ipc_error("ipc: comp %d pipeline not found", pcm_params->comp_id); return -EINVAL; } @@ -228,9 +224,8 @@ static int ipc_stream_pcm_params(uint32_t stream) err = ipc_get_page_descriptors(iipc->dmac, iipc->page_table, &pcm_params->params.buffer); if (err < 0) { - trace_ipc_error("ipc_stream_pcm_params() error: " - "ipc_get_page_descriptors() failed with err = " - "%d", err); + trace_ipc_error("ipc: comp %d get descriptors failed %d", + pcm_params->comp_id, err); goto error; } @@ -242,16 +237,15 @@ static int ipc_stream_pcm_params(uint32_t stream) &pcm_params->params.buffer, &elem_array, host->direction); if (err < 0) { - trace_ipc_error("ipc_stream_pcm_params() error: " - "ipc_parse_page_descriptors() failed with err =" - " %d", err); + trace_ipc_error("ipc: comp %d parse descriptors failed %d", + pcm_params->comp_id, err); goto error; } err = comp_host_buffer(cd, &elem_array, ring_size); if (err < 0) { - trace_ipc_error("ipc_stream_pcm_params() error: " - "comp_host_buffer() failed with err = %d", err); + trace_ipc_error("ipc: comp %d host buffer failed %d", + pcm_params->comp_id, err); goto error; } @@ -261,23 +255,26 @@ static int ipc_stream_pcm_params(uint32_t stream) /* configure pipeline audio params */ err = pipeline_params(pcm_dev->cd->pipeline, pcm_dev->cd, pcm_params); if (err < 0) { - trace_ipc_error("ipc_stream_pcm_params() error: " - "pipeline_params() failed with err = %d", err); + trace_ipc_error("ipc: pipe %d comp %d params failed %d", + pcm_dev->cd->pipeline->ipc_pipe.pipeline_id, + pcm_params->comp_id, err); goto error; } /* prepare pipeline audio params */ err = pipeline_prepare(pcm_dev->cd->pipeline, pcm_dev->cd); if (err < 0) { - trace_ipc_error("ipc_stream_pcm_params() error: " - "pipeline_prepare() failed with err = %d", err); + trace_ipc_error("ipc: pipe %d comp %d prepare failed %d", + pcm_dev->cd->pipeline->ipc_pipe.pipeline_id, + pcm_params->comp_id, err); goto error; } posn_offset = ipc_get_posn_offset(_ipc, pcm_dev->cd->pipeline); if (posn_offset < 0) { - trace_ipc_error("ipc_stream_pcm_params() error: " - "ipc_get_posn_offset() failed."); + trace_ipc_error("ipc: pipe %d comp %d posn offset failed %d", + pcm_dev->cd->pipeline->ipc_pipe.pipeline_id, + pcm_params->comp_id, err); goto error; } /* write component values to the outbox */ @@ -296,8 +293,9 @@ static int ipc_stream_pcm_params(uint32_t stream) err = pipeline_reset(pcm_dev->cd->pipeline, pcm_dev->cd); if (err < 0) - trace_ipc_error("ipc_stream_pcm_params() error: " - "pipeline_reset() failed with err = %d", err); + trace_ipc_error("ipc: pipe %d comp %d reset failed %d", + pcm_dev->cd->pipeline->ipc_pipe.pipeline_id, + pcm_params->comp_id, err); return -EINVAL; } @@ -307,27 +305,25 @@ static int ipc_stream_pcm_free(uint32_t header) struct sof_ipc_stream *free_req = _ipc->comp_data; struct ipc_comp_dev *pcm_dev; - trace_ipc("ipc_stream_pcm_free()"); + trace_ipc("ipc: comp %d -> free", free_req->comp_id); /* sanity check size */ if (IPC_INVALID_SIZE(free_req)) { - trace_ipc_error("ipc_stream_pcm_free() error: Invalid size of " - "IPC."); + trace_ipc_error("ipc:_invalid IPC size 0x%x got 0x%x", + sizeof(*free_req), free_req->hdr.size); return -EINVAL; } /* get the pcm_dev */ pcm_dev = ipc_get_comp(_ipc, free_req->comp_id); if (pcm_dev == NULL) { - trace_ipc_error("ipc_stream_pcm_free() error: Requested pcm_dev" - " ID = %u not found.", free_req->comp_id); + trace_ipc_error("ipc: comp %d not found", free_req->comp_id); return -ENODEV; } /* sanity check comp */ if (pcm_dev->cd->pipeline == NULL) { - trace_ipc_error("ipc_stream_pcm_free() error: Requested pcm_dev" - " ID = %u has no pipeline associated.", + trace_ipc_error("ipc: comp %d pipeline not found", free_req->comp_id); return -EINVAL; } @@ -343,22 +339,21 @@ static int ipc_stream_position(uint32_t header) struct sof_ipc_stream_posn posn; struct ipc_comp_dev *pcm_dev; - trace_ipc("ipc_stream_position()"); + trace_ipc("ipc: comp %d -> position", stream->comp_id); memset(&posn, 0, sizeof(posn)); /* sanity check size */ if (IPC_INVALID_SIZE(stream)) { - trace_ipc_error("ipc_stream_position() error: Invalid size of " - "IPC"); + trace_ipc_error("ipc:_invalid IPC size 0x%x got 0x%x", + sizeof(*stream), stream->hdr.size); return -EINVAL; } /* get the pcm_dev */ pcm_dev = ipc_get_comp(_ipc, stream->comp_id); if (pcm_dev == NULL) { - trace_ipc_error("ipc_stream_position() error: Requested pcm_dev" - " ID = %u not found.", stream->comp_id); + trace_ipc_error("ipc: comp %d not found", stream->comp_id); return -ENODEV; } @@ -382,7 +377,6 @@ static int ipc_stream_position(uint32_t header) int ipc_stream_send_position(struct comp_dev *cdev, struct sof_ipc_stream_posn *posn) { - tracev_ipc("Pos"); posn->rhdr.hdr.cmd = SOF_IPC_GLB_STREAM_MSG | SOF_IPC_STREAM_POSITION | cdev->comp.id; posn->rhdr.hdr.size = sizeof(*posn); @@ -414,20 +408,19 @@ static int ipc_stream_trigger(uint32_t header) uint32_t ipc_cmd = (header & SOF_CMD_TYPE_MASK) >> SOF_CMD_TYPE_SHIFT; int ret; - trace_ipc("ipc_stream_trigger()"); + trace_ipc("ipc: comp %d -> trigger cmd %d", stream->comp_id, ipc_cmd); /* sanity check size */ if (IPC_INVALID_SIZE(stream)) { - trace_ipc_error("ipc_stream_trigger() error: Invalid size of " - "IPC"); + trace_ipc_error("ipc:_invalid IPC size 0x%x got 0x%x", + sizeof(*stream), stream->hdr.size); return -EINVAL; } /* get the pcm_dev */ pcm_dev = ipc_get_comp(_ipc, stream->comp_id); if (pcm_dev == NULL) { - trace_ipc_error("ipc_stream_trigger() error: Requested pcm_dev " - " ID = %u not found.", stream->comp_id); + trace_ipc_error("ipc: comp %d not found", stream->comp_id); return -ENODEV; } @@ -452,9 +445,8 @@ static int ipc_stream_trigger(uint32_t header) /* trigger the component */ ret = pipeline_trigger(pcm_dev->cd->pipeline, pcm_dev->cd, cmd); if (ret < 0) { - trace_ipc_error("ipc_stream_trigger() error: pipeline_trigger()" - " failed with ret = %d, ipc_cmd = %u", ret, - ipc_cmd); + trace_ipc_error("ipc: comp %d trigger %d failed %d", + stream->comp_id, ipc_cmd, ret); } return ret; @@ -479,8 +471,7 @@ static int ipc_glb_stream_message(uint32_t header) case iCS(SOF_IPC_STREAM_POSITION): return ipc_stream_position(header); default: - trace_ipc_error("ipc_glb_stream_message() error: Invalid " - "command, cmd = %u", cmd); + trace_ipc_error("ipc: unknown stream cmd %u", cmd); return -EINVAL; } } @@ -495,13 +486,13 @@ static int ipc_dai_config(uint32_t header) struct dai *dai; int ret; - trace_ipc("ipc_dai_config()"); + trace_ipc("ipc: dai %d,%d -> config ", config->type, + config->dai_index); /* get DAI */ dai = dai_get(config->type, config->dai_index, 0 /* existing only */); if (dai == NULL) { - trace_ipc_error("ipc_dai_config() error: Requested DAI not " - "found, type = %u, dai_index = %u", + trace_ipc_error("ipc: dai %d,%d not found", config->type, config->dai_index); return -ENODEV; } @@ -510,8 +501,8 @@ static int ipc_dai_config(uint32_t header) ret = dai_set_config(dai, config); dai_put(dai); /* free ref immediately */ if (ret < 0) { - trace_ipc_error("ipc_dai_config() error: dai_set_config() " - "failed with ret = %d", ret); + trace_ipc_error("ipc: dai %d,%d config failed %d", + config->type, config->dai_index, ret); return ret; } @@ -529,8 +520,7 @@ static int ipc_glb_dai_message(uint32_t header) case iCS(SOF_IPC_DAI_LOOPBACK): //return ipc_comp_set_value(header, COMP_CMD_LOOPBACK); default: - trace_ipc_error("ipc_glb_dai_message() error: Invalid command " - "header = %u", header); + trace_ipc_error("ipc: unknown DAI cmd %u", cmd); return -EINVAL; } } @@ -543,7 +533,7 @@ static int ipc_pm_context_size(uint32_t header) { struct sof_ipc_pm_ctx pm_ctx; - trace_ipc("ipc_pm_context_size()"); + trace_ipc("ipc: pm -> size"); bzero(&pm_ctx, sizeof(pm_ctx)); @@ -559,7 +549,7 @@ static int ipc_pm_context_save(uint32_t header) struct sof_ipc_pm_ctx *pm_ctx = _ipc->comp_data; struct ipc_data *iipc = ipc_get_drvdata(_ipc); - trace_ipc("ipc_pm_context_save()"); + trace_ipc("ipc: pm -> save"); /* TODO: check we are inactive - all streams are suspended */ @@ -595,7 +585,7 @@ static int ipc_pm_context_restore(uint32_t header) { struct sof_ipc_pm_ctx *pm_ctx = _ipc->comp_data; - trace_ipc("ipc_pm_context_restore()"); + trace_ipc("ipc: pm -> restore"); /* restore context placeholder */ mailbox_hostbox_write(0, pm_ctx, sizeof(*pm_ctx)); @@ -608,7 +598,8 @@ static int ipc_pm_core_enable(uint32_t header) struct sof_ipc_pm_core_config *pm_core_config = _ipc->comp_data; int i = 0; - trace_ipc("ipc_pm_core_enable()"); + trace_ipc("ipc: pm core mask 0x%x -> enable", + pm_core_config->enable_mask); for (i = 0; i < PLATFORM_CORE_COUNT; i++) { if (i != PLATFORM_MASTER_CORE_ID) { @@ -639,6 +630,7 @@ static int ipc_glb_pm_message(uint32_t header) case iCS(SOF_IPC_PM_CLK_GET): case iCS(SOF_IPC_PM_CLK_REQ): default: + trace_ipc_error("ipc: unknown pm cmd %u", cmd); return -EINVAL; } } @@ -656,12 +648,11 @@ static int ipc_dma_trace_config(uint32_t header) struct sof_ipc_dma_trace_params *params = _ipc->comp_data; int err; - trace_ipc("ipc_dma_trace_config()"); /* sanity check size */ if (IPC_INVALID_SIZE(params)) { - trace_ipc_error("ipc_dma_trace_config() error: Invalid size of " - "IPC"); + trace_ipc_error("ipc:_invalid IPC size 0x%x got 0x%x", + sizeof(*params), params->hdr.size); return -EINVAL; } @@ -673,30 +664,24 @@ static int ipc_dma_trace_config(uint32_t header) err = ipc_get_page_descriptors(iipc->dmac, iipc->page_table, ¶ms->buffer); if (err < 0) { - trace_ipc_error("ipc_dma_trace_config() error: " - "ipc_get_page_descriptors() failed with err = " - "%u", err); + trace_ipc_error("ipc: trace failed to get descriptors %u", err); goto error; } - trace_ipc("ipc_dma_trace_config() Page descriptors acquired."); - /* Parse host tables */ ring_size = params->buffer.size; err = ipc_parse_page_descriptors(iipc->page_table, ¶ms->buffer, &elem_array, SOF_IPC_STREAM_CAPTURE); if (err < 0) { - trace_ipc_error("ipc_dma_trace_config() error: " - "ipc_parse_page_descriptors() failed with err =" - " %d", err); + trace_ipc_error("ipc: trace failed to parse descriptors %d", + err); goto error; } err = dma_trace_host_buffer(_ipc->dmat, &elem_array, ring_size); if (err < 0) { - trace_ipc_error("ipc_dma_trace_config() error: " - "dma_trace_host_buffer() failed with err = %d", + trace_ipc_error("ipc: trace failed to set host buffers %d", err); goto error; } @@ -708,12 +693,10 @@ static int ipc_dma_trace_config(uint32_t header) /* host buffer size for DMA trace */ _ipc->dmat->host_size = params->buffer.size; #endif - trace_ipc("ipc_dma_trace_config() DMA trace configured."); err = dma_trace_enable(_ipc->dmat); if (err < 0) { - trace_ipc_error("ipc_dma_trace_config() error: " - "dma_trace_enable() failed with err = %d", err); + trace_ipc_error("ipc: failed to enable trace %d", err); goto error; } @@ -746,14 +729,13 @@ static int ipc_glb_debug_message(uint32_t header) { uint32_t cmd = (header & SOF_CMD_TYPE_MASK) >> SOF_CMD_TYPE_SHIFT; - trace_ipc("ipc_glb_debug_message()"); + trace_ipc("ipc: debug cmd 0x%x", cmd); switch (cmd) { case iCS(SOF_IPC_TRACE_DMA_PARAMS): return ipc_dma_trace_config(header); default: - trace_ipc_error("ipc_glb_debug_message() error: Unknown command" - ", header = %u", header); + trace_ipc_error("ipc: unknown debug cmd %u", cmd); return -EINVAL; } } @@ -771,6 +753,7 @@ static int ipc_comp_cmd(struct comp_dev *dev, int cmd, /* pipeline running on other core */ if (dev->pipeline->status == COMP_STATE_ACTIVE && cpu_get_id() != core) { + /* check if requested core is enabled */ if (!cpu_is_core_enabled(core)) return -EINVAL; @@ -794,21 +777,20 @@ static int ipc_comp_value(uint32_t header, uint32_t cmd) struct sof_ipc_ctrl_data *data = _ipc->comp_data; int ret; - trace_ipc("ipc_comp_value()"); + trace_ipc("ipc: comp %d -> cmd %d", data->comp_id, data->cmd); /* get the component */ comp_dev = ipc_get_comp(_ipc, data->comp_id); if (comp_dev == NULL){ - trace_ipc_error("ipc_comp_value() error: Requested comp_dev ID " - "= %u not found.", data->comp_id); + trace_ipc_error("ipc: comp %d not found", data->comp_id); return -ENODEV; } /* get component values */ ret = ipc_comp_cmd(comp_dev->cd, cmd, data); if (ret < 0) { - trace_ipc_error("ipc_comp_value() error: ipc_comp_cmd() failed," - " cmd = %u", cmd); + trace_ipc_error("ipc: comp %d cmd %u failed 5d", data->comp_id, + data->cmd, ret); return ret; } @@ -831,8 +813,7 @@ static int ipc_glb_comp_message(uint32_t header) case iCS(SOF_IPC_COMP_GET_DATA): return ipc_comp_value(header, COMP_CMD_GET_DATA); default: - trace_ipc_error("ipc_glb_comp_message() error: Unknown command," - "header = %u", header); + trace_ipc_error("ipc: unknown comp cmd %u", cmd); return -EINVAL; } } @@ -843,13 +824,14 @@ static int ipc_glb_tplg_comp_new(uint32_t header) struct sof_ipc_comp_reply reply; int ret; - trace_ipc("ipc_glb_tplg_comp_new()"); + trace_ipc("ipc: pipe %d comp %d -> new (type %d)", comp->pipeline_id, + comp->id, comp->type); /* register component */ ret = ipc_comp_new(_ipc, comp); if (ret < 0) { - trace_ipc_error("ipc_glb_tplg_comp_new() error: ipc_comp_new() " - "failed."); + trace_ipc_error("ipc: pipe %d comp %d creation failed %d", + comp->pipeline_id, comp->id, ret); return ret; } @@ -868,12 +850,15 @@ static int ipc_glb_tplg_buffer_new(uint32_t header) struct sof_ipc_comp_reply reply; int ret; - trace_ipc("ipc_glb_tplg_buffer_new()"); + trace_ipc("ipc: pipe %d buffer %d -> new (0x%x bytes)", + ipc_buffer->comp.pipeline_id, ipc_buffer->comp.id, + ipc_buffer->size); ret = ipc_buffer_new(_ipc, ipc_buffer); if (ret < 0) { - trace_ipc_error("ipc_glb_tplg_buffer_new() error: " - "ipc_buffer_new() failed."); + trace_ipc_error("ipc: pipe %d buffer %d creation failed %d", + ipc_buffer->comp.pipeline_id, + ipc_buffer->comp.id, ret); return ret; } @@ -892,19 +877,19 @@ static int ipc_glb_tplg_pipe_new(uint32_t header) struct sof_ipc_comp_reply reply; int ret; - trace_ipc("ipc_glb_tplg_pipe_new()"); + trace_ipc("ipc: pipe %d -> new", ipc_pipeline->pipeline_id); /* sanity check size */ if (IPC_INVALID_SIZE(ipc_pipeline)) { - trace_ipc_error("ipc_glb_tplg_pipe_new() error: Invalid size of" - " IPC"); + trace_ipc_error("ipc:_invalid IPC size 0x%x got 0x%x", + sizeof(*ipc_pipeline), ipc_pipeline->hdr.size); return -EINVAL; } ret = ipc_pipeline_new(_ipc, ipc_pipeline); if (ret < 0) { - trace_ipc_error("ipc_glb_tplg_pipe_new() error: " - "ipc_pipeline_new() failed."); + trace_ipc_error("ipc: pipe %d creation failed %d", + ipc_pipeline->pipeline_id, ret); return ret; } @@ -921,7 +906,7 @@ static int ipc_glb_tplg_pipe_complete(uint32_t header) { struct sof_ipc_pipe_ready *ipc_pipeline = _ipc->comp_data; - trace_ipc("ipc_glb_tplg_pipe_complete()"); + trace_ipc("ipc: pipe %d -> complete", ipc_pipeline->comp_id); return ipc_pipeline_complete(_ipc, ipc_pipeline->comp_id); } @@ -930,12 +915,13 @@ static int ipc_glb_tplg_comp_connect(uint32_t header) { struct sof_ipc_pipe_comp_connect *connect = _ipc->comp_data; - trace_ipc("ipc_glb_tplg_comp_connect()"); + trace_ipc("ipc: comp sink %d, source %d -> connect", + connect->sink_id, connect->source_id); /* sanity check size */ if (IPC_INVALID_SIZE(connect)) { - trace_ipc_error("ipc_glb_tplg_comp_connect() error: Invalid " - "size of IPC"); + trace_ipc_error("ipc:_invalid IPC size 0x%x got 0x%x", + sizeof(*connect), connect->hdr.size); return -EINVAL; } @@ -948,12 +934,12 @@ static int ipc_glb_tplg_free(uint32_t header, struct sof_ipc_free *ipc_free = _ipc->comp_data; int ret; - trace_ipc("ipc_glb_tplg_free()"); + trace_ipc("ipc: comp %d -> free", ipc_free->id); /* sanity check size */ if (IPC_INVALID_SIZE(ipc_free)) { - trace_ipc_error("ipc_glb_tplg_free() error: Invalid size of " - "IPC"); + trace_ipc_error("ipc:_invalid IPC size 0x%x got 0x%x", + sizeof(*ipc_free), ipc_free->hdr.size); return -EINVAL; } @@ -961,8 +947,8 @@ static int ipc_glb_tplg_free(uint32_t header, ret = free_func(_ipc, ipc_free->id); if (ret < 0) { - trace_ipc_error("ipc_glb_tplg_free() error: free_func() failed " - "with ret = %d", ret); + trace_ipc_error("ipc: comp %d free failed %d", + ipc_free->id, ret); } return ret; @@ -990,8 +976,7 @@ static int ipc_glb_tplg_message(uint32_t header) case iCS(SOF_IPC_TPLG_BUFFER_FREE): return ipc_glb_tplg_free(header, ipc_buffer_free); default: - trace_ipc_error("ipc_glb_tplg_message() error: Unknown command," - "header = %u", header); + trace_ipc_error("ipc: unknown tplg header %u", header); return -EINVAL; } } @@ -1007,7 +992,7 @@ int ipc_cmd(void) hdr = mailbox_validate(); if (hdr == NULL) { - trace_ipc_error("ipc_cmd() error: Missing IPC header."); + trace_ipc_error("ipc: invalid IPC header."); return -EINVAL; } @@ -1031,8 +1016,7 @@ int ipc_cmd(void) case iGS(SOF_IPC_GLB_TRACE_MSG): return ipc_glb_debug_message(hdr->cmd); default: - trace_ipc_error("ipc_cmd() error: Unknown command, type = %u", - type); + trace_ipc_error("ipc: unknown command type %u", type); return -EINVAL; } } @@ -1152,7 +1136,7 @@ int ipc_queue_host_message(struct ipc *ipc, uint32_t header, void *tx_data, msg = msg_get_empty(ipc); if (msg == NULL) { - trace_ipc_error("ipc_queue_host_message() error: header 0x08x " + trace_ipc_error("ipc: msg hdr for 0x08x not found " "replace %d", header, replace); ret = -EBUSY; goto out; diff --git a/src/ipc/hsw-ipc.c b/src/ipc/hsw-ipc.c index 344daa19a5aa..8a48d854d5fd 100644 --- a/src/ipc/hsw-ipc.c +++ b/src/ipc/hsw-ipc.c @@ -58,13 +58,13 @@ static void do_notify(void) uint32_t flags; struct ipc_msg *msg; - tracev_ipc("Not"); - spin_lock_irq(&_ipc->lock, flags); msg = _ipc->shared_ctx->dsp_msg; if (msg == NULL) goto out; + trace_ipc("ipc: not rx -> 0x%x", msg->header); + /* copy the data returned from DSP */ if (msg->rx_size && msg->rx_size < SOF_IPC_MSG_MAX_SIZE) mailbox_dspbox_read(msg->rx_data, 0, msg->rx_size); @@ -88,12 +88,13 @@ static void do_notify(void) static void irq_handler(void *arg) { uint32_t isr; - - tracev_ipc("IRQ"); + uint32_t msg = 0; /* Interrupt arrived, check src */ isr = shim_read(SHIM_ISRD); + tracev_ipc("ipc: irq isr 0x%x", isr); + if (isr & SHIM_ISRD_DONE) { /* Mask Done interrupt before return */ @@ -108,12 +109,17 @@ static void irq_handler(void *arg) shim_write(SHIM_IMRD, shim_read(SHIM_IMRD) | SHIM_IMRD_BUSY); interrupt_clear(PLATFORM_IPC_INTERRUPT); + msg = shim_read(SHIM_IPCX); + /* TODO: place message in Q and process later */ /* It's not Q ATM, may overwrite */ if (_ipc->host_pending) { - trace_ipc_error("Pen"); + trace_ipc_error("ipc: dropping msg 0x%x", msg); + trace_ipc_error(" isr 0x%x imrd 0x%x ipcx 0x%x", + isr, shim_read(SHIM_IMRD), + shim_read(SHIM_IPCX)); } else { - _ipc->host_msg = shim_read(SHIM_IPCX); + _ipc->host_msg = msg; _ipc->host_pending = 1; ipc_schedule_process(_ipc); } @@ -126,7 +132,7 @@ void ipc_platform_do_cmd(struct ipc *ipc) struct sof_ipc_reply reply; int32_t err; - tracev_ipc("Cmd"); + trace_ipc("ipc: msg rx -> 0x%x", ipc->host_msg); /* perform command and return any error */ err = ipc_cmd(); @@ -155,12 +161,9 @@ void ipc_platform_do_cmd(struct ipc *ipc) /* are we about to enter D3 ? */ if (iipc->pm_prepare_D3) { while (1) { - trace_ipc("pme"); wait_for_interrupt(0); } } - - tracev_ipc("CmD"); } void ipc_platform_send_msg(struct ipc *ipc) @@ -186,7 +189,7 @@ void ipc_platform_send_msg(struct ipc *ipc) mailbox_dspbox_write(0, msg->tx_data, msg->tx_size); list_item_del(&msg->list); ipc->shared_ctx->dsp_msg = msg; - tracev_ipc("Msg"); + tracev_ipc("ipc: msg tx -> 0x%x", msg->header); /* now interrupt host to tell it we have message sent */ shim_write(SHIM_IPCD, SHIM_IPCD_BUSY); diff --git a/src/ipc/pmc-ipc.c b/src/ipc/pmc-ipc.c index 9a60cfd25789..53517a0d622b 100644 --- a/src/ipc/pmc-ipc.c +++ b/src/ipc/pmc-ipc.c @@ -40,8 +40,6 @@ #include #include - - /* private data for IPC */ struct intel_ipc_pmc_data { uint32_t msg_l; @@ -49,7 +47,6 @@ struct intel_ipc_pmc_data { uint32_t pending; }; - static struct intel_ipc_pmc_data *_pmc; static void do_cmd(void) @@ -57,10 +54,8 @@ static void do_cmd(void) uint32_t ipcsc; uint32_t status = 0; - trace_ipc("SCm"); - trace_value(_pmc->msg_l); + trace_ipc("pmc: tx -> 0x%x", _pmc->msg_l); - //status = ipc_cmd(); _pmc->pending = 0; /* clear BUSY bit and set DONE bit - accept new messages */ @@ -73,7 +68,6 @@ static void do_cmd(void) shim_write(SHIM_IMRLPESC, shim_read(SHIM_IMRLPESC) & ~SHIM_IMRLPESC_BUSY); } - /* process current message */ int pmc_process_msg_queue(void) { @@ -84,7 +78,7 @@ int pmc_process_msg_queue(void) static void do_notify(void) { - trace_ipc("SNo"); + trace_ipc("pmc: not rx"); /* clear DONE bit */ shim_write(SHIM_IPCLPESCH, shim_read(SHIM_IPCLPESCH) & ~SHIM_IPCLPESCH_DONE); @@ -97,11 +91,11 @@ static void irq_handler(void *arg) { uint32_t isrlpesc; - trace_ipc("SIQ"); - /* Interrupt arrived, check src */ isrlpesc = shim_read(SHIM_ISRLPESC); + tracev_ipc("pmc: irq isrlpesc 0x%x", isrlpesc); + if (isrlpesc & SHIM_ISRLPESC_DONE) { /* Mask Done interrupt before return */ @@ -128,13 +122,13 @@ int ipc_pmc_send_msg(uint32_t message) uint32_t ipclpesch; int ret; - trace_ipc("SMs"); + tracev_ipc("pmc: msg tx -> 0x%x", message); ipclpesch = shim_read(SHIM_IPCLPESCH); /* we can only send new messages if the SC is not busy */ if (ipclpesch & SHIM_IPCLPESCH_BUSY) { - trace_ipc_error("ePb"); + trace_ipc_error("pmc: busy 0x%x", ipclpesch); return -EAGAIN; } @@ -149,7 +143,7 @@ int ipc_pmc_send_msg(uint32_t message) /* did command succeed */ if (ret < 0) { - trace_ipc_error("ePf"); + trace_ipc_error("pmc: command 0x%x failed", message); return -EINVAL; } diff --git a/src/ipc/sue-ipc.c b/src/ipc/sue-ipc.c index 3c6718922ea0..f089b35530cf 100644 --- a/src/ipc/sue-ipc.c +++ b/src/ipc/sue-ipc.c @@ -65,7 +65,7 @@ void ipc_platform_do_cmd(struct ipc *ipc) struct sof_ipc_reply reply; int32_t err; - trace_ipc("Cmd"); + trace_ipc("ipc: msg rx -> 0x%x", ipc->host_msg); /* perform command and return any error */ err = ipc_cmd(); @@ -93,8 +93,6 @@ void ipc_platform_do_cmd(struct ipc *ipc) while (1) wait_for_interrupt(0); } - - tracev_ipc("CmD"); } void ipc_platform_send_msg(struct ipc *ipc) @@ -116,7 +114,7 @@ void ipc_platform_send_msg(struct ipc *ipc) mailbox_dspbox_write(0, msg->tx_data, msg->tx_size); list_item_del(&msg->list); ipc->shared_ctx->dsp_msg = msg; - tracev_ipc("Msg"); + tracev_ipc("ipc: msg tx -> 0x%x", msg->header); /* now interrupt host to tell it we have message sent */ From 2183aede833580c8b8da2c3eeb590379420fe873 Mon Sep 17 00:00:00 2001 From: Liam Girdwood Date: Thu, 15 Nov 2018 20:34:51 +0000 Subject: [PATCH 2/2] ipc: Fix false positive IPC dropped messages. On receiving an IPC IRQ the handler currently does not check the IRQ mask. This means notification received ACKs (i.e. for trace updates) from the host may be reported as duplicate host command IPCs. Fix this by checking IPC IRQ mask. Signed-off-by: Liam Girdwood --- src/ipc/apl-ipc.c | 9 ++++++--- src/ipc/cnl-ipc.c | 9 ++++++--- 2 files changed, 12 insertions(+), 6 deletions(-) diff --git a/src/ipc/apl-ipc.c b/src/ipc/apl-ipc.c index 79eb8da5530a..3d28616b504b 100644 --- a/src/ipc/apl-ipc.c +++ b/src/ipc/apl-ipc.c @@ -59,18 +59,21 @@ static void irq_handler(void *arg) { uint32_t dipct; uint32_t dipcie; + uint32_t dipcctl; uint32_t msg = 0; dipct = ipc_read(IPC_DIPCT); dipcie = ipc_read(IPC_DIPCIE); + dipcctl = ipc_read(IPC_DIPCCTL); - tracev_ipc("ipc: irq dipct 0x%x dipcie 0x%x", dipct, dipcie); + tracev_ipc("ipc: irq dipct 0x%x dipcie 0x%x dipcctl 0x%x", dipct, + dipcie, dipcctl); /* new message from host */ - if (dipct & IPC_DIPCT_BUSY) { + if (dipct & IPC_DIPCT_BUSY && dipcctl & IPC_DIPCCTL_IPCTBIE) { /* mask Busy interrupt */ - ipc_write(IPC_DIPCCTL, ipc_read(IPC_DIPCCTL) & ~IPC_DIPCCTL_IPCTBIE); + ipc_write(IPC_DIPCCTL, dipcctl & ~IPC_DIPCCTL_IPCTBIE); msg = dipct & IPC_DIPCT_MSG_MASK; diff --git a/src/ipc/cnl-ipc.c b/src/ipc/cnl-ipc.c index 33042c1efab7..9d5165a6064a 100644 --- a/src/ipc/cnl-ipc.c +++ b/src/ipc/cnl-ipc.c @@ -60,18 +60,21 @@ static void irq_handler(void *arg) { uint32_t dipctdr; uint32_t dipcida; + uint32_t dipcctl; uint32_t msg = 0; dipctdr = ipc_read(IPC_DIPCTDR); dipcida = ipc_read(IPC_DIPCIDA); + dipcctl = ipc_read(IPC_DIPCCTL); - tracev_ipc("ipc: irq dipctdr 0x%x dipcida 0x%x", dipctdr, dipcida); + tracev_ipc("ipc: irq dipct 0x%x dipcie 0x%x dipcctl 0x%x", dipct, + dipcie, dipcctl); /* new message from host */ - if (dipctdr & IPC_DIPCTDR_BUSY) { + if (dipctdr & IPC_DIPCTDR_BUSY && dipcctl & IPC_DIPCCTL_IPCTBIE) { /* mask Busy interrupt */ - ipc_write(IPC_DIPCCTL, ipc_read(IPC_DIPCCTL) & ~IPC_DIPCCTL_IPCTBIE); + ipc_write(IPC_DIPCCTL, dipcctl & ~IPC_DIPCCTL_IPCTBIE); msg = dipctdr & IPC_DIPCTDR_MSG_MASK;