[CML][Bug] IPC timed out for 0x60030000: GLB_STREAM_MSG: PCM_FREE in system reboot test

[ClarexZhou]

Summary:
IPC timed out for 0x60030000: GLB_STREAM_MSG: PCM_FREE in system reboot test

To reproduce
Run ./test-reboot.sh 330 to do system reboot stress test, check dmesg once boot up during system reboot test.

Actual result
IPC timed out for 0x60030000: GLB_STREAM_MSG: PCM_FREE

Expect result
Boot up successfully without any ipc timed out issue.

Reproduce rate: 2/330

Environment
Kernel： linux-image-ipc_only.deb https://drive.google.com/drive/folders/16DI8IFPIGf-xjHw2n-5iVPwnkIyB-jpc?usp=sharing
Firmware repo: b73b9a6 https://github.com/thesofproject/sof/tree/debug-ipc-timeout  
Topology: https://github.com/thesofproject/sof/tree/debug-ipc-timeout . Same as above SOF repo
file: tools/topology/sof-hda-generic.m4, sof-hda-generic-2ch.tplg

Dmesg:

[47303.392229] IPv6: ADDRCONF(NETDEV_CHANGE): enx000ec6b72c8c: link becomes ready
[47303.395439] asix 1-1.1:1.0 enx000ec6b72c8c: link up, 100Mbps, full-duplex, lpa 0xCDE1
[47361.113405] sof-audio-pci 0000:00:1f.3: pcm: open stream 5 dir 0
[47361.113412] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[47361.113416] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[47361.113419] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[47361.113709] HDMI HDA Codec ehdaudio0D2: ASoC: can't set intel-hdmi-hifi3 hw params: -19
[47361.113719]  iDisp3: ASoC: hw_params BE failed -19
[47361.113723]  HDMI3: ASoC: hw_params BE failed -19
[47361.113729] sof-audio-pci 0000:00:1f.3: pcm: free stream 5 dir 0
[47361.113780] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[47361.416107] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[47361.416127] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[47361.416401] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[47361.416416] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[47361.416444] WARNING: CPU: 2 PID: 2271 at /usr/local/src/project/51/src/linux/kernel/workqueue.c:3030 __flush_work+0x150/0x180
[47361.416446] Modules linked in: asix usbnet snd_soc_skl_hda_dsp snd_soc_hdac_hdmi snd_soc_dmic snd_hda_codec_realtek snd_hda_codec_generic sof_pci_dev snd_sof_intel_hda_common iwlmvm snd_soc_hdac_hda snd_sof_intel_hda snd_sof_intel_byt snd_soc_acpi_intel_match snd_sof_intel_ipc snd_sof snd_sof_xtensa_dsp snd_soc_acpi snd_hda_ext_core snd_soc_core snd_hda_codec x86_pkg_temp_thermal snd_hwdep intel_powerclamp snd_hda_core snd_pcm iwlwifi processor_thermal_device intel_soc_dts_iosf mei_me intel_lpss_pci mei intel_lpss mfd_core intel_pch_thermal int3403_thermal int340x_thermal_zone int3400_thermal acpi_thermal_rel efivarfs xhci_pci sdhci_pci cqhci xhci_hcd sdhci
[47361.416495] CPU: 2 PID: 2271 Comm: pulseaudio Tainted: G        W         5.1.0+ #32
[47361.416497] Hardware name: Dell Inc. Vostro 5391/, BIOS 0.1.4 05/02/2019
[47361.416505] RIP: 0010:__flush_work+0x150/0x180

error sof logger:

 CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME	CONTENT
    0      1         COMP         209205371.927083 209205376.000000 rc/audio/component.c:140 	comp_set_state() error: wrong state = 1, COMP_TRIGGER_START
    0      1          IPC         209205378.125000         6.197917 src/audio/pipeline.c:606 	pipeline_trigger() error: ret = -22, host->comp.id = 1, cmd = 1
    0      1          IPC         209205385.000000         6.875000    src/ipc/handler.c:513 	ipc: comp 1 trigger 0x40000 failed -22
    0      1         COMP         209586980.937500    381595.937500 rc/audio/component.c:161 	comp_set_state() error: wrong state = 1, COMP_TRIGGER_STOP
    0      1          IPC         209586986.822917         5.885417 src/audio/pipeline.c:606 	pipeline_trigger() error: ret = -22, host->comp.id = 1, cmd = 0
    0      1          IPC         209586993.593750         6.770833    src/ipc/handler.c:513 	ipc: comp 1 trigger 0x50000 failed -22

dmesg_failed_1.log
dmesg_failed_235.log
logger-t_failed_1.log
logger-t_failed_235.log

[lyakh]

A full dmesg output is needed, attached logs are truncated

[lyakh]

This looks like a duplicate of #932 to me

[ranj063]

@ClarexZhou where is this is test-reboot.sh test script?

[ClarexZhou]

@ranj063 attach test script and need add this sh file to system startup application first.
Also you can find all stress test scripts from https://gitlab.devtools.intel.com/sof-ci/sofcitest/tree/master/sof-test-suites/stress-test

test-reboot.sh.txt

[ranj063]

Thanks @ClarexZhou

[ranj063]

@lyakh there's something very stange in the logs for this one. Why do have the call trace printed and besides the timeout seems to happen after hw_Params fails. So I am not sure which happens first. hw_params failure or the pcm_free ipc timeout.

[ClarexZhou]

0x60030000: GLB_STREAM_MSG: PCM_FREE ipc timed out occurred during aplay stress test.

