Bug 116171 - snd_hda_codec_cirrus audio recording fails since v4.4
Summary: snd_hda_codec_cirrus audio recording fails since v4.4
Status: RESOLVED CODE_FIX
Alias: None
Product: Drivers
Classification: Unclassified
Component: Sound(ALSA) (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: Jaroslav Kysela
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2016-04-11 15:59 UTC by chr()
Modified: 2016-05-10 09:48 UTC (History)
2 users (show)

See Also:
Kernel Version: 4.4
Subsystem:
Regression: No
Bisected commit-id:


Attachments
alsa info w/o hint - idle - broken (60.96 KB, application/octet-stream)
2016-04-11 16:00 UTC, chr()
Details
alsa info w/o hint - recording - broken (60.96 KB, application/octet-stream)
2016-04-11 16:01 UTC, chr()
Details
alsa info hint: power_save_node=0 - idle (62.26 KB, application/octet-stream)
2016-04-11 16:02 UTC, chr()
Details
alsa info hint: power_save_node=0 - recoding - ok (62.26 KB, application/octet-stream)
2016-04-11 16:04 UTC, chr()
Details
kernel oops (5.05 KB, text/plain)
2016-04-12 14:07 UTC, chr()
Details
4.6-rc3 alsa info while rec [ok] (45.32 KB, application/octet-stream)
2016-04-15 15:12 UTC, chr()
Details
4.6-rc3 alsa info while rec with power_save=2 [broken] (45.28 KB, application/octet-stream)
2016-04-15 15:13 UTC, chr()
Details
4.6-rc3 trace arecord [ok] (1.71 KB, application/octet-stream)
2016-04-15 15:16 UTC, chr()
Details
4.6-rc3 trace arecord [broken] (26.73 KB, application/octet-stream)
2016-04-15 15:17 UTC, chr()
Details
4.6-rc3 trace set power_save (16.05 KB, application/octet-stream)
2016-04-15 15:19 UTC, chr()
Details
Test patch (845 bytes, patch)
2016-04-15 18:19 UTC, Takashi Iwai
Details | Diff
alsa-info 4.6-rc3 patch#1 [works] (45.32 KB, application/octet-stream)
2016-04-17 02:00 UTC, chr()
Details
4.6-rc3+patch trace acecord+switch (7.01 KB, application/octet-stream)
2016-04-19 14:25 UTC, chr()
Details
4.6-rc3+patch kernel oops (5.49 KB, application/octet-stream)
2016-04-19 14:27 UTC, chr()
Details
Patch #2 (905 bytes, patch)
2016-04-19 15:13 UTC, Takashi Iwai
Details | Diff
Patch to fix kernel WARNING (5.02 KB, patch)
2016-04-19 20:20 UTC, Takashi Iwai
Details | Diff
Revised patch to fix kernel WARNING (4.83 KB, patch)
2016-04-21 15:58 UTC, Takashi Iwai
Details | Diff

Description chr() 2016-04-11 15:59:09 UTC
After upgrading from kernel 4.2 to 4.4 audio recording fails on my MacBook 6,2

arecord -V stereo -f dat -c2 -v -D hw:0,0 test.wav
arecord: pcm_read:1801: read error: Input/output error

This commit catched my eye:
3e19fec33a5493f8a627a96ad3494d6c6dc2a624
"ALSA: hda - Enable widget power saving for Cirrus codecs" 

Using the hint power_save_node=0 makes recording working.

While testing I run
`watch grep -r actual=D /proc/asound/card0`

I noticed that nodes changes from D3 to D0 on playback, but I don't see any changes for the Auto-In nodes while recording: always D0
Comment 1 chr() 2016-04-11 16:00:29 UTC
Created attachment 212351 [details]
alsa info w/o hint - idle - broken
Comment 2 chr() 2016-04-11 16:01:19 UTC
Created attachment 212361 [details]
alsa info w/o hint - recording - broken

arecord -V stereo -f dat -c2 -v -D hw:0,0 test.wav

arecord: pcm_read:1801: read error: Input/output error
Comment 3 chr() 2016-04-11 16:02:24 UTC
Created attachment 212371 [details]
alsa info hint: power_save_node=0 - idle
Comment 4 chr() 2016-04-11 16:04:02 UTC
Created attachment 212381 [details]
alsa info hint: power_save_node=0 - recoding - ok

arecord -V stereo -f dat -c2  -D hw:0,0 test.wav

Recording WAVE 'testB.wav' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
                                  +00%|00%+

recoding with hint works
Comment 5 Takashi Iwai 2016-04-11 16:06:48 UTC
Which input are you recording from?  From the built-in mic?
Also, to be sure, could you check whether the issue is present in 4.5 or 4.6-rc3?
Comment 6 chr() 2016-04-11 21:52:40 UTC
The alsa-infos were made while I tried to record from built-in mic

However, the mixer setup doesn't matter. I would record at least some silence.

I tested both, mic and line-in, work with the hint.

I can test 4.6 next weekend.
Comment 7 Raymond 2016-04-12 03:36:56 UTC
how do you test ? 

do it mean dynamic reconfigure fail to work in specific case


19089.578576] snd_hda_codec_cirrus hdaudioC0D0: Unbalanced pm_runtime_enable!
[19089.580432] snd_hda_intel 0000:00:1b.0: control 2:0:0:IEC958 Default PCM Playback Switch:0 is already present
[19697.394810] i915 0000:00:02.0: BAR 6: [??? 0x00000000 flags 0x20000000] has bogus align


