Bug 110879

Summary: [CI][SHARDS] igt@kms_chamelium@dp-audio - fail - Timeout on waiting for condition IsAudioInputStable == True
Product: DRI Reporter: Martin Peres <martin.peres>
Component: DRM/IntelAssignee: Intel GFX Bugs mailing list <intel-gfx-bugs>
Status: NEW --- QA Contact: Intel GFX Bugs mailing list <intel-gfx-bugs>
Severity: normal    
Priority: high CC: cezary.j.rojewski, filip.kaczmarski, intel-gfx-bugs
Version: XOrg git   
Hardware: Other   
OS: All   
Whiteboard: ReadyForDev
i915 platform: ICL i915 features: display/Other

Description Martin Peres 2019-06-10 12:05:18 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6216/re-icl-u/igt@kms_chamelium@dp-audio.html

Starting subtest: dp-audio
Home directory not accessible: Permission denied
(kms_chamelium:4843) igt_chamelium-CRITICAL: Test assertion failure function chamelium_rpc, file ../lib/igt_chamelium.c:344:
(kms_chamelium:4843) igt_chamelium-CRITICAL: Failed assertion: !chamelium->env.fault_occurred
(kms_chamelium:4843) igt_chamelium-CRITICAL: Chamelium RPC call failed: RPC failed at server.  <class 'chameleond.utils.common.TimeoutError'>:Timeout on waiting for condition IsAudioInputStable == True
Comment 1 CI Bug Log 2019-06-10 12:05:58 UTC
The CI Bug Log issue associated to this bug has been updated.

### New filters associated

* CHAMELIUM: igt@kms_chamelium@dp-audio - fail - Timeout on waiting for condition IsAudioInputStable == True
  - https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6216/re-icl-u/igt@kms_chamelium@dp-audio.html
Comment 2 Martin Peres 2019-06-10 12:06:35 UTC
Assigning Simon Ser, since he introduced this new code.
Comment 3 emersion 2019-06-10 12:15:56 UTC
Not sure what's up with this one. An interesting part of the log which may or may not be related is:

(kms_chamelium:4843) igt_alsa-DEBUG: Matched device "HDMI 0"
(kms_chamelium:4843) igt_alsa-DEBUG: Opened output hw:0,3
(kms_chamelium:4843) igt_alsa-DEBUG: Matched device "HDMI 1"
(kms_chamelium:4843) igt_alsa-DEBUG: Opened output hw:0,7
(kms_chamelium:4843) igt_alsa-DEBUG: Matched device "HDMI 2"
(kms_chamelium:4843) igt_alsa-DEBUG: Opened output hw:0,8
(kms_chamelium:4843) igt_alsa-DEBUG: Matched device "HDMI 3"
(kms_chamelium:4843) igt_alsa-DEBUG: Opened output hw:0,9
(kms_chamelium:4843) igt_alsa-DEBUG: Matched device "HDMI 4"
(kms_chamelium:4843) igt_alsa-DEBUG: [ALSA] snd_pcm_hw_open: Device or resource busy
(kms_chamelium:4843) igt_alsa-DEBUG: Matched device "HDMI 5"
(kms_chamelium:4843) igt_alsa-DEBUG: [ALSA] snd_pcm_hw_open: Device or resource busy
(kms_chamelium:4843) igt_alsa-DEBUG: Matched device "HDMI 6"
(kms_chamelium:4843) igt_alsa-DEBUG: [ALSA] snd_pcm_hw_open: Device or resource busy

Maybe the DP port is mapped to one of these ALSA pins which fail with EBUSY.
Comment 4 Jani Saarinen 2019-06-12 06:40:55 UTC
Any updates on this?
Comment 5 emersion 2019-06-12 08:37:13 UTC
- Tried to reset the Chamelium audio receiver before capturing audio: doesn't make it work
- Tried with different audio params: same error
- Since the last 3 audio devices fail with EBUSY, tried to skip the first 3: the last 3 work correctly, but still no audio. So the EBUSY error happens because we open too many devices it seems.
Comment 6 emersion 2019-06-14 07:28:41 UTC
User impact: test coverage issue, we're not able to run DisplayPort audio tests so we won't know if it works/breaks.
Comment 7 emersion 2019-06-17 13:12:15 UTC
Interesting logs… Not sure whether this is normal or not.