[  171.684923] HDMI HDA Codec ehdaudio0D2: ASoC: can't set intel-hdmi-hifi3 hw params: -19
[  171.684924]  iDisp3: ASoC: hw_params BE failed -19
[  171.684925]  HDMI3: ASoC: hw_params BE failed -19
[  171.684927] sof-audio-pci 0000:00:1f.3: pcm: free stream 5 dir 0
[  171.684930] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  171.685060] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  178.705936] HDMI HDA Codec ehdaudio0D2: ASoC: can't set intel-hdmi-hifi3 hw params: -19
[  178.705945]  iDisp3: ASoC: hw_params BE failed -19
[  178.705949]  HDMI3: ASoC: hw_params BE failed -19
[  178.705958] sof-audio-pci 0000:00:1f.3: pcm: free stream 5 dir 0
[  178.705965] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  178.705982] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 1
[  179.013498] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[  179.013515] sof-audio-pci 0000:00:1f.3: unknown ROM status value 00000035
[  179.013800] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x000001db trace 0x000001db
[  179.013824] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x90020000 mask 0x00000003
[  179.013827] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[  179.013900] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[  179.013944] HDMI HDA Codec ehdaudio0D2: ASoC: can't set intel-hdmi-hifi3 hw params: -19
[  179.013948]  iDisp3: ASoC: hw_params BE failed -19
[  179.013952]  HDMI3: ASoC: hw_params BE failed -19
[  179.013957] sof-audio-pci 0000:00:1f.3: pcm: free stream 5 dir 0
[  179.317518] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60040000 size 12
[  179.317531] sof-audio-pci 0000:00:1f.3: unknown ROM status value 00000057
[  179.317786] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x000001dc trace 0x000001dc
[  179.317794] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x90020000 mask 0x00000003
[  179.317795] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[  179.317800]  HDA Analog: ASoC: trigger FE failed -110
[  179.317805] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 0
[  179.317820] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  179.317945] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  179.317955] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[  179.317977] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  179.317984] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  179.318020] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[  179.318042] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  179.621498] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[  179.621515] sof-audio-pci 0000:00:1f.3: unknown ROM status value 00000057
[  179.621802] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x000001dc trace 0x000001dc
[  179.621826] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[  179.621830] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[  179.621937] HDMI HDA Codec ehdaudio0D2: ASoC: can't set intel-hdmi-hifi3 hw params: -19
[  179.621942]  iDisp3: ASoC: hw_params BE failed -19
[  179.621945]  HDMI3: ASoC: hw_params BE failed -19
[  179.621951] sof-audio-pci 0000:00:1f.3: pcm: free stream 5 dir 0
[  179.621956] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  179.807778] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[  179.807806] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  179.925505] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[  179.925525] sof-audio-pci 0000:00:1f.3: unknown ROM status value 00000057
[  179.925917] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x000001dc trace 0x000001dc
[  179.925934] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[  179.925938] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[  179.925959] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0
[  179.925967] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  180.229503] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[  180.229522] sof-audio-pci 0000:00:1f.3: unknown ROM status value 00000057
[  180.229917] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x000001dc trace 0x000001dc
[  180.229943] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[  180.229947] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[  180.229977] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[  180.307758] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[  180.307786] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  180.533500] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x80010000 size 120
[  180.533516] sof-audio-pci 0000:00:1f.3: unknown ROM status value 00000057
[  180.533851] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x000001dc trace 0x000001dc
[  180.533864] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[  180.533866] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[  180.533870] sof-audio-pci 0000:00:1f.3: error: failed to set dai config for Analog Playback and Capture
[  180.533943] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 0
[  180.534313] sof-audio-pci 0000:00:1f.3: pcm: close stream 5 dir 0
[  180.540455] HDMI HDA Codec ehdaudio0D2: No connections found for pin:port 7:0
[  180.540465] sof-audio-pci 0000:00:1f.3: pcm: open stream 5 dir 0
[  180.540469] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[  180.540474] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[  180.540477] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[  180.540727] HDMI HDA Codec ehdaudio0D2: ASoC: can't set intel-hdmi-hifi3 hw params: -19
[  180.540738]  iDisp3: ASoC: hw_params BE failed -19
[  180.540742]  HDMI3: ASoC: hw_params BE failed -19
[  180.540754] sof-audio-pci 0000:00:1f.3: pcm: free stream 5 dir 0
[  180.540761] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE

 CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME	CONTENT
    0      1         PIPE 1.6     6365557211.979167              nan src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365560905.364584      3693.385498 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365560951.302084        45.937500 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365560956.770834         5.468750 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365560963.385417         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365564655.520834      3692.135498 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365564701.406250        45.885418 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365564706.718750         5.312500 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365564713.281250         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365568405.468750      3692.187500 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365568452.031250        46.562500 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365568457.604167         5.572917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365568464.166667         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365572155.312500      3691.145752 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365572201.458334        46.145832 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365572206.927084         5.468750 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365572213.541667         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365575905.520834      3691.979248 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365575951.614584        46.093750 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365575957.187500         5.572917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365575963.906250         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365579655.208334      3691.302002 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365579701.250000        46.041668 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365579706.614584         5.364583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365579713.229167         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365583405.520834      3692.291748 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365583451.718750        46.197918 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365583457.187500         5.468750 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365583463.906250         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365587155.104167      3691.197998 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365587201.093750        45.989582 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365587206.458334         5.364583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365587213.177084         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365590905.416667      3692.239502 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365590951.666667        46.250000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365590957.083334         5.416667 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365590963.802084         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365594655.312500      3691.510498 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365594701.718750        46.406250 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365594706.927084         5.208333 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365594713.645834         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365598405.104167      3691.458252 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365598450.104167        45.000000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365598455.468750         5.364583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365598462.135417         6.666667 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365602155.208334      3693.072998 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365602200.364584        45.156250 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365602205.677084         5.312500 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365602212.291667         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365605905.468750      3693.177002 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365605951.614584        46.145832 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365605956.979167         5.364583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365605963.541667         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365609655.312500      3691.770752 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365609701.927084        46.614582 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365609707.291667         5.364583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365609713.854167         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365613405.520834      3691.666748 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365613451.666667        46.145832 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365613457.083334         5.416667 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365613463.697917         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365617155.416667      3691.718750 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365617201.510417        46.093750 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365617206.875000         5.364583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365617213.489584         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365620905.468750      3691.979248 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365620951.562500        46.093750 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365620957.031250         5.468750 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365620963.593750         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365624655.468750      3691.875000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365624701.510417        46.041668 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365624706.822917         5.312500 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365624713.437500         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365628405.572917      3692.135498 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365628451.927084        46.354168 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365628457.500000         5.572917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365628464.062500         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365632155.677084      3691.614502 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365632201.927084        46.250000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365632207.447917         5.520833 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365632214.062500         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365635905.520834      3691.458252 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365635951.770834        46.250000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365635957.343750         5.572917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365635964.062500         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365639655.208334      3691.145752 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365639701.562500        46.354168 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365639706.875000         5.312500 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365639713.385417         6.510417 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365643405.260417      3691.875000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365643451.562500        46.302082 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365643457.031250         5.468750 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365643463.750000         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365647155.208334      3691.458252 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365647201.250000        46.041668 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365647206.614584         5.364583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365647213.333334         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365650905.208334      3691.875000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365650951.406250        46.197918 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365650956.822917         5.416667 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365650963.541667         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365654655.260417      3691.718750 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365654701.302084        46.041668 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365654706.666667         5.364583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365654713.854167         7.187500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365658405.208334      3691.354248 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365658450.156250        44.947918 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365658455.468750         5.312500 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365658462.135417         6.666667 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365662155.260417      3693.125000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365662200.208334        44.947918 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365662205.468750         5.260417 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365662212.083334         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365665905.260417      3693.177002 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365665950.312500        45.052082 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365665955.625000         5.312500 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365665962.083334         6.458333 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365669655.104167      3693.020752 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365669700.781250        45.677082 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365669705.989584         5.208333 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365669712.447917         6.458333 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365673405.312500      3692.864502 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365673451.614584        46.302082 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365673457.031250         5.416667 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365673463.645834         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365677155.781250      3692.135498 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365677202.083334        46.302082 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365677207.447917         5.364583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365677214.062500         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365680905.625000      3691.562500 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365680951.666667        46.041668 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365680957.135417         5.468750 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365680963.697917         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365684655.416667      3691.718750 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365684701.354167        45.937500 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365684706.666667         5.312500 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365684713.229167         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365688405.260417      3692.031250 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365688451.562500        46.302082 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365688457.083334         5.520833 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365688463.645834         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365692155.572917      3691.927002 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365692201.927084        46.354168 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365692207.395834         5.468750 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365692214.010417         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365695905.260417      3691.250000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365695951.302084        46.041668 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365695956.822917         5.520833 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365695963.541667         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365699655.260417      3691.718750 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365699701.562500        46.302082 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365699706.927084         5.364583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365699713.489584         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365703405.468750      3691.979248 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365703451.822917        46.354168 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365703457.291667         5.468750 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365703464.010417         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365707155.260417      3691.250000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365707201.510417        46.250000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365707206.875000         5.364583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365707213.593750         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365710905.104167      3691.510498 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365710951.406250        46.302082 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365710956.822917         5.416667 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365710963.541667         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365714655.156250      3691.614502 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365714701.302084        46.145832 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365714706.666667         5.364583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365714713.437500         6.770833 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365718405.312500      3691.875000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365718450.312500        45.000000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365718455.625000         5.312500 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365718462.291667         6.666667 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365722155.052084      3692.760498 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365722199.947917        44.895832 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365722205.364584         5.416667 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365722211.979167         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365725905.260417      3693.281250 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365725950.312500        45.052082 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365725955.625000         5.312500 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365725962.083334         6.458333 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365729655.156250      3693.072998 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365729700.364584        45.208332 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365729705.677084         5.312500 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365729712.239584         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365733405.104167      3692.864502 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365733450.000000        44.895832 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365733455.312500         5.312500 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365733461.822917         6.510417 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365737155.572917      3693.750000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365737200.989584        45.416668 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365737206.250000         5.260417 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365737212.760417         6.510417 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365740905.312500      3692.552002 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365740951.510417        46.197918 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365740956.979167         5.468750 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365740963.541667         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365744655.364584      3691.822998 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365744701.510417        46.145832 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365744706.822917         5.312500 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365744713.385417         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365748405.416667      3692.031250 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365748451.770834        46.354168 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365748457.343750         5.572917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365748463.906250         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365752155.364584      3691.458252 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365752201.562500        46.197918 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365752207.031250         5.468750 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365752213.750000         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365755905.364584      3691.614502 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365755951.510417        46.145832 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365755957.083334         5.572917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365755963.697917         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365759655.312500      3691.614502 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365759701.354167        46.041668 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365759706.718750         5.364583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365759713.281250         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365763405.208334      3691.927002 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365763451.302084        46.093750 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365763456.770834         5.468750 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365763463.489584         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365767155.520834      3692.031250 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365767201.510417        45.989582 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365767206.875000         5.364583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365767213.593750         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365770905.416667      3691.822998 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365770951.875000        46.458332 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365770957.291667         5.416667 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365770964.010417         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365774655.260417      3691.250000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365774701.510417        46.250000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365774706.875000         5.364583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365774713.645834         6.770833 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365778405.156250      3691.510498 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365778450.208334        45.052082 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365778455.520834         5.312500 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365778462.291667         6.770833 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365782155.156250      3692.864502 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365782200.208334        45.052082 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365782205.520834         5.312500 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365782212.135417         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365785905.312500      3693.177002 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365785950.052084        44.739582 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365785955.364584         5.312500 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365785961.822917         6.458333 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365789655.052084      3693.229248 rc/audio/component.c:252 	comp_get_copy_limits() error: source component buffer has not enough data available
    0      1       VOLUME         6365789700.104167        45.052082 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365789705.572917         5.468750 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365789712.135417         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1          DMA         6365791150.937500      1438.802124 intel/cavs/hda-dma.c:290 	hda-dmac: 5 wait for buffer full timeout rp 0x0 wp 0x0
    0      1         HOST         6365791158.333334         7.395833     src/audio/host.c:795 	host_copy() error: dma_copy() failed, ret = 4294967234
    0      1         PIPE         6365791164.322917         5.989583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -62, start->comp.id = 5, dir = 1
    0      1         PIPE 1.6     6365791170.937500         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365791183.958334        13.020833 rc/audio/component.c:197 	comp_set_state() error: wrong state = 5, COMP_TRIGGER_PREPARE
    0      1         PIPE         6365791190.052084         6.093750 src/audio/pipeline.c:359 	pipeline_prepare() error: ret = -22,dev->comp.id = 1
    0      1         PIPE 1.6     6365791196.354167         6.302083 src/audio/pipeline.c:851 	pipeline_xrun_recover() error: pipeline_prepare() failed, ret = -22
    0      1         PIPE 1.6     6365791201.927084         5.572917 src/audio/pipeline.c:922 	pipeline_task(): xrun recover failed! pipeline will be stopped!
    0      1          DMA         6354913248.125000              nan intel/cavs/hda-dma.c:639 	hda-dmac: 5 invalid channel -1
    0      1          DMA         6354913573.489584       325.364594 intel/cavs/hda-dma.c:639 	hda-dmac: 5 invalid channel -1
    0      1          DMA         6354913854.218750       280.729156 intel/cavs/hda-dma.c:639 	hda-dmac: 5 invalid channel -1
    0      1          DMA         6354914115.677084       261.458344 intel/cavs/hda-dma.c:639 	hda-dmac: 5 invalid channel -1
    0      1          DMA         6354914355.416667       239.739578 intel/cavs/hda-dma.c:639 	hda-dmac: 5 invalid channel -1
    0      1          DMA         6356243221.354167   1328866.000000 intel/cavs/hda-dma.c:639 	hda-dmac: 5 invalid channel -1
    0      1          DMA         6356244175.312500       953.958313 intel/cavs/hda-dma.c:639 	hda-dmac: 5 invalid channel -1
    0      1          DMA         6365020471.250000   8776296.000000 intel/cavs/hda-dma.c:639 	hda-dmac: 5 invalid channel -1
    0      1         COMP         6365407156.250000    386685.000000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365407203.281250        47.031250 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365407208.697917         5.416667 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365407215.572917         6.875000 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365410905.208334      3689.635498 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365410951.458334        46.250000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365410956.875000         5.416667 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365410963.593750         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365414655.260417      3691.666748 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365414700.312500        45.052082 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365414705.572917         5.260417 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365414712.343750         6.770833 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365418405.208334      3692.864502 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365418450.052084        44.843750 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365418455.364584         5.312500 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365418462.135417         6.770833 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365422155.208334      3693.072998 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365422200.208334        45.000000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365422205.625000         5.416667 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365422212.239584         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365425905.468750      3693.229248 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365425950.572917        45.104168 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365425955.885417         5.312500 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365425962.343750         6.458333 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365429655.312500      3692.968750 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365429700.260417        44.947918 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365429705.520834         5.260417 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365429711.979167         6.458333 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365433405.156250      3693.177002 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365433450.156250        45.000000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365433455.468750         5.312500 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365433462.083334         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365437155.260417      3693.177002 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365437201.562500        46.302082 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365437206.927084         5.364583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365437213.697917         6.770833 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365440905.729167      3692.031250 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365440951.875000        46.145832 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365440957.447917         5.572917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365440964.010417         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365444655.729167      3691.718750 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365444701.770834        46.041668 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365444707.187500         5.416667 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365444713.750000         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365448405.208334      3691.458252 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365448451.354167        46.145832 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365448456.927084         5.572917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365448463.489584         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365452155.364584      3691.875000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365452201.406250        46.041668 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365452206.875000         5.468750 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365452213.593750         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365455905.260417      3691.666748 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365455951.197917        45.937500 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365455956.770834         5.572917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365455963.489584         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365459655.260417      3691.770752 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365459701.302084        46.041668 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365459706.666667         5.364583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365459713.281250         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365463405.468750      3692.187500 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365463451.406250        45.937500 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365463456.979167         5.572917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365463463.697917         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365467155.156250      3691.458252 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365467201.562500        46.406250 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365467206.927084         5.364583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365467213.645834         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365470905.416667      3691.770752 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365470951.718750        46.302082 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365470957.135417         5.416667 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365470963.854167         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365474655.416667      3691.562500 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365474701.302084        45.885418 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365474706.562500         5.260417 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365474713.281250         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365478405.364584      3692.083252 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365478450.416667        45.052082 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365478455.729167         5.312500 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365478462.500000         6.770833 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365482155.312500      3692.812500 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365482200.260417        44.947918 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365482205.677084         5.416667 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365482212.291667         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365485905.468750      3693.177002 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365485950.625000        45.156250 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365485955.937500         5.312500 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365485962.395834         6.458333 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365489655.156250      3692.760498 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365489700.208334        45.052082 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365489705.468750         5.260417 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365489711.927084         6.458333 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365493405.104167      3693.177002 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365493450.104167        45.000000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365493455.416667         5.312500 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365493462.031250         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365497155.677084      3693.645752 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365497200.677084        45.000000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365497205.937500         5.260417 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365497212.552084         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365500905.468750      3692.916748 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365500950.625000        45.156250 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365500956.093750         5.468750 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365500962.604167         6.510417 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365504655.208334      3692.604248 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365504701.302084        46.093750 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365504706.666667         5.364583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365504713.229167         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365508405.312500      3692.083252 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365508451.614584        46.302082 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365508457.135417         5.520833 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365508463.697917         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365512155.416667      3691.718750 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365512201.406250        45.989582 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365512206.927084         5.520833 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365512213.645834         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365515905.260417      3691.614502 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365515951.250000        45.989582 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365515956.822917         5.572917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365515963.541667         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365519655.416667      3691.875000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365519701.458334        46.041668 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365519706.822917         5.364583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365519713.437500         6.614583 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365523405.468750      3692.031250 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365523451.406250        45.937500 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365523456.979167         5.572917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365523463.697917         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365527155.260417      3691.562500 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365527201.354167        46.093750 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365527206.718750         5.364583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365527213.437500         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365530905.312500      3691.875000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365530951.510417        46.197918 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365530956.927084         5.416667 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365530963.645834         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365534655.156250      3691.510498 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365534701.406250        46.250000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365534706.614584         5.208333 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365534713.385417         6.770833 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365538405.364584      3691.979248 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365538451.458334        46.093750 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365538456.875000         5.416667 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365538463.750000         6.875000 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365542155.260417      3691.510498 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365542201.562500        46.302082 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365542207.031250         5.468750 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365542213.750000         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365545905.625000      3691.875000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365545951.822917        46.197918 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365545957.239584         5.416667 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365545963.802084         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365549655.416667      3691.614502 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365549701.927084        46.510418 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365549707.291667         5.364583 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365549713.854167         6.562500 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365553405.468750      3691.614502 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365553451.562500        46.093750 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         6365553456.979167         5.416667 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     6365553463.697917         6.718750 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         6365557155.520834      3691.822998 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         6365557201.666667        46.145832 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()