19089.578576] snd_hda_codec_cirrus hdaudioC0D0: Unbalanced pm_runtime_enable!
[19089.580432] snd_hda_intel 0000:00:1b.0: control 2:0:0:IEC958 Default PCM Playback Switch:0 is already present
[19697.394810] i915 0000:00:02.0: BAR 6: [??? 0x00000000 flags 0x20000000] has bogus align
Comment 8 Raymond 2016-04-12 03:37:49 UTC
19730.579425] snd_hda_codec_cirrus hdaudioC0D0:    dig-in=0xf
[19730.580121] snd_hda_intel 0000:01:00.1: Refused to change power state, currently in D3
[19730.580136] snd_hda_intel 0000:01:00.1: Disabling MSI
[19730.580148] snd_hda_intel 0000:01:00.1: Handle vga_switcheroo audio client
[19730.587959] input: HDA Intel MID Line as /devices/pci0000:00/0000:00:1b.0/sound/card0/input49
[19730.588248] input: HDA Intel MID Headphone as /devices/pci0000:00/0000:00:1b.0/sound/card0/input50
[19730.588550] input: HDA Intel MID SPDIF In as /devices/pci0000:00/0000:00:1b.0/sound/card0/input51
[19730.682122] hdaudio hdaudioC1D1: no AFG or MFG node found
[19730.682138] hdaudio hdaudioC1D2: no AFG or MFG node found
Comment 9 chr() 2016-04-12 13:07:13 UTC
@raymond "how do you test ?"

Step #0: stopped all audio apps (pulse ...)

`arecord -V stereo -f dat -c2 -v -D hw:0,0 test.wav`
>arecord: pcm_read:1801: read error: Input/output error

First I tried and error to apply the hint via /sys/class/sound/hwC0D0,
1st try `hint+reconfig` 
2nd try was clear+hint+reconfig

but no success (audio-out ok, rec still broken), instead it caused those messages:

"snd_hda_codec_cirrus hdaudioC0D0: hda-codec: reconfiguring"
"Unbalanced pm_runtime_enable!" ... "Switch:0 is already present" ...

They don't appear on a regular bootup or modprobe.
Clear doesn't clear 100%, alsamixer still shows 2 sliders, /proc/asound/card0/codec#0 unchanged ... this may be another bug.

So I used rmmod/modprobe (patch=hda-init.fw) and alsactrl to re/store mixer for record via mic.



The machine is a notebook with 'hybrid-graphics' and has a display-port plug.