<7> [979.191222] [drm:intel_audio_codec_enable [i915]] ELD on [CONNECTOR:214:DP-2], [ENCODER:213:DDI D]
<7> [979.191266] [drm:hsw_audio_codec_enable [i915]] Enable audio codec on transcoder A, 28 bytes ELD
<7> [979.191325] [drm:hsw_audio_config_update [i915]] using automatic Maud, Naud
<4> [979.191335] snd_hda_codec_hdmi hdaudioC0D2: HDMI: pin nid 7 not registered
<7> [979.193599] [drm:intel_fbc_enable [i915]] reserved 16588800 bytes of contiguous stolen space for FBC, threshold: 1
<7> [979.193637] [drm:intel_fbc_enable [i915]] Enabling FBC on pipe A
<7> [979.208173] [drm:verify_connector_state.isra.76 [i915]] [CONNECTOR:214:DP-2]
<7> [979.208248] [drm:intel_atomic_commit_tail [i915]] [CRTC:83:pipe A]
<7> [979.208340] [drm:verify_single_dpll_state.isra.109 [i915]] MG PLL 2
<7> [979.208395] [drm:intel_atomic_commit_tail [i915]] [CRTC:136:pipe B]
<7> [979.208431] [drm:intel_power_well_disable [i915]] disabling power well 4
<7> [979.208473] [drm:intel_atomic_commit_tail [i915]] [CRTC:189:pipe C]
<7> [979.208606] [drm:intel_enable_sagv [i915]] Enabling SAGV
<7> [979.208919] [drm:i915_fifo_underrun_reset_write [i915]] Re-arming FIFO underruns on pipe A
<4> [979.216025] azx_single_wait_for_response: 250 callbacks suppressed
<3> [979.452516] snd_hda_codec_hdmi hdaudioC0D2: Unable to sync register 0x2f8100. -5
<7> [979.452810] [drm:i915_audio_component_get_eld [i915]] Not valid for port B
<7> [979.452934] [drm:i915_audio_component_get_eld [i915]] Not valid for port B
<7> [979.453039] [drm:i915_audio_component_get_eld [i915]] Not valid for port B
<7> [979.453139] [drm:i915_audio_component_get_eld [i915]] Not valid for port C
<7> [979.453234] [drm:i915_audio_component_get_eld [i915]] Not valid for port C
<7> [979.453328] [drm:i915_audio_component_get_eld [i915]] Not valid for port C
<7> [979.454091] [drm:i915_audio_component_get_eld [i915]] Not valid for port D
<7> [979.454211] [drm:i915_audio_component_get_eld [i915]] Not valid for port D
<7> [979.454331] [drm:i915_audio_component_get_eld [i915]] Not valid for port E
<7> [979.454426] [drm:i915_audio_component_get_eld [i915]] Not valid for port E
<7> [979.454560] [drm:i915_audio_component_get_eld [i915]] Not valid for port E
<7> [979.454692] [drm:i915_audio_component_get_eld [i915]] Not valid for port F
<7> [979.454783] [drm:i915_audio_component_get_eld [i915]] Not valid for port F
<7> [979.454871] [drm:i915_audio_component_get_eld [i915]] Not valid for port F
<4> [979.465490] snd_hda_intel 0000:00:1f.3: Too big adjustment 128
<4> [979.469926] snd_hda_intel 0000:00:1f.3: Too big adjustment 128
<4> [979.473772] snd_hda_intel 0000:00:1f.3: Too big adjustment 128
<7> [979.474255] [drm:hsw_audio_config_update [i915]] using Maud 1024, Naud 10125
<4> [979.479821] snd_hda_intel 0000:00:1f.3: Too big adjustment 128
Comment 8 CI Bug Log 2019-06-18 04:48:42 UTC
A CI Bug Log filter associated to this bug has been updated:

{- CHAMELIUM: igt@kms_chamelium@dp-audio - fail - Timeout on waiting for condition IsAudioInputStable == True -}
{+ CHAMELIUM: igt@kms_chamelium@(dp|HDMI)-audio - fail - Timeout on waiting for condition IsAudioInputStable == True +}

New failures caught by the filter:

  * https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_309/fi-icl-u2/igt@kms_chamelium@hdmi-audio.html
Comment 9 emersion 2019-06-18 10:45:22 UTC
> https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_309/fi-icl-u2/igt@kms_chamelium@hdmi-audio.html

HDMI logs also have this line:

<4> [564.191936] snd_hda_codec_hdmi hdaudioC0D2: HDMI: pin nid 7 not registered
Comment 10 emersion 2019-06-18 10:46:35 UTC
Okay, I've been investigating issues with re-icl-u and it turns out that:

* Audio via the regular DisplayPort connector works
* Audio via the mini-DP connector doesn't work

So this is a driver bug after all!
Comment 11 emersion 2019-06-18 12:11:46 UTC
(In reply to emersion from comment #10)
> Okay, I've been investigating issues with re-icl-u and it turns out that:
> 
> * Audio via the regular DisplayPort connector works
> * Audio via the mini-DP connector doesn't work
> 
> So this is a driver bug after all!

Errr, maybe not. Tried again with Jani and hw:0,3 plays sound on a real monitor.

I've also tried manually capturing audio with the Chamelium via mini-DP and it works. However running the test doesn't (using the same audio device and audio parameters).

Another data point is that running the test works on DP but not on mini-DP.
Comment 12 emersion 2019-06-18 14:40:09 UTC
I'm still not sure whether this is a driver issue or a test issue.

User impact: test coverage issue. We cannot ensure DP audio is working reliably with the CI.
Comment 13 emersion 2019-06-20 12:23:08 UTC
(In reply to emersion from comment #11)
> (In reply to emersion from comment #10)
> > Okay, I've been investigating issues with re-icl-u and it turns out that:
> > 
> > * Audio via the regular DisplayPort connector works
> > * Audio via the mini-DP connector doesn't work
> > 
> > So this is a driver bug after all!
> 
> Errr, maybe not. Tried again with Jani and hw:0,3 plays sound on a real
> monitor.
> 
> I've also tried manually capturing audio with the Chamelium via mini-DP and
> it works. However running the test doesn't (using the same audio device and
> audio parameters).
> 
> Another data point is that running the test works on DP but not on mini-DP.

Okay, new update that I think explains why it sometimes worked and sometimes didn't:

When starting playing audio and then connecting the monitor, I don't hear any sounds from a real monitor. When first connecting the real monitor and then playing audio, I hear it.

The IGT test first starts playing audio then connects the monitor.

* * *

Summary: I believe this is a real driver issue. I don't know whether this is a bug in the audio stack or in i915.

User impact: mini-DP audio doesn't work if the user started playing audio before connecting an external monitor.
Comment 14 CI Bug Log 2019-07-01 07:19:49 UTC
A CI Bug Log filter associated to this bug has been updated:

{- CHAMELIUM: igt@kms_chamelium@(dp|HDMI)-audio - fail - Timeout on waiting for condition IsAudioInputStable == True -}
{+ CHAMELIUM: igt@kms_chamelium@(dp|HDMI)-audio - fail/dmesg-fail - Timeout on waiting for condition IsAudioInputStable == True +}

New failures caught by the filter:

  * https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_319/fi-cml-u2/igt@kms_chamelium@dp-audio.html
Comment 15 Lakshmi 2019-08-01 09:38:09 UTC
This bug needs help from audio team input here.
Comment 16 emersion 2019-08-20 10:10:28 UTC
I hope this can be fixed by removing PulseAudio from the DUTs. It seems to load when we start sending audio or something.
Comment 17 Mateusz Górski 2019-08-23 09:55:53 UTC
We have tried to reproduce this issue on our side, but, for now, with no success - audio is audible even when the stream is started before connecting monitor via mini-DP port. 

More information is needed - for example HW used, kernel version, test steps, full logs. 

For now we can't do much since we can't even see the issue on our side.
Comment 18 Lakshmi 2019-08-26 06:30:44 UTC
(In reply to Mateusz Górski from comment #17)
> We have tried to reproduce this issue on our side, but, for now, with no
> success - audio is audible even when the stream is started before connecting
> monitor via mini-DP port. 
> 
> More information is needed - for example HW used, kernel version, test
> steps, full logs. 
> 
> For now we can't do much since we can't even see the issue on our side.

Here is the latest log https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_351/fi-cml-u2/dmesg19.log
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_351/fi-kbl-7500u/dmesg19.log
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_348/fi-icl-u2/dmesg8.log

IGT-Version: 1.24-g6756ede6 (x86_64) (Linux: 5.3.0-rc5-gc8d316e9005a-drmtip_351+ x86_64)
HW: ICL, CML, KBL, 
Test: igt@kms_chamelium@dp-audio
Comment 19 Mateusz Górski 2019-08-29 11:06:33 UTC
(In reply to Lakshmi from comment #18)
> (In reply to Mateusz Górski from comment #17)
> > We have tried to reproduce this issue on our side, but, for now, with no
> > success - audio is audible even when the stream is started before connecting
> > monitor via mini-DP port. 
> > 
> > More information is needed - for example HW used, kernel version, test
> > steps, full logs. 
> > 
> > For now we can't do much since we can't even see the issue on our side.
> 
> Here is the latest log
> https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_351/fi-cml-u2/dmesg19.log
> https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_351/fi-kbl-7500u/dmesg19.log
> https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_348/fi-icl-u2/dmesg8.log
> 
> IGT-Version: 1.24-g6756ede6 (x86_64) (Linux:
> 5.3.0-rc5-gc8d316e9005a-drmtip_351+ x86_64)
> HW: ICL, CML, KBL, 
> Test: igt@kms_chamelium@dp-audio

Thank you for your logs, for now there is one suspicion that we will further analyse. 

In the meantime, could you please provide the full logs? By full I mean logs right from system boot [0.0000000]. 

Also the exact test steps would be very helpful, with used commands/parameters. 

And one more question/request -  Do you have the reproduction when performing that test manually, and if not, could you perform such test and share the results? I am asking, because we still can't reproduce the issue on our side.
Comment 20 emersion 2019-08-29 11:13:13 UTC
I tested manually on re-icl-u: https://intel-gfx-ci.01.org/hardware/re-icl-u/

Reproduction steps from what I recall:

1. Run `aplay -D hdmi:CARD=PCH,DEV=0 test.wav` (choose mini-DP, actual name may be different on your HW)
2. Plug the screen
3. Notice that no sound is played
4. Run `cat /proc/asound/card0/eld*`, notice that the ELD isn't up-to-date (doesn't match the plugged-in screen)

Now repeat the experiment by first plugging the screen and then run aplay: works correctly.

I could try again to take the machine out of our CI to reproduce again and get full kernel logs, if necessary.
Comment 21 Mateusz Górski 2019-09-02 09:27:19 UTC
(In reply to emersion from comment #20)
> I tested manually on re-icl-u: https://intel-gfx-ci.01.org/hardware/re-icl-u/
> 
> Reproduction steps from what I recall:
> 
> 1. Run `aplay -D hdmi:CARD=PCH,DEV=0 test.wav` (choose mini-DP, actual name
> may be different on your HW)
> 2. Plug the screen
> 3. Notice that no sound is played
> 4. Run `cat /proc/asound/card0/eld*`, notice that the ELD isn't up-to-date
> (doesn't match the plugged-in screen)
> 
> Now repeat the experiment by first plugging the screen and then run aplay:
> works correctly.
> 
> I could try again to take the machine out of our CI to reproduce again and
> get full kernel logs, if necessary.

Thank you for these test steps. If possible, please re-run your test to gather full logs, with dynamic debug for hda enabled:

echo -n 'module *hda* +p' > /sys/kernel/debug/dynamic_debug/control

Thanks.
Comment 22 emersion 2019-09-12 10:51:33 UTC
This patch might help understand what's going on: https://patchwork.freedesktop.org/series/66592/

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.