Env.
disable CONFIG_SND_SOC_SOF_DEBUG_ENABLE_DEBUGFS_CACHE in kernel config.
Kernel:
https://github.com/lyakh/linux/tree/ipc-timeout
commit 5969756 ASoC: SOF: hda: couple host and link DMA during FE hw_free , PR 895
FW:
https://github.com/lyakh/sof/tree/ipc-timeout
commit: b527fd7 dai: assign/free link DMA channel during dai_config() , PR1354

aplay_23_all_error_logger.log
aplay_23_all_logger.log
aplay_23_dmesg.log

[ranj063]

I have some more info now. The 80s long time interval between pcm close and the next open is caused by the hdac_codec runtime suspend and resume. The codec_display_power() calls in the 2 runtime PM callbacks take a really long time randomly. Removing this helps with reducing the gap.

[ClarexZhou]

Error occurred on CFL laptop aplay -d 1 stress test in 16th. System response very slow first then ipc timed out

Environment
Kernel: 9453da1 https://github.com/lyakh/linux/tree/ipc-timeout (with PR895)
FW:b527fd7 https://github.com/lyakh/sof/tree/ipc-timeout (with PR1354)
Topology:Same as above FW repo, file: tools/topology/sof-hda-generic.m4, sof-hda-generic-2ch.tplg
kconfig:
unset CONFIG_SND_SOC_SOF_DEBUG_ENABLE_FIRMWARE_TRACE
unset CONFIG_SND_SOC_SOF_DEBUG_ENABLE_DEBUGFS_CACHE

  402.632432] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  402.632471] HDMI HDA Codec ehdaudio0D2: ASoC: can't set intel-hdmi-hifi3 hw params: -19
[  402.632473]  iDisp3: ASoC: hw_params BE failed -19
[  402.632474]  HDMI3: ASoC: hw_params BE failed -19
[  402.632475] sof-audio-pci 0000:00:1f.3: pcm: free stream 5 dir 0
[  402.632477] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  402.632600] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  409.655394] HDMI HDA Codec ehdaudio0D2: ASoC: can't set intel-hdmi-hifi3 hw params: -19
[  409.655403]  iDisp3: ASoC: hw_params BE failed -19
[  409.655407]  HDMI3: ASoC: hw_params BE failed -19
[  409.655416] sof-audio-pci 0000:00:1f.3: pcm: free stream 5 dir 0
[  409.655423] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  409.655473] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 1
[  409.956092] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[  409.956109] sof-audio-pci 0000:00:1f.3: unknown ROM status value 00000024
[  409.956395] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x0000016a trace 0x0000016a
[  409.956408] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x00000000 mask 0x00000003
[  409.956482] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[  409.956523] HDMI HDA Codec ehdaudio0D2: ASoC: can't set intel-hdmi-hifi3 hw params: -19
[  409.956528]  iDisp3: ASoC: hw_params BE failed -19
[  409.956531]  HDMI3: ASoC: hw_params BE failed -19
[  409.956537] sof-audio-pci 0000:00:1f.3: pcm: free stream 5 dir 0
[  410.260090] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60040000 size 12
[  410.260110] sof-audio-pci 0000:00:1f.3: unknown ROM status value 00000047
[  410.260510] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x0000016b trace 0x0000016b
[  410.260538] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x00000000 mask 0x00000003
[  410.260548]  HDA Analog: ASoC: trigger FE failed -110
[  410.260558] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 0
[  410.260577] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  410.260784] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  410.260856] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  410.564098] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[  410.564118] sof-audio-pci 0000:00:1f.3: unknown ROM status value 00000047
[  410.564500] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x0000016b trace 0x0000016b
[  410.564527] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[  410.564636] HDMI HDA Codec ehdaudio0D2: ASoC: can't set intel-hdmi-hifi3 hw params: -19
[  410.564641]  iDisp3: ASoC: hw_params BE failed -19
[  410.564644]  HDMI3: ASoC: hw_params BE failed -19
[  410.564650] sof-audio-pci 0000:00:1f.3: pcm: free stream 5 dir 0
[  410.564656] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  410.868100] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[  410.868120] sof-audio-pci 0000:00:1f.3: unknown ROM status value 00000047
[  410.868503] sof-

 CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME	CONTENT
    0      1         PIPE 1.6     100204608.281250 100204608.000000 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100208328.333333      3720.052002 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100208350.885417        22.552084 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100208354.687500         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100208359.687500         5.000000 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100212078.333333      3718.645752 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100212100.885417        22.552084 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100212104.687500         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100212109.635417         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100215828.385417      3718.750000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100215851.093750        22.708334 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100215854.895833         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100215859.843750         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100219578.020833      3718.177002 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100219600.468750        22.447916 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100219604.166667         3.697917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100219609.114583         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100223327.968750      3718.854248 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100223350.572917        22.604166 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100223354.375000         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100223359.375000         5.000000 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100227078.125000      3718.750000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100227100.625000        22.500000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100227104.375000         3.750000 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100227109.375000         5.000000 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100230827.968750      3718.593750 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100230850.677083        22.708334 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100230854.531250         3.854167 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100230859.479167         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100234578.072917      3718.593750 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100234600.572917        22.500000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100234604.322917         3.750000 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100234609.270833         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100238328.385417      3719.114502 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100238351.093750        22.708334 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100238354.895833         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100238359.843750         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100242078.125000      3718.281250 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100242100.677083        22.552084 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100242104.375000         3.697917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100242109.375000         5.000000 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100245828.333333      3718.958252 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100245850.833333        22.500000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100245854.635417         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100245859.635417         5.000000 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100249578.281250      3718.645752 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100249600.677083        22.395834 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100249604.375000         3.697917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100249609.322917         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100253328.020833      3718.697998 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100253350.625000        22.604166 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100253354.479167         3.854167 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100253359.427083         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100257078.125000      3718.697998 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100257100.677083        22.552084 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100257104.427083         3.750000 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100257109.375000         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100260828.281250      3718.906250 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100260850.937500        22.656250 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100260854.739583         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100260859.687500         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100264578.020833      3718.333252 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100264600.468750        22.447916 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100264604.166667         3.697917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100264609.166667         5.000000 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100268327.916667      3718.750000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100268350.416667        22.500000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100268354.218750         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100268359.218750         5.000000 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100272077.968750      3718.750000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100272100.416667        22.447916 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100272104.218750         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100272109.166667         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100275828.177083      3719.010498 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100275850.833333        22.656250 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100275854.635417         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100275859.583333         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100279578.281250      3718.697998 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100279600.729167        22.447916 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100279604.479167         3.750000 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100279609.427083         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100283328.177083      3718.750000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100283350.781250        22.604166 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100283354.583333         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100283359.583333         5.000000 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100287078.229167      3718.645752 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100287100.677083        22.447916 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100287104.375000         3.697917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100287109.375000         5.000000 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100290828.072917      3718.697998 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100290850.572917        22.500000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100290854.427083         3.854167 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100290859.375000         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100294578.072917      3718.697998 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100294600.625000        22.552084 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100294604.375000         3.750000 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100294609.322917         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100298328.177083      3718.854248 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100298350.781250        22.604166 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100298354.583333         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100298359.531250         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100302077.968750      3718.437500 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100302100.416667        22.447916 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100302104.166667         3.750000 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100302109.166667         5.000000 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100305828.229167      3719.062500 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100305850.937500        22.708334 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100305854.739583         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100305859.739583         5.000000 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100309578.229167      3718.489502 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100309600.781250        22.552084 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100309604.531250         3.750000 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100309609.479167         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100313328.020833      3718.541748 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100313350.572917        22.552084 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100313354.427083         3.854167 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100313359.375000         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100317078.072917      3718.697998 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100317100.677083        22.604166 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100317104.375000         3.697917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100317109.322917         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100320828.229167      3718.906250 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100320850.833333        22.604166 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100320854.635417         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100320859.583333         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100324578.333333      3718.750000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100324600.885417        22.552084 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100324604.583333         3.697917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100324609.583333         5.000000 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100328328.125000      3718.541748 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100328350.729167        22.604166 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100328354.531250         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100328359.531250         5.000000 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100332078.229167      3718.697998 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100332100.729167        22.500000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100332104.531250         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100332109.479167         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100335827.968750      3718.489502 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100335850.572917        22.604166 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100335854.375000         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100335859.322917         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100339578.385417      3719.062500 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100339600.885417        22.500000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100339604.583333         3.697917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100339609.531250         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100343328.281250      3718.750000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100343350.833333        22.552084 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100343354.635417         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100343359.739583         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100347077.968750      3718.229248 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100347100.625000        22.656250 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100347104.375000         3.750000 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100347109.375000         5.000000 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100350828.281250      3718.906250 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100350850.885417        22.604166 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100350854.739583         3.854167 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100350859.687500         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100354578.385417      3718.697998 rc/audio/component.c:252 	comp_get_copy_limits() error: source component buffer has not enough data available
    0      1       VOLUME         100354600.885417        22.500000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100354604.583333         3.697917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100354609.531250         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1          DMA         100356076.197917      1466.666626 intel/cavs/hda-dma.c:290 	hda-dmac: 5 wait for buffer full timeout rp 0x0 wp 0x0
    0      1         HOST         100356081.822917         5.625000     src/audio/host.c:795 	host_copy() error: dma_copy() failed, ret = 4294967234
    0      1         PIPE         100356086.302083         4.479167 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -62, start->comp.id = 5, dir = 1
    0      1         PIPE 1.6     100356091.250000         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100356097.968750         6.718750 rc/audio/component.c:197 	comp_set_state() error: wrong state = 5, COMP_TRIGGER_PREPARE
    0      1         PIPE         100356102.447917         4.479167 src/audio/pipeline.c:359 	pipeline_prepare() error: ret = -22,dev->comp.id = 1
    0      1         PIPE 1.6     100356107.239583         4.791667 src/audio/pipeline.c:851 	pipeline_xrun_recover() error: pipeline_prepare() failed, ret = -22
    0      1         PIPE 1.6     100356111.302083         4.062500 src/audio/pipeline.c:922 	pipeline_task(): xrun recover failed! pipeline will be stopped!
    0      1          DMA          85712565.364583              nan intel/cavs/hda-dma.c:639 	hda-dmac: 5 invalid channel -1
    0      1          DMA          85712997.552083       432.187500 intel/cavs/hda-dma.c:639 	hda-dmac: 5 invalid channel -1
    0      1          DMA          85713442.447917       444.895844 intel/cavs/hda-dma.c:639 	hda-dmac: 5 invalid channel -1
    0      1          DMA          85713758.072917       315.625000 intel/cavs/hda-dma.c:639 	hda-dmac: 5 invalid channel -1
    0      1          DMA          85714141.614583       383.541656 intel/cavs/hda-dma.c:639 	hda-dmac: 5 invalid channel -1
    0      1          DMA          90815066.041667   5100924.500000 intel/cavs/hda-dma.c:639 	hda-dmac: 5 invalid channel -1
    0      1          DMA          90815279.218750       213.177078 intel/cavs/hda-dma.c:639 	hda-dmac: 5 invalid channel -1
    0      1          DMA          99593958.437500   8778679.000000 intel/cavs/hda-dma.c:639 	hda-dmac: 5 invalid channel -1
    0      1         COMP          99972078.541667    378120.093750 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME          99972101.927083        23.385416 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE          99972105.937500         4.010417 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6      99972111.093750         5.156250 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP          99975828.281250      3717.187500 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME          99975850.989583        22.708334 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE          99975854.791667         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6      99975859.739583         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP          99979578.385417      3718.645752 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME          99979600.989583        22.604166 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE          99979604.739583         3.750000 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6      99979609.687500         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP          99983328.229167      3718.541748 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME          99983350.781250        22.552084 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE          99983354.583333         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6      99983359.687500         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP          99987078.281250      3718.593750 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME          99987100.833333        22.552084 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE          99987104.531250         3.697917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6      99987109.635417         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP          99990828.020833      3718.385498 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME          99990850.677083        22.656250 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE          99990854.635417         3.958333 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6      99990859.583333         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP          99994578.020833      3718.437500 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME          99994600.625000        22.604166 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE          99994604.427083         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6      99994609.375000         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP          99998328.333333      3718.958252 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME          99998351.041667        22.708334 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE          99998354.843750         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6      99998359.791667         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100002078.229167      3718.437500 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100002100.833333        22.604166 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100002104.583333         3.750000 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100002109.687500         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100005828.385417      3718.697998 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100005851.041667        22.656250 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100005854.843750         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100005859.947917         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100009578.281250      3718.333252 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100009600.781250        22.500000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100009604.531250         3.750000 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100009609.583333         5.052083 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100013328.177083      3718.593750 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100013350.885417        22.708334 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100013354.843750         3.958333 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100013359.791667         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100017078.177083      3718.385498 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100017100.729167        22.552084 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100017104.427083         3.697917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100017109.375000         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100020828.177083      3718.802002 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100020850.729167        22.552084 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100020854.531250         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100020859.479167         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100024577.916667      3718.437500 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100024600.416667        22.500000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100024604.114583         3.697917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100024609.218750         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100028327.968750      3718.750000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100028350.625000        22.656250 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100028354.427083         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100028359.531250         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100032078.072917      3718.541748 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100032100.520833        22.447916 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100032104.375000         3.854167 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100032109.322917         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100035828.020833      3718.697998 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100035850.781250        22.760416 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100035854.583333         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100035859.531250         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100039578.229167      3718.697998 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100039600.833333        22.604166 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100039604.583333         3.750000 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100039609.531250         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100043328.333333      3718.802002 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100043350.885417        22.552084 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100043354.687500         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100043359.791667         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100047078.281250      3718.489502 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100047100.833333        22.552084 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100047104.531250         3.697917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100047109.635417         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100050828.177083      3718.541748 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100050850.625000        22.447916 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100050854.583333         3.958333 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100050859.531250         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100054578.177083      3718.645752 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100054600.625000        22.447916 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100054604.427083         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100054609.375000         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100058328.333333      3718.958252 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100058350.989583        22.656250 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100058354.791667         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100058359.739583         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100062078.281250      3718.541748 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100062100.729167        22.447916 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100062104.479167         3.750000 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100062109.583333         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100065828.177083      3718.593750 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100065850.885417        22.708334 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100065854.687500         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100065859.791667         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100069578.229167      3718.437500 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100069600.833333        22.604166 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100069604.531250         3.697917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100069609.531250         5.000000 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100073328.177083      3718.645752 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100073350.885417        22.708334 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100073354.791667         3.906250 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100073359.739583         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100077078.020833      3718.281250 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100077100.572917        22.552084 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100077104.322917         3.750000 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100077109.270833         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100080828.125000      3718.854248 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100080850.833333        22.708334 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100080854.635417         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100080859.583333         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100084578.385417      3718.802002 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100084600.937500        22.552084 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100084604.687500         3.750000 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100084609.791667         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100088328.125000      3718.333252 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100088350.729167        22.604166 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100088354.583333         3.854167 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100088359.687500         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100092078.020833      3718.333252 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100092100.520833        22.500000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100092104.375000         3.854167 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100092109.322917         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100095828.020833      3718.697998 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100095850.833333        22.812500 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100095854.635417         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100095859.583333         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100099578.333333      3718.750000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100099600.833333        22.500000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100099604.531250         3.697917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100099609.479167         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100103328.385417      3718.906250 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100103350.989583        22.604166 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100103354.791667         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100103359.895833         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100107077.968750      3718.072998 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100107100.416667        22.447916 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100107104.114583         3.697917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100107109.218750         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100110828.020833      3718.802002 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100110850.572917        22.552084 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100110854.531250         3.958333 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100110859.479167         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100114578.385417      3718.906250 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100114600.937500        22.552084 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100114604.739583         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100114609.687500         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100118328.125000      3718.437500 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100118350.937500        22.812500 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100118354.739583         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100118359.687500         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100122078.177083      3718.489502 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100122100.677083        22.500000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100122104.375000         3.697917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100122109.479167         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100125828.020833      3718.541748 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100125850.468750        22.447916 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100125854.270833         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100125859.375000         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100129578.281250      3718.906250 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100129600.781250        22.500000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100129604.531250         3.750000 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100129609.583333         5.052083 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100133328.020833      3718.437500 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100133350.625000        22.604166 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100133354.583333         3.958333 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100133359.531250         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100137078.125000      3718.593750 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100137100.729167        22.604166 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100137104.427083         3.697917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100137109.375000         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100140828.333333      3718.958252 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100140850.885417        22.552084 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100140854.687500         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100140859.635417         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100144578.385417      3718.750000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100144600.937500        22.552084 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100144604.635417         3.697917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100144609.739583         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100148328.177083      3718.437500 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100148350.781250        22.604166 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100148354.583333         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100148359.687500         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100152078.072917      3718.385498 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100152100.520833        22.447916 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100152104.375000         3.854167 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100152109.322917         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100155828.229167      3718.906250 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100155850.937500        22.708334 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100155854.739583         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100155859.687500         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100159578.072917      3718.385498 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100159600.729167        22.656250 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100159604.479167         3.750000 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100159609.427083         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100163328.072917      3718.645752 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100163350.677083        22.604166 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100163354.479167         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100163359.583333         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100167078.125000      3718.541748 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100167100.625000        22.500000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100167104.322917         3.697917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100167109.427083         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100170828.072917      3718.645752 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100170850.520833        22.447916 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100170854.427083         3.906250 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100170859.375000         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100174578.229167      3718.854248 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100174600.625000        22.395834 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100174604.427083         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100174609.375000         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100178327.864583      3718.489502 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100178350.520833        22.656250 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100178354.322917         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100178359.270833         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100182078.281250      3719.010498 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100182100.677083        22.395834 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100182104.375000         3.697917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100182109.479167         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100185828.281250      3718.802002 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100185850.885417        22.604166 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100185854.687500         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100185859.791667         5.104167 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100189578.281250      3718.489502 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100189600.781250        22.500000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100189604.531250         3.750000 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100189609.531250         5.000000 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100193328.281250      3718.750000 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100193350.781250        22.500000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100193354.739583         3.958333 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100193359.687500         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100197078.333333      3718.645752 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100197100.885417        22.552084 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100197104.583333         3.697917 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100197109.531250         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100200828.072917      3718.541748 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100200850.729167        22.656250 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()
    0      1         PIPE         100200854.531250         3.802083 src/audio/pipeline.c:732 	pipeline_copy() error: ret = -5, start->comp.id = 2, dir = 1
    0      1         PIPE 1.6     100200859.479167         4.947917 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP         100204577.968750      3718.489502 rc/audio/component.c:261 	comp_get_copy_limits() error: sink component buffer has not enough free bytes for copy
    0      1       VOLUME         100204600.468750        22.500000 udio/volume/volume.c:510 	volume_copy(): Failed comp_get_copy_limits()

aplay_error_16_dmesg.log
aplay_error_16_logger_error.log

[lyakh]

I have some more info now. The 80s long time interval between pcm close and the next open is caused by the hdac_codec runtime suspend and resume. The codec_display_power() calls in the 2 runtime PM callbacks take a really long time randomly. Removing this helps with reducing the gap.

I was thinking whether such long delays could have been caused by deadlocks due to the wrong use of spin_lock() instead of spin_lock_irq(), but I don't think that could be the case: such a lockup would stay forever, it wouldn't just take a couple of seconds.