0000:01:00.1 is HDMI but the discrete nvidia-gpu-chip is permanent powered down,
snd_hda_codec_hdmi is blacklisted.
This bug is about snd_hda_codec_cirrus and the device is at 00:1b.0,
so ignore snd_hda_intel 0000:01:00.1 hdaudio hdaudioC1D1.
Comment 10 Takashi Iwai 2016-04-12 13:15:11 UTC
Well, something got messed up during the reconfig.  Maybe something missing in the pm refcount setup.  But it's a slightly off-topic here.  So, for taking alsa-info.sh snapthots, please do clean reboot.  Otherwise the logs become confusing.

In addition, the hybrid GPU makes things complex.  Please try to disable the Nvidia HDMI, e.g. pass enable=1,0 option to snd-hda-intel module.

The lack of D-state change isn't seen on emulator.  On hda-emu, the widgets corresponding to the input paths are powered on upon recording (NID 0x0d and 0x06).  If this isn't seen, something is inconsistent.

In that case, it'd be helpful to get the trace of HD-audio verbs.  Check "Tracepoints" section in HD-Audio.txt about how to get the tracing results.
Comment 11 chr() 2016-04-12 14:03:33 UTC
Quick answer:

I used probe_mask to silence the snd-hdmi but I cleared it before, did a fresh reboot with 'factory defaults'.

To check the PM, I've got here another notebook with codec-realtek kernel 4.4 which works fine.
To observe I ran

watch -d grep actual= /proc/asound/card0/codec#0

 Power: setting=D0, actual=D0
 Power: setting=D3, actual=D3
 Power: setting=D3, actual=D3
 Power: setting=D0, actual=D0
...

echo 1 > /sys/module/snd_hda_intel/parameters/power_save

After 1 second, all nodes are on D3 except the 1st,
run aplay or arecord some nodes changes to D0 and back as expected.


On the Mac, .... well I just got a kernel-oops on rmmod/modprobe ... got to reboot.

... letting power_save_node=on [default] and setting power_save=1 there are some

Power: setting=D3, actual=D0

Mh.

On aplay I see some D3->D0 but arecord changes nothing and fails.
Comment 12 chr() 2016-04-12 14:07:17 UTC
Created attachment 212481 [details]
kernel oops

FYI

modprobe -r snd_hda_intel
modprobe -r snd_hda_codec_cirrus

modprobe snd_hda_intel

KABLAM.

That worked n-times before, n+1 crashed ...
Comment 13 Takashi Iwai 2016-04-12 14:27:06 UTC
(In reply to chr() from comment #11)
> Quick answer:
> 
> I used probe_mask to silence the snd-hdmi but I cleared it before, did a
> fresh reboot with 'factory defaults'.

The probe_mask doesn't help for Nvidia because it's an individual controller chip.  You need to disable the whole card via enable option.

> To check the PM, I've got here another notebook with codec-realtek kernel
> 4.4 which works fine.
> To observe I ran
> 
> watch -d grep actual= /proc/asound/card0/codec#0
> 
>  Power: setting=D0, actual=D0
>  Power: setting=D3, actual=D3
>  Power: setting=D3, actual=D3
>  Power: setting=D0, actual=D0
> ...
> 
> echo 1 > /sys/module/snd_hda_intel/parameters/power_save
> 
> After 1 second, all nodes are on D3 except the 1st,
> run aplay or arecord some nodes changes to D0 and back as expected.
> 
> 
> On the Mac, .... well I just got a kernel-oops on rmmod/modprobe ... got to
> reboot.

It's a known problem of 4.4 kernel.  It's been already fixed in the recent kernels.  So, if you do reload modules, test with the latest 4.6-rc at best until the fixes land into 4.4.x stable.

> ... letting power_save_node=on [default] and setting power_save=1 there are
> some
> 
> Power: setting=D3, actual=D0
> 
> Mh.

This is seen on the previous alsa-info.sh outputs, too, indeed.  Interesting.
Is this actual=D0 sticky even after some seconds?

In anyway, it's not clear whether the driver wanted to change to D3 or D0 in this case.  We need the tracer output.
Comment 14 chr() 2016-04-12 15:37:31 UTC
(In reply to Takashi Iwai from comment #13)
> (In reply to chr() from comment #11)

> This is seen on the previous alsa-info.sh outputs, too, indeed.  Interesting.
> Is this actual=D0 sticky even after some seconds?

Yes. It stays actual=D0


> 
> In anyway, it's not clear whether the driver wanted to change to D3 or D0 in
> this case.  We need the tracer output.

I'll make this with 4.6, but backup etc ... will take some time ;)
Comment 15 chr() 2016-04-15 15:08:42 UTC
Hi!

I checked 4.6-rc3

I used an external usb-hd to boot 4.6 with devuan (systemd-free debian), libasound is newe
r, vanilla Kernel, no hybrid-gpu-hdmi-gotchas etc.

1st surprise: recording works (factory defaults).

So I tried harder:
After setting power_save > 0 recording fails but I don't get an I/O error, arecord just hangs.

Observations:

On a fresh reboot, `grep actual= /proc/asound/card0/codec#0i | nl` shows
     1    Power: setting=D0, actual=D0
     2    Power: setting=D3, actual=D3
     3    Power: setting=D3, actual=D3
     4    Power: setting=D3, actual=D3
     5    Power: setting=D3, actual=D0 < ?!
     6    Power: setting=D3, actual=D3 < D0 on rec
     7    Power: setting=D3, actual=D3
     8    Power: setting=D3, actual=D3
     9    Power: setting=D3, actual=D3
    10    Power: setting=D3, actual=D3
    11    Power: setting=D3, actual=D0 < ?! 
    12    Power: setting=D3, actual=D3 < D0 on rec
    13    Power: setting=D3, actual=D3
    14    Power: setting=D3, actual=D3
    15    Power: setting=D0, actual=D0
    16    Power: setting=D0, actual=D0
    17    Power: setting=D0, actual=D0
    18    Power: setting=D0, actual=D0

After using arec/aplay once, the nodes are switched and stay on D0.

Set power_save, aplay still works, I see D3>D0>D3 as expected.
Using arecord 'nothing' changes.

Set power_save back to 0 recording still fails,
reloading the snd-modules doesn't help either!
Comment 16 chr() 2016-04-15 15:12:56 UTC
Created attachment 212961 [details]
4.6-rc3 alsa info while rec [ok]
Comment 17 chr() 2016-04-15 15:13:34 UTC
Created attachment 212971 [details]
4.6-rc3 alsa info while rec with power_save=2 [broken]
Comment 18 chr() 2016-04-15 15:16:49 UTC
Created attachment 212981 [details]
4.6-rc3 trace arecord [ok]

fresh boot.
power_save=0,
however nodes are on D3
On 2nd record, the trace just shows the last 2 lines
(nodes stay D0)
Comment 19 chr() 2016-04-15 15:17:55 UTC
Created attachment 212991 [details]
4.6-rc3 trace arecord [broken]

power_save=2
Comment 20 chr() 2016-04-15 15:19:59 UTC
Created attachment 213001 [details]
4.6-rc3 trace set power_save

trace of:

echo 2 > /sys/module/snd_hda_intel/parameters/power_save
Comment 21 Raymond 2016-04-15 15:28:08 UTC
(In reply to chr() from comment #19)
> Created attachment 212991 [details]
> 4.6-rc3 trace arecord [broken]
> 
> power_save=2

hda-emu seem behave the same way , stream=0 after suspend resume while recording

PCM -s 0 c 44100 2 16
pm
Comment 22 Takashi Iwai 2016-04-15 18:19:06 UTC
The stream=0 itself is OK if it is *after* recording and PM resume.
But it's strange if stream=0 is shown *during* recording.

In anyway, one problem I can see is that the driver may skip the power state change when the codec shows an inconsistent state.  In this case, the codec advertises the actual power is D0 and the target is D3 although it seems actually being powered off.

Does the patch below make any difference?
Comment 23 Takashi Iwai 2016-04-15 18:19:25 UTC
Created attachment 213021 [details]
Test patch
Comment 24 chr() 2016-04-16 15:09:05 UTC
(In reply to Takashi Iwai from comment #22)
> The stream=0 itself is OK if it is *after* recording and PM resume.
> But it's strange if stream=0 is shown *during* recording.

Which is the case on power_save > 0

To clarify how I made the captures: As I released, that doing anything with the card, it makes irreversible changes up to reloading the modules doesn't help. Running alsa-info wakes up everything and tracing arecord after just shows up two lines which I interpret as 'start rec, stop rec'.

So I reboot (power down as I know hardware which keeps it's itches), make just alsa-info-files, reboot again and then I made the trace. I briefly named them idle, whilerec, afterrec, whileplay, afterall.

I just upped the files 'while recording'.

> Does the patch below make any difference?

Thanks, I'll test ASAP
Comment 25 chr() 2016-04-17 01:56:48 UTC
Hi!

Good news: the patch makes recording going with power_save > 0
(tested: 4.6-rc3)

However, there are still nodes left in inconsistent state:

Power: setting=D3, actual=D0

While testing I found Schroedingers Cat around.
My aim was to measure power consumption, so I increased the timeout:

power_save=10

and run `watch grep Power: /proc/asound/card0/codec#0`

Now I was wondering there was no switch back to setting=D0 anymore ... Watch runs every 2 seconds ... aaahaha ... his doesn't wake up the nodes, but it keeps them busy in D0.
Comment 26 chr() 2016-04-17 02:00:13 UTC
Created attachment 213061 [details]
alsa-info 4.6-rc3 patch#1 [works]

note:
power_save=1
state: idle,
_after_ using record/play

Some nodes are still in inconsistent power-state
Comment 27 Takashi Iwai 2016-04-17 09:12:09 UTC
Good to hear.  The fix patch was now submitted and merged.  Once when it's included in Linus tree (likely in 4.6-rc5), it'll be backported to stable kernels, too.

The inconsistent D3/D0 states are the hardware characteristic (IOW bug).  It can't flip down to D3 properly by some reason and got stuck at the wrong state.
As long as the recording itself works, we can ignore the wrongly shown states.
Comment 28 chr() 2016-04-17 18:52:52 UTC
Hi!

Bad news: that patch doesn't help v4.4.7

Recording via build-in-mic works, but switching to line-in arecord stalls and fails with IO-Error.
mic is then in a messed state, fails now too ... at least for some time. On n+1 tries it works again ...

power_save is 0 but:

grep Power: /proc/asound/card0/codec#0 | nl
     1    Power: setting=D0, actual=D0
     2    Power: setting=D0, actual=D0
     3    Power: setting=D0, actual=D0
     4    Power: setting=D0, actual=D0
     5    Power: setting=D3, actual=D0
     6    Power: setting=D0, actual=D0
     7    Power: setting=D3, actual=D3
     8    Power: setting=D0, actual=D0
     9    Power: setting=D3, actual=D3
    10    Power: setting=D0, actual=D0
    11    Power: setting=D3, actual=D0
    12    Power: setting=D0, actual=D0
    13    Power: setting=D3, actual=D3
    14    Power: setting=D3, actual=D3

without the patch all was D0/D0 (=> https://bugzilla.kernel.org/attachment.cgi?id=212371)

power_save > 0 makes no difference.
Comment 29 Takashi Iwai 2016-04-17 20:26:50 UTC
Does 4.6-rc with the patch really work with line/mic switching?  I doubt it if 4.4.x doesn't work.

Maybe we need to add virtual paths from mic and line-in to both ADCs for keeping both paths up.  I'll work on it later.
Comment 30 chr() 2016-04-18 10:44:47 UTC
(In reply to Takashi Iwai from comment #29)
> Does 4.6-rc with the patch really work with line/mic switching?  I doubt it
> if 4.4.x doesn't work.
> 

I'm pretty sure I tested that. I'm going to triplecheck again.

What alsa-info/traces would be useful?
Comment 31 Takashi Iwai 2016-04-18 11:27:45 UTC
The trace while transition of the capture switch would be helpful.  i.e. start tracing at mic recording.  Keep trace and recording, and switch to line-in.  Confirm that the recording fails.  Then stop the trace, get the trace log and upload it.
Comment 32 chr() 2016-04-19 14:22:01 UTC
Hi!

4.6+patch is broken :(

It worked, because I stopped record before switching to line-in.

If I switch while recording, it gets stuck.

After this, recording always fails, regardless of the mixer setting. I got it somehow working again, but I can't reproduce how (switch a lot the mixer, curse+pray).

Notes:

arecord fail:
With kernel 4.4, arecord fails with I/O error and stops.
while under 4.6 it just stalls and hangs. I waited at least 4 minutes.

I rarely get an "overrun !!!" while recording works.

Mic-in: the signal is on right channel only. arecord -c1 always fails.

Strange power-transition (idle, just mixer switched):

grep -E 'Node|Power:' /proc/asound/card0/codec#0

line-in selected:
Node 0x0c [Pin Complex] wcaps 0x41048b: Stereo Amp-In
  Power: setting=D3, actual=D3

mic-selected:
Node 0x0c [Pin Complex] wcaps 0x41048b: Stereo Amp-In
  Power: setting=D3, actual=D0
=================^^=========^^

On the first try+error-run I got a kernel oops.

Question: does this card got 2 A/D each for the mic and the line-in? Just wondering that mic and line-in are exclusive where on other cards the inputs are mixed and usually have just 1 A/D ?
Comment 33 chr() 2016-04-19 14:25:31 UTC
Created attachment 213271 [details]
4.6-rc3+patch trace acecord+switch

0. set up mixer to mic
1. start trace
2. start arecord [ok] ~8secs
3. switch to line-in: arecord stalls
~10sec
4. switch back to mic-in
5. stop rec
Comment 34 chr() 2016-04-19 14:27:57 UTC
Created attachment 213281 [details]
4.6-rc3+patch kernel oops

Playing with alsamixer. I can't say if arecord was running.
Comment 35 Takashi Iwai 2016-04-19 15:12:52 UTC
Thanks.  So, maybe we need to keep powering up both ADCs for cirrus.
Could you try the patch below in addition?

The kernel WARNING with stack trace in comment 34 is rather spurious, I suppose.  Possibly a race between the proc read and the control access.  While the former wants the raw read, the latter needs non-bypassed access.

I may put some mutex for protecting it, but you can ignore it, so far.  It's no real crash but just a sanity check.
Comment 36 Takashi Iwai 2016-04-19 15:13:24 UTC
Created attachment 213291 [details]
Patch #2
Comment 37 chr() 2016-04-19 19:07:02 UTC
Hi,

patch 1+2 makes it going!

Tested: 4.6-rc3 and 4.4.7, power_save=0 and 1.

To try harder, I put machine in suspend, even while recording: works.

On wake up, all nodes are on D3 (!)
starting a rec, they become inconsistent
e.g. nid 0x0d setting=D3>D0 wakes up nid 0x0c
and it stays on D0
Comment 38 Takashi Iwai 2016-04-19 20:19:35 UTC
Great, then I'm going to submit and queue the fix patch.

(And note that the power change to D3 at suspend or runtime suspend is the standard behavior even before 4.4.)

The kernel WARNING may be fixed by yet another patch below.  It's totally untested yet.  Let me know if this looks working.

I guess the condition to trigger is to do capture-source switching and "cat /proc/asound/card0/codec#0" at the same time.  The warning should appear only the first shot after the driver (re)load, so it's rare in anyway.
Comment 39 Takashi Iwai 2016-04-19 20:20:07 UTC
Created attachment 213321 [details]
Patch to fix kernel WARNING
Comment 40 Takashi Iwai 2016-04-21 15:58:21 UTC
I rewrote the patch for kernel WARNING fix to a simpler one.  Try this one instead of the previous one.
Comment 41 Takashi Iwai 2016-04-21 15:58:45 UTC
Created attachment 213551 [details]
Revised patch to fix kernel WARNING
Comment 42 Takashi Iwai 2016-05-10 09:48:25 UTC
The patch landed to Linus tree.  Feel free to reopen if you still see the issue in the latest 4.6-rc.

Note You need to log in before you can comment on or make changes to this bug.