Skip to content

KWD: Sometimes wait for buffer empty timeout issue happens during draining #1406

Closed
Closed
KWD: Sometimes wait for buffer empty timeout issue happens during draining#1406
Assignees
mrajwa
Labels
GLKApplies to Gemini Lake platformKeyword DetectionApplies to Keyword DetectionbugSomething isn't working as expected

Description

@keyonjie
keyonjie
opened on May 10, 2019

Describe the bug
Sometimes wait for buffer empty timeout issue happens during draining, especially when dma trace is more verbos.

To Reproduce

  1. run KWD capture pipeline:
    arecord -Dhw:0,8 -M -N -c 2 -f S16_LE -r 16000 tmp.wav
  2. clap your hands.

Expected behavior
keyword is detected and keyword data is draining, PCM will start to get captured data from FW.

Impact
The capture pipeline can't get any data recorded and FW KWD pipeline is hang with "wait for buffer empty timeout" issue happened in FW.

Environment

  1. Linux:
    https://github.com/thesofproject/linux/tree/topic/sof-dev
    FW:
    https://github.com/thesofproject/sof/tree/master
    (+ PR#1365)

  2. Name of the topology file
    Tplg file: sof-glk-da7219-kwd.tplg (need rename it to be sof-glk-da7219.tplg)

  3. Name of the platform(s) on which the bug is observed.
    GLK Ubuntu.

  4. Reproducibility Rate.
    About 10%.

Screenshots or console output

^Croot@test-Bobba:~# ./log_e 
 CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME	CONTENT
    0      1          MEM          21319261.197917  21319262.000000      src/lib/alloc.c:271 	error: 342 blocks needed for allocation but only 341 blocks are remaining
    0      1          DMA          96208970.937500      3115.937500 intel/cavs/hda-dma.c:297 	hda-dmac: 4 wait for buffer empty timeout
    0      1         HOST          96208976.822917         5.885417     src/audio/host.c:494 	host_buffer_cb() error: dma_copy() failed, ret = 4294967234

Activity

  1. keyonjie
    added
    bugSomething isn't working as expected
    on May 10, 2019

  2. tlauda commented on May 10, 2019

    @tlauda
    tlauda
    on May 10, 2019
    Contributor

    @keyonjie Draining is done on passive level, so the only potential problem I can see is preemption in hda_dma_wait_for_buffer_empty(). If it happens at the wrong time, we can throw an error without even checking the BNE value.

    Check with this change:

    diff --git a/src/drivers/intel/cavs/hda-dma.c b/src/drivers/intel/cavs/hda-dma.c
index 24e435a..611f0d4 100644
--- a/src/drivers/intel/cavs/hda-dma.c
+++ b/src/drivers/intel/cavs/hda-dma.c
@@ -293,6 +293,9 @@ static int hda_dma_wait_for_buffer_empty(struct dma *dma,
 
        while (host_dma_reg_read(dma, chan->index, DGCS) & DGCS_BNE) {
                if (deadline < platform_timer_get(platform_timer)) {
+                       if (!(host_dma_reg_read(dma, chan->index, DGCS) & DGCS_BNE))
+                               return 0;
+
                        trace_hddma_error("hda-dmac: %d wait for buffer empty "
                                          "timeout", dma->plat_data.id);
                        return -ETIME;
  3. wenqingfu
    assigned
    mrajwa
    on May 13, 2019

  4. keyonjie commented on May 14, 2019

    @keyonjie
    keyonjie
    on May 14, 2019
    ContributorAuthor

    PR#1415 help?

  5. mengdonglin commented on May 14, 2019

    @mengdonglin
    mengdonglin
    on May 14, 2019
    Collaborator

    @keqiaozhang please verify #1415

  6. keqiaozhang commented on May 14, 2019

    @keqiaozhang
    keqiaozhang
    on May 14, 2019
    Collaborator

    no above trace error with PR #1415 . But I run into below new error:

     CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME    CONTENT
    0      1          MEM             53060.208333     53060.207031      src/lib/alloc.c:271    error: 342 blocks needed for allocation but only 341 blocks are remaining
    0      1         COMP           7005958.020833   6952898.000000 rc/audio/component.c:161    comp_set_state() error: wrong state = 1, COMP_TRIGGER_STOP
    0      1          IPC           7005964.375000         6.354167 src/audio/pipeline.c:606    pipeline_trigger() error: ret = -22, host->comp.id = 57, cmd = 0
    0      1          IPC           7005970.989583         6.614583    src/ipc/handler.c:513    ipc: comp 57 trigger 0x50000 failed -22

    dmesg：

    [   62.922911] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[   62.923015] sof-audio-pci 0000:00:0e.0: error: ipc error for 0x60050000 size 12
[   62.923019] sof-audio-pci 0000:00:0e.0: error: failed to trigger DETECT9.0
[   62.923021] sof-audio-pci 0000:00:0e.0: error: failed to trigger widget DETECT9.0

  7. tlauda commented on May 14, 2019

    @tlauda
    tlauda
    on May 14, 2019
    Contributor

    @keqiaozhang Please fill the separate issue for the new finding.

  8. keqiaozhang commented on May 14, 2019

    @keqiaozhang
    keqiaozhang
    on May 14, 2019
    Collaborator

    @keqiaozhang Please fill the separate issue for the new finding.

    Please refer to #1423

  9. keyonjie commented on May 14, 2019

    @keyonjie
    keyonjie
    on May 14, 2019
    ContributorAuthor

    @tlauda I still seeing occasional "wait for buffer empty timeout" issue in my KWD capture draining case, after applied PR #1415

  10. tlauda commented on May 14, 2019

    @tlauda
    tlauda
    on May 14, 2019
    Contributor

    @keyonjie Could you try also with #1426? It seems that APL needs longer time to fully exit L1.

  11. keyonjie commented on May 15, 2019

    @keyonjie
    keyonjie
    on May 15, 2019
    ContributorAuthor

    @tlauda looks #1426 can improve it, still seeing the issue with lower reproduce rate.

  12. tlauda commented on May 15, 2019

    @tlauda
    tlauda
    on May 15, 2019
    Contributor

    @keyonjie Could you try with L1SEN = 0? It can be set on the host side.

  13. keyonjie commented on May 16, 2019

    @keyonjie
    keyonjie
    on May 16, 2019
    ContributorAuthor

    @tlauda sorry, don't get you with L1SEN = 0. Are you meaning FDHDL1E bit in SVCFG?

  14. keyonjie commented on May 16, 2019

    @keyonjie
    keyonjie
    on May 16, 2019
    ContributorAuthor

    Once the issue happened, if we try to run "arecord" again, DSP panic from FW:

    [ 1755.323488] sof-audio-pci 0000:00:0e.0: pcm: free stream 8 dir 1
[ 1755.323495] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 1755.625662] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60030000 size 12
[ 1755.625669] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[ 1755.625706] sof-audio-pci 0000:00:0e.0: error: runtime exception
[ 1755.625708] sof-audio-pci 0000:00:0e.0: error: trace point 00004000
[ 1755.625709] sof-audio-pci 0000:00:0e.0: error: panic at :-1106773600
[ 1755.625712] sof-audio-pci 0000:00:0e.0: error: DSP Firmware Oops
[ 1755.625714] sof-audio-pci 0000:00:0e.0: EXCCAUSE 0x00000180 EXCVADDR 0xc3f3fbfe PS       0x1544813c SAR     0x00060720
[ 1755.625716] sof-audio-pci 0000:00:0e.0: EPC1     0x00000040 EPC2     0x0000017c EPC3     0xbe07f9d0 EPC4    0x0000000d
[ 1755.625718] sof-audio-pci 0000:00:0e.0: EPC5     0x00000000 EPC6     0x00060025 EPC7     0xbe02a11c DEPC    0x00060f20
[ 1755.625720] sof-audio-pci 0000:00:0e.0: EPS2     0xbe01c05d EPS3     0xbe0288e4 EPS4     0x00000000 EPS5    0xbe02b764
[ 1755.625722] sof-audio-pci 0000:00:0e.0: EPS6     0x00000000 EPS7     0x00000000 INTENABL 0x00060522 INTERRU 0x00000000
[ 1755.625723] sof-audio-pci 0000:00:0e.0: stack dump from 0x00000000
[ 1755.625727] sof-audio-pci 0000:00:0e.0: 0x00000000: be00a81c 00060025 be00a828 00be07f9
[ 1755.625729] sof-audio-pci 0000:00:0e.0: 0x00000004: 00000004 00000001 00000310 be001160
[ 1755.625732] sof-audio-pci 0000:00:0e.0: 0x00000008: 3530ee00 6f1c2456 392333e8 ffff8a23
[ 1755.625734] sof-audio-pci 0000:00:0e.0: 0x0000000c: 049f5b00 ffff8a23 b6ca1910 ffffffff
[ 1755.625736] sof-audio-pci 0000:00:0e.0: 0x00000010: c1d97be0 ffff910d c1d97bec ffff910d
[ 1755.625738] sof-audio-pci 0000:00:0e.0: 0x00000014: 386ee828 ffff8a23 38b84400 ffff8a23
[ 1755.625740] sof-audio-pci 0000:00:0e.0: 0x00000018: 38a3eeb8 ffff8a23 00000000 00000000
[ 1755.625743] sof-audio-pci 0000:00:0e.0: 0x0000001c: 38a3e818 ffff8a23 c02e4d91 ffffffff
[ 1755.625746] sof-audio-pci 0000:00:0e.0: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 1755.625748] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[ 1755.637890] sof-audio-pci 0000:00:0e.0: pcm: close stream 8 dir 1
[ 1755.638037] sof-audio-pci 0000:00:0e.0: received event 4 for widget DETECT9.0

  15. keyonjie commented on May 16, 2019

    @keyonjie
    keyonjie
    on May 16, 2019
    ContributorAuthor

    I tried non-blocking mode also, though we won't log out "wait for buffer empty timeout", the FW will hang and there is SA warning in error log:

    root@test-Bobba:~# ./log_e 
 CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME	CONTENT
    0      1          MEM             52381.666667     52381.667969      src/lib/alloc.c:271 	error: 342 blocks needed for allocation but only 341 blocks are remaining
    0      2           SA           6750226.354167   6697844.500000      src/lib/agent.c:74  	validate(), idle longer than timeout, delta = 20505534

  16. 9 remaining items

  17. keyonjie commented on May 22, 2019

    @keyonjie
    keyonjie
    on May 22, 2019
    ContributorAuthor

    On FW side, patch here:

    diff --git a/src/audio/host.c b/src/audio/host.c
index 9b85d931..6effe5c1 100644
--- a/src/audio/host.c
+++ b/src/audio/host.c
@@ -168,7 +168,7 @@ static void host_dma_cb(void *data, uint32_t type, struct dma_sg_elem *next)
                hd->local_pos = 0;
 
        /* NO_IRQ mode if host_period_size == 0 */
-       if (dev->params.host_period_bytes != 0) {
+       if (dev->params.no_ipc_position != 0) {
                hd->report_pos += bytes;
 
                /* send IPC message to driver if needed */
diff --git a/src/audio/kpb.c b/src/audio/kpb.c
index 62cdbe62..bd64168e 100644
--- a/src/audio/kpb.c
+++ b/src/audio/kpb.c
@@ -41,6 +41,7 @@
 #include <sof/ipc.h>
 #include <sof/audio/component.h>
 #include <sof/audio/kpb.h>
+#include <sof/clk.h>
 #include <sof/list.h>
 #include <sof/audio/buffer.h>
 #include <sof/ut.h>
@@ -61,6 +62,7 @@ struct comp_data {
        bool is_internal_buffer_full;
        size_t buffered_data;
        struct dd draining_task_data;
+       uint32_t draining_interval; /**< interval delay between each copies */
 };
 
 /*! KPB private functions */
@@ -336,8 +338,6 @@ static int kpb_prepare(struct comp_dev *dev)
        struct comp_data *cd = comp_get_drvdata(dev);
        int ret = 0;
        int i;
-       struct list_item *blist;
-       struct comp_buffer *sink;
 
        trace_kpb("kpb_prepare()");
 
@@ -380,26 +380,6 @@ static int kpb_prepare(struct comp_dev *dev)
                           0, /* core on which we should run */
                           0); /* not used flags */
 
-       /* Search for KPB related sinks.
-        * NOTE! We assume here that channel selector component device
-        * is connected to the KPB sinks as well as host device.
-        */
-       list_for_item(blist, &dev->bsink_list) {
-               sink = container_of(blist, struct comp_buffer, source_list);
-
-               if (!sink->sink) {
-                       ret = -EINVAL;
-                       break;
-               }
-               if (sink->sink->comp.type == SOF_COMP_SELECTOR) {
-                       /* We found proper real time sink */
-                       cd->sel_sink = sink;
-               } else if (sink->sink->comp.type == SOF_COMP_HOST) {
-                       /* We found proper host sink */
-                       cd->host_sink = sink;
-               }
-       }
-
        return ret;
 }
 
@@ -418,6 +398,46 @@ static int kpb_cmd(struct comp_dev *dev, int cmd, void *data,
        return ret;
 }
 
+
+/**
+ * \brief Sets kpb component audio stream parameters.
+ * \return Error code.
+ */
+static int kpb_params(struct comp_dev *dev)
+{
+       struct comp_data *cd = comp_get_drvdata(dev);
+       struct list_item *blist;
+       struct comp_buffer *sink;
+
+       trace_kpb_error("kpb_params()");
+
+       /* Search for KPB related sinks.
+        * NOTE! We assume here that channel selector component device
+        * is connected to the KPB sinks as well as host device.
+        */
+       list_for_item(blist, &dev->bsink_list) {
+               sink = container_of(blist, struct comp_buffer, source_list);
+
+               if (!sink->sink)
+                       return -EINVAL;
+
+               if (sink->sink->comp.type == SOF_COMP_SELECTOR) {
+                       /* We found proper real time sink */
+                       cd->sel_sink = sink;
+               } else if (sink->sink->comp.type == SOF_COMP_HOST) {
+                       /* We found proper host sink */
+                       cd->host_sink = sink;
+               }
+       }
+
+       cd->draining_interval = KPB_APP_INTERVAL * cd->host_sink->size *
+                               KPB_APP_INTERVAL_TIMES /
+                               dev->params.host_period_bytes;
+       cd->draining_interval = clock_ms_to_ticks(PLATFORM_DEFAULT_CLOCK,
+                                                 (500 + cd->draining_interval) / 1000);
+       return 0;
+}
+
 static void kpb_cache(struct comp_dev *dev, int cmd)
 {
        /* TODO: writeback history buffer */
@@ -816,6 +836,7 @@ static uint64_t kpb_draining_task(void *arg)
        struct dd *draining_data = (struct dd *)arg;
        struct comp_buffer *sink = draining_data->sink;
        struct hb *buff = draining_data->history_buffer;
+       struct comp_data *kpb = container_of(draining_data,struct comp_data, draining_task_data);
        size_t history_depth = draining_data->history_depth;
        size_t size_to_read;
        size_t size_to_copy;
@@ -855,6 +876,7 @@ static uint64_t kpb_draining_task(void *arg)
                }
                if (size_to_copy)
                        comp_update_buffer_produce(sink, size_to_copy);
+               wait_delay(kpb->draining_interval);
        }
 
        /* Draining is done. Now switch KPB to copy real time stream
@@ -973,7 +995,7 @@ struct comp_driver comp_kpb = {
                .prepare = kpb_prepare,
                .reset = kpb_reset,
                .cache = kpb_cache,
-               .params = NULL,
+               .params = kpb_params,
        },
 };
 
diff --git a/src/include/sof/audio/kpb.h b/src/include/sof/audio/kpb.h
index c5859a4f..e68c083e 100644
--- a/src/include/sof/audio/kpb.h
+++ b/src/include/sof/audio/kpb.h
@@ -57,6 +57,11 @@
 #define KPB_ALLOCATION_STEP 0x100
 #define KPB_NO_OF_MEM_POOLS 3
 
+/**< average interval b/w copies for application, in ms */
+#define KPB_APP_INTERVAL 100
+/**< delay times to avoid overrun for draining */
+#define KPB_APP_INTERVAL_TIMES 40
+
 enum kpb_state {
        KPB_STATE_BUFFERING = 0,
        KPB_STATE_DRAINING_ON_DEMAND,
diff --git a/src/include/uapi/ipc/stream.h b/src/include/uapi/ipc/stream.h
index 6a8b21de..7220c984 100644
--- a/src/include/uapi/ipc/stream.h
+++ b/src/include/uapi/ipc/stream.h
@@ -113,10 +113,11 @@ struct sof_ipc_stream_params {
        uint16_t sample_valid_bytes;
        uint16_t sample_container_bytes;
 
-       /* for notifying host period has completed - 0 means no period IRQ */
+       /* for notifying host period has completed */
        uint32_t host_period_bytes;
+       uint32_t no_ipc_position; /* 1 means no period IRQ */
 
-       uint32_t reserved[2];
+       uint32_t reserved[1];
        uint16_t chmap[SOF_IPC_MAX_CHANNELS];   /**< channel map - SOF_CHMAP_ */
 } __attribute__((packed));

  18. keyonjie commented on May 22, 2019

    @keyonjie
    keyonjie
    on May 22, 2019
    ContributorAuthor

    It might require kernel and ABI changes also, here it's my patch for that:

    diff --git a/include/sound/sof/stream.h b/include/sound/sof/stream.h
index 643f175cb479..097111061470 100644
--- a/include/sound/sof/stream.h
+++ b/include/sound/sof/stream.h
@@ -83,10 +83,11 @@ struct sof_ipc_stream_params {
        uint16_t sample_valid_bytes;
        uint16_t sample_container_bytes;
 
-       /* for notifying host period has completed - 0 means no period IRQ */
+       /* for notifying host period has completed */
        uint32_t host_period_bytes;
+       uint32_t no_ipc_position; /* 1 means no period IRQ */
 
-       uint32_t reserved[2];
+       uint32_t reserved[1];
        uint16_t chmap[SOF_IPC_MAX_CHANNELS];   /**< channel map - SOF_CHMAP_ */
 } __packed;
 
diff --git a/sound/soc/sof/intel/hda-pcm.c b/sound/soc/sof/intel/hda-pcm.c
index 9b730f183529..ae072403c6fe 100644
--- a/sound/soc/sof/intel/hda-pcm.c
+++ b/sound/soc/sof/intel/hda-pcm.c
@@ -118,7 +118,7 @@ int hda_dsp_pcm_hw_params(struct snd_sof_dev *sdev,
 
        /* set host_period_bytes to 0 if no IPC position */
        if (hda && hda->no_ipc_position)
-               ipc_params->host_period_bytes = 0;
+               ipc_params->no_ipc_position = 0;
 
        ipc_params->stream_tag = hstream->stream_tag;

  19. mrajwa commented on May 22, 2019

    @mrajwa
    mrajwa
    on May 22, 2019
    Contributor

    Slowing down draining is an option but opens up another issue - we may be catched by real time copy before history buffer is emptied completely. Therefore a more advanced solution is needed. I am working on it now.

  20. keyonjie commented on May 23, 2019

    @keyonjie
    keyonjie
    on May 23, 2019
    ContributorAuthor

    @mmaka1 if you have went though the patches I pasted above, it doesn't slow down the draining necessarily, it depends on the size of host_period_bytes to decide whether to slow down and how much we should slow it down. But I am open if you have advanced solution to fix that.

  21. jajanusz commented on Jun 7, 2019

    @jajanusz
    jajanusz
    on Jun 7, 2019
    Contributor

    @mrajwa @keyonjie @tlauda Is it still a problem?

  22. mengdonglin commented on Jun 14, 2019

    @mengdonglin
    mengdonglin
    on Jun 14, 2019
    Collaborator

    @keyonjie @keqiaozhang @tlauda Is this issue also fixed by PR #1546 ?

  23. tlauda commented on Jun 14, 2019

    @tlauda
    tlauda
    on Jun 14, 2019
    Contributor

    @mengdonglin No.

  24. mrajwa commented on Jun 14, 2019

    @mrajwa
    mrajwa
    on Jun 14, 2019
    Contributor

    @mengdonglin, @tlauda this issue is fixed by:
    https://github.com/mrajwa/sof/commits/cml-005-drop-stable [FW]
    thesofproject/linux#1037 [Kernel]

  25. mengdonglin
    added
    GLKApplies to Gemini Lake platform
    on Jun 14, 2019

  26. keqiaozhang commented on Jun 17, 2019

    @keqiaozhang
    keqiaozhang
    on Jun 17, 2019
    Collaborator

    @mrajwa
    I tested above recipe on GLK Chromebook, but I run to DSP panic after draining, The reproduction rate is 100%.

    console output

    localhost ~ # arecord -M -N -D hw:0,8 -f s16_le -c 2 -r 16000 record.wav -d 10 -vvv
Recording WAVE 'record.wav' : Signed 16 bit Little Endian, Rate 16000 Hz, Stereo
Hardware PCM card 0 'sof-glkda7219max' device 8 subdevice 0
Its setup is:
  stream       : CAPTURE
  access       : MMAP_INTERLEAVED
  format       : S16_LE
  subformat    : STD
  channels     : 2
  rate         : 16000
  exact rate   : 16000 (16000/1)
  msbits       : 16
  buffer_size  : 8016
  period_size  : 2016
  period_time  : 126000
  tstamp_mode  : NONE
  tstamp_type  : MONOTONIC
  period_step  : 1
  avail_min    : 2016
  period_event : 0
  start_threshold  : 1
  stop_threshold   : 8016
  silence_threshold: 0
  silence_size : 0
  boundary     : 9025213653250473984
  appl_ptr     : 0
  hw_ptr       : 0
mmap_area[0] = 0x7db352484000,0,32 (16)
mmap_area[1] = 0x7db352484000,16,32 (16)
overrun!!! (at least 0.051 ms long)
Status:
  state       : XRUN
  trigger_time: 107.585440
  tstamp      : 0.000000
  delay       : 0
  avail       : 8656
  avail_max   : 8656
Max peak (3200 samples): 0x00000094 #                    0%
Max peak (832 samples): 0x00000014 #                    0%
Max peak (448 samples): 0x00000038 #                    0%

    dmesg

    [    7.972807] sof-audio-pci 0000:00:0e.0: firmware boot complete
[    8.842286] Bluetooth: sock.c:rfcomm_init_sockets() RFCOMM socket layer initialized
[    8.842334] Bluetooth: core.c:rfcomm_init() RFCOMM ver 1.11
[   13.401715] binder: 4069:4069 ioctl 4018620d 7ffef2a4ff20 returned -22
[   15.759224] capability: warning: `main' uses 32-bit capabilities (legacy support in use)
[  103.780627] sof-audio-pci 0000:00:0e.0: firmware boot complete
[  108.978676] sof-audio-pci 0000:00:0e.0: error : DSP panic!
[  108.978709] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[  108.978914] sof-audio-pci 0000:00:0e.0: error: runtime exception
[  108.978916] sof-audio-pci 0000:00:0e.0: error: trace point 00004000
[  108.978918] sof-audio-pci 0000:00:0e.0: error: panic at :-1106851504
[  108.978921] sof-audio-pci 0000:00:0e.0: error: DSP Firmware Oops
[  108.978924] sof-audio-pci 0000:00:0e.0: EXCCAUSE 0x0000017c EXCVADDR 0xc3f3fbfe PS       0x1544813c SAR     0x00060f20
[  108.978927] sof-audio-pci 0000:00:0e.0: EPC1     0x00000040 EPC2     0x000001a8 EPC3     0xbe06c980 EPC4    0x0000000d
[  108.978929] sof-audio-pci 0000:00:0e.0: EPC5     0x00000000 EPC6     0x00060025 EPC7     0xbe02c212 DEPC    0x00060f20
[  108.978932] sof-audio-pci 0000:00:0e.0: EPS2     0xbe020a02 EPS3     0xbe020a02 EPS4     0x00000000 EPS5    0xbe020a02
[  108.978934] sof-audio-pci 0000:00:0e.0: EPS6     0x00000000 EPS7     0x00000000 INTENABL 0x00060f20 INTERRU 0x00000000
[  108.978937] sof-audio-pci 0000:00:0e.0: stack dump from 0x00000000
[  108.978941] sof-audio-pci 0000:00:0e.0: 0x00000000: be00a81c 00060025 be00a828 00be06c9
[  108.978944] sof-audio-pci 0000:00:0e.0: 0x00000004: 00000002 00000001 00000328 00000014
[  108.978946] sof-audio-pci 0000:00:0e.0: 0x00000008: 00000000 00000000 00000000 00000222
[  108.978949] sof-audio-pci 0000:00:0e.0: 0x0000000c: 49c4e028 ffff8bbc 00000000 00000000
[  108.978952] sof-audio-pci 0000:00:0e.0: 0x00000010: 0dead000 00000000 42f33e80 ffffa55c
[  108.978955] sof-audio-pci 0000:00:0e.0: 0x00000014: 42f33ea8 ffffa55c ab13517d ffffffff
[  108.978957] sof-audio-pci 0000:00:0e.0: 0x00000018: 00000000 00000000 ab1351a2 ffffffff
[  108.978960] sof-audio-pci 0000:00:0e.0: 0x0000001c: 42f33f48 ffffa55c ab0fcb71 ffffffff
[  108.978962] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers

    trace
    No obvious trace errors, the trace logs are attached.
    logger.log
    logger-t.log
    dmesg.log

    test recipe
    Kernel: cros-sof-v4.14-rebase/18a233 +PR1037
    SOF/TPLG: https://github.com/mrajwa/sof/commits/cml-005-drop-stable
    Platform: GLK-Chromebook/ChromeOS

  27. YvonneYang2 commented on Jun 18, 2019

    @YvonneYang2
    YvonneYang2
    on Jun 18, 2019

    Tested on GLK Chromebook with test recipe as below. Not found DSP panic in dmesg log but console showed Xrun alert info, and arecored failed.

    test recipe
    Kernel: https://github.com/thesofproject/linux/tree/topic/keyword_detect 9c95e6f +PR1037
    SOF/TPLG: https://github.com/mrajwa/sof/commits/cml-005-drop-stable
    Platform: GLK-Chromebook/ChromeOS

    frequency
    8/10

    console

      hw_ptr       : 0
mmap_area[0] = 0x7f6c3e6d4000,0,32 (16)
mmap_area[1] = 0x7f6c3e6d4000,16,32 (16)
overrun!!! (at least 0.017 ms long)
Status:
  state       : XRUN
  trigger_time: 43.890591523
  tstamp      : 0.000000
  delay       : 0
  avail       : 8656
  avail_max   : 8656

    logger

        0      2          DMA          40775389.531250         5.312500 intel/cavs/hda-dma.c:635 	hda-dmac: 5 channel 0 -> stop
    0      2       VOLUME          40775395.156250         5.625000 udio/volume/volume.c:521 	volume_trigger()
    0      2          DAI 1.5      40775400.052083         4.895833      src/audio/dai.c:470 	dai_comp_trigger(), command = 0
    0      2          DAI 1.5      40775404.531250         4.479167      src/audio/dai.c:534 	dai_comp_trigger(), PAUSE/STOP
    0      2          DMA          40775408.802083         4.270833 src/drivers/dw/dma.c:442 	dw_dma_stop(): dma 0 channel 0 stop
    0      2          SSP          40775419.895833        11.093750 ers/intel/cavs/ssp.c:798 	ssp_trigger() cmd 0
    0      2          SSP          40775469.114583        49.218750 ers/intel/cavs/ssp.c:779 	ssp_stop(), TX stop
    0      2          SSP          40775474.427083         5.312500 ers/intel/cavs/ssp.c:788 	ssp_stop(), SSP port disabled
    0      2          IPC          40775635.000000       160.572922    src/ipc/handler.c:328 	ipc: comp 1 -> free
    0      2         PIPE 1.6      40775640.312500         5.312500 src/audio/pipeline.c:683 	pipeline_reset()
    0      2         HOST          40775645.104167         4.791667     src/audio/host.c:679 	host_reset()
    0      2       VOLUME          40775653.229167         8.125000 udio/volume/volume.c:662 	volume_reset()
    0      2          DAI 1.5      40775657.968750         4.739583      src/audio/dai.c:448 	dai_reset()
    0      2      unknown          43805274.427083   3029616.500000 /audio/detect_test.c:75  	notify_host()
    0      2      unknown          43805282.864583         8.437500 /audio/detect_test.c:87  	notify_kpb(), preamble: 0
    0      2          KPB          43805289.218750         6.354167      src/audio/kpb.c:607 	kpb_event_handler(): received event with ID: 2 
    0      2          KPB          43805294.218750         5.000000      src/audio/kpb.c:701 	kpb_init_draining() host buff size: 32064 period size 2016, ticks_per_ms 19200
    0      1          KPB          43805299.479167         5.260417      src/audio/kpb.c:781 	kpb_init_draining(), period_limit: 16032 [bytes] and interval 2000 [uS] 38400 ticks 
    0      2          KPB          43805320.729167        21.250000      src/audio/kpb.c:833 	kpb_draining_task(), start.
    0      2          KPB          43805327.343750         6.614583      src/audio/kpb.c:916 	kpb_draining_task(), done. 0 drained in 0 ms.
    0      2       BUFFER          43825291.197917     19963.853516   src/audio/buffer.c:94  	comp_update_buffer_produce(), no bytes to produce
    0      2       BUFFER          43825296.510417         5.312500   src/audio/buffer.c:168 	comp_update_buffer_consume(), no bytes to consume
    0      2       BUFFER          43825301.302083         4.791667   src/audio/buffer.c:168 	comp_update_buffer_consume(), no bytes to consume
    0      2       BUFFER          43845300.052083     19998.750000   src/audio/buffer.c:94  	comp_update_buffer_produce(), no bytes to produce
    0      2       BUFFER          43845305.833333         5.781250   src/audio/buffer.c:168 	comp_update_buffer_consume(), no bytes to consume
    0      2       BUFFER          43845310.833333         5.000000   src/audio/buffer.c:168 	comp_update_buffer_consume(), no bytes to consume
    0      2          IPC          43845921.145833       610.312500    src/ipc/handler.c:439 	ipc: comp 50 -> trigger cmd 0x50000
    0      2         PIPE 8.55     43845944.479167        23.333334 src/audio/pipeline.c:604 	pipeline_trigger()
    0      2         HOST          43845949.843750         5.364583     src/audio/host.c:263 	host_trigger()
    0      2          DMA          43845955.104167         5.260417 intel/cavs/hda-dma.c:635 	hda-dmac: 4 channel 1 -> stop
    0      2          KPB          43845960.885417         5.781250      src/audio/kpb.c:317 	kpb_trigger()
    0      2          DAI 8.54     43845965.885417         5.000000      src/audio/dai.c:470 	dai_comp_trigger(), command = 0
    0      2          DAI 8.54     43845970.260417         4.375000      src/audio/dai.c:534 	dai_comp_trigger(), PAUSE/STOP
    0      2          DMA          43845974.687500         4.427083 src/drivers/dw/dma.c:442 	dw_dma_stop(): dma 0 channel 4 stop
    0      2         DMIC          43845986.562500        11.875000 rs/intel/cavs/dmic.c:1386	dmic_trigger()
    0      2         DMIC          43845991.093750         4.531250 rs/intel/cavs/dmic.c:1318	dmic_stop()

    dmesg

    [   39.711426] sof-audio-pci 0000:00:0e.0: ipc rx: 0x600a0001: GLB_STREAM_MSG: POSITION
[   39.711438] sof-audio-pci 0000:00:0e.0: posn : host 0xf6c0 dai 0xcf100 wall 0x50e0abb
[   39.711439] sof-audio-pci 0000:00:0e.0: ipc rx done: 0x600a0001: GLB_STREAM_MSG: POSITION
[   39.733424] sof-audio-pci 0000:00:0e.0: ipc rx: 0x600a0001: GLB_STREAM_MSG: POSITION
[   39.733437] sof-audio-pci 0000:00:0e.0: posn : host 0x780 dai 0xd0180 wall 0x5147cba
[   39.733438] sof-audio-pci 0000:00:0e.0: ipc rx done: 0x600a0001: GLB_STREAM_MSG: POSITION
[   39.755424] sof-audio-pci 0000:00:0e.0: ipc rx: 0x600a0001: GLB_STREAM_MSG: POSITION
[   39.755436] sof-audio-pci 0000:00:0e.0: posn : host 0x1800 dai 0xd1200 wall 0x51aeebe
[   39.755437] sof-audio-pci 0000:00:0e.0: ipc rx done: 0x600a0001: GLB_STREAM_MSG: POSITION
[   39.777440] sof-audio-pci 0000:00:0e.0: ipc rx: 0x600a0001: GLB_STREAM_MSG: POSITION
[   39.777453] sof-audio-pci 0000:00:0e.0: posn : host 0x2880 dai 0xd2280 wall 0x52160ba
[   39.777454] sof-audio-pci 0000:00:0e.0: ipc rx done: 0x600a0001: GLB_STREAM_MSG: POSITION
[   39.793038] sof-audio-pci 0000:00:0e.0: pcm: open stream 8 dir 1
[   39.793042] sof-audio-pci 0000:00:0e.0: period min 192 max 16384 bytes
[   39.793043] sof-audio-pci 0000:00:0e.0: period count 2 max 16
[   39.793045] sof-audio-pci 0000:00:0e.0: buffer max 65536 bytes
[   39.793322] sof-audio-pci 0000:00:0e.0: pcm: hw params stream 8 dir 1
[   39.793326] sof-audio-pci 0000:00:0e.0: generating page table for 00000000e8c20c6e size 0x7d40 pages 8
[   39.793334] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x40000 successful
[   39.793348] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x40000 successful
[   39.793350] sof-audio-pci 0000:00:0e.0: period_bytes:0x1f80
[   39.793351] sof-audio-pci 0000:00:0e.0: periods:3
[   39.793357] sof-audio-pci 0000:00:0e.0: stream_tag 2
[   39.793363] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[   39.793901] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[   39.793903] sof-audio-pci 0000:00:0e.0: pcm: stream dir 1, posn mailbox offset is 790604
[   39.799496] sof-audio-pci 0000:00:0e.0: ipc rx: 0x600a0001: GLB_STREAM_MSG: POSITION
[   39.799512] sof-audio-pci 0000:00:0e.0: posn : host 0x3900 dai 0xd3300 wall 0x527d2c0
[   39.799514] sof-audio-pci 0000:00:0e.0: ipc rx done: 0x600a0001: GLB_STREAM_MSG: POSITION
[   39.806081] sof-audio-pci 0000:00:0e.0: received event 1 for widget DETECT9.0
[   39.806098] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[   39.806264] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[   39.806266] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[   39.806439] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[   39.806441] sof-audio-pci 0000:00:0e.0: received event 2 for widget DETECT9.0

    xrun_error_dmesg.log
    xrun_error_logger.log

  28. mengdonglin
    added
    Keyword DetectionApplies to Keyword Detection
    on Jul 8, 2019

  29. mrajwa commented on Jul 8, 2019

    @mrajwa
    mrajwa
    on Jul 8, 2019
    Contributor

    This issue is fixed on https://github.com/thesofproject/sof/tree/cml-005-drop-stable

  30. michalgrodzicki commented on Jul 8, 2019

    @michalgrodzicki
    michalgrodzicki
    on Jul 8, 2019

    @mrajwa please submit code from release branch to the master,
    once you will do it validation team will be able to confirm/reject fix.

  31. tlauda
    closed this as completedon Oct 10, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

GLKApplies to Gemini Lake platformKeyword DetectionApplies to Keyword DetectionbugSomething isn't working as expected

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions