[alsa-devel] snd-hda-intel: no data when recording from mic, "IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj" logged in kern.log
Hi!
I think I have some interesting problems to analyse for Takashi.
Maybe my sound card model is a non typical one, but I have a continuous stream of capture-related problems with it.
It's an integrated sound card on my Gigabyte GA-MA74GM-S2H Rev. 1.1 motherboard.
"grep ^Codec /proc/asound/card0/codec#0" shows: Codec: Realtek ALC888
I'm attaching the full contents of /proc/asound/card0/codec#0 for identification.
But first, some background.
With this particular card, I've been continuously hit by the "azx_get_response timeout, switching to single_cmd mode" problem, described here: http://www.kernel.org/pub/linux/kernel/people/tiwai/docs/HD-Audio.html#_code...
However, in my case setting probe_mask=1 (experimentally determined) didn't make the problem go away, although it seemed to reduce its frequency (might be just a coincidence).
Whenever the dreaded "azx_get_response timeout, switching to single_cmd mode" message appeared in the kernel log, recording stopped working.
The card got into the bad state where it would not record sound, and arecord would be giving a stream of "overrun" error messages:
arecord -f cd output.wav Recording WAVE 'a.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo overrun!!! (at least 27.876 ms long) overrun!!! (at least 26.965 ms long) overrun!!! (at least 16.169 ms long) overrun!!! (at least 11.749 ms long) overrun!!! (at least 11.298 ms long) overrun!!! (at least 11.814 ms long) overrun!!! (at least 11.190 ms long) overrun!!! (at least 11.190 ms long) overrun!!! (at least 11.747 ms long) overrun!!! (at least 11.819 ms long) overrun!!! (at least 11.149 ms long) overrun!!! (at least 11.257 ms long) overrun!!! (at least 11.315 ms long) overrun!!! (at least 11.651 ms long) overrun!!! (at least 11.745 ms long) overrun!!! (at least 11.235 ms long) overrun!!! (at least 11.169 ms long) overrun!!! (at least 11.776 ms long) overrun!!! (at least 11.391 ms long) overrun!!! (at least 11.669 ms long) overrun!!! (at least 11.714 ms long) overrun!!! (at least 11.671 ms long) overrun!!! (at least 11.190 ms long)
What's notable, sound playback would continue to work OK.
After being fed up with interrupted Skype conversations (where I weren't immediately aware that the other side stopped hearing me, since I was hearing them), I've decided to upgrade do kernel 2.6.29 (citing the http://www.kernel.org/pub/linux/kernel/people/tiwai/docs/HD-Audio.html#_code... document: "Since 2.6.29 kernel, the driver has a more robust probing method, so this error might happen rarely, though").
After upgrading to 2.6.29 I've removed any extra snd-hda-intel options from modprobe config files.
Now the azx_get_response timeout seems to be gone, but I'm experiencing another problem: after some powered up time, recording starts giving empty streams - there's no error, but audio data has zero lengh.
e.g. when I arecord, I get a .wav file that is only 44 bytes long (which seems to be the length of the WAV header). When I make a Skype test call to echo123, and it starts playing back my message, it's zero length too - the playback end signal can be heard immediately after the playback start signal.
This problem seems to concide with the following error message in the kernel log: hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj.
Do you have any idea what could be the cause and how to debug this issue further?
At Wed, 23 Sep 2009 00:46:41 +0200, Aleksander Adamowski wrote:
Hi!
I think I have some interesting problems to analyse for Takashi.
Maybe my sound card model is a non typical one, but I have a continuous stream of capture-related problems with it.
It's an integrated sound card on my Gigabyte GA-MA74GM-S2H Rev. 1.1 motherboard.
"grep ^Codec /proc/asound/card0/codec#0" shows: Codec: Realtek ALC888
I'm attaching the full contents of /proc/asound/card0/codec#0 for identification.
But first, some background.
With this particular card, I've been continuously hit by the "azx_get_response timeout, switching to single_cmd mode" problem, described here: http://www.kernel.org/pub/linux/kernel/people/tiwai/docs/HD-Audio.html#_code...
However, in my case setting probe_mask=1 (experimentally determined) didn't make the problem go away, although it seemed to reduce its frequency (might be just a coincidence).
Whenever the dreaded "azx_get_response timeout, switching to single_cmd mode" message appeared in the kernel log, recording stopped working.
The card got into the bad state where it would not record sound, and arecord would be giving a stream of "overrun" error messages:
arecord -f cd output.wav Recording WAVE 'a.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo overrun!!! (at least 27.876 ms long) overrun!!! (at least 26.965 ms long) overrun!!! (at least 16.169 ms long) overrun!!! (at least 11.749 ms long) overrun!!! (at least 11.298 ms long) overrun!!! (at least 11.814 ms long) overrun!!! (at least 11.190 ms long) overrun!!! (at least 11.190 ms long) overrun!!! (at least 11.747 ms long) overrun!!! (at least 11.819 ms long) overrun!!! (at least 11.149 ms long) overrun!!! (at least 11.257 ms long) overrun!!! (at least 11.315 ms long) overrun!!! (at least 11.651 ms long) overrun!!! (at least 11.745 ms long) overrun!!! (at least 11.235 ms long) overrun!!! (at least 11.169 ms long) overrun!!! (at least 11.776 ms long) overrun!!! (at least 11.391 ms long) overrun!!! (at least 11.669 ms long) overrun!!! (at least 11.714 ms long) overrun!!! (at least 11.671 ms long) overrun!!! (at least 11.190 ms long)
What's notable, sound playback would continue to work OK.
After being fed up with interrupted Skype conversations (where I weren't immediately aware that the other side stopped hearing me, since I was hearing them), I've decided to upgrade do kernel 2.6.29 (citing the http://www.kernel.org/pub/linux/kernel/people/tiwai/docs/HD-Audio.html#_code... document: "Since 2.6.29 kernel, the driver has a more robust probing method, so this error might happen rarely, though").
After upgrading to 2.6.29 I've removed any extra snd-hda-intel options from modprobe config files.
Now the azx_get_response timeout seems to be gone, but I'm experiencing another problem: after some powered up time, recording starts giving empty streams - there's no error, but audio data has zero lengh.
e.g. when I arecord, I get a .wav file that is only 44 bytes long (which seems to be the length of the WAV header). When I make a Skype test call to echo123, and it starts playing back my message, it's zero length too - the playback end signal can be heard immediately after the playback start signal.
This problem seems to concide with the following error message in the kernel log: hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj.
Do you have any idea what could be the cause and how to debug this issue further?
First off, try the very latest alsa-driver snapshot. 2.6.29 is already very old, and there have been bunch of fixes and improvements since then.
Also, load the driver with model=auto option, too.
If both don't help, please attach alsa-info.sh output (run with --no-upload option) to analyze more.
thanks,
Takashi
On Wed, Sep 23, 2009 at 8:01 AM, Takashi Iwai tiwai@suse.de wrote:
This problem seems to concide with the following error message in the kernel log: hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj.
Do you have any idea what could be the cause and how to debug this issue further?
First off, try the very latest alsa-driver snapshot. 2.6.29 is already very old, and there have been bunch of fixes and improvements since then.
Also, load the driver with model=auto option, too.
If both don't help, please attach alsa-info.sh output (run with --no-upload option) to analyze more.
OK, I've upgraded to kernel 2.6.30, then installed the alsa-driver-20090923 snapshot (configured with --with-debug=full).
I'm also running with the following options: bdl_pos_adj=32 probe_mask=1 model=auto
I'm attaching output from alsa-info.sh just in case.
If the problem reappears, I'll let you know.
If it doesn't, then I'll try running without any snd-hda-intel options whatsoever, using only defaults.
At Thu, 24 Sep 2009 09:23:59 +0200, Aleksander Adamowski wrote:
On Wed, Sep 23, 2009 at 8:01 AM, Takashi Iwai tiwai@suse.de wrote:
This problem seems to concide with the following error message in the kernel log: hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj.
Do you have any idea what could be the cause and how to debug this issue further?
First off, try the very latest alsa-driver snapshot. 2.6.29 is already very old, and there have been bunch of fixes and improvements since then.
Also, load the driver with model=auto option, too.
If both don't help, please attach alsa-info.sh output (run with --no-upload option) to analyze more.
OK, I've upgraded to kernel 2.6.30, then installed the alsa-driver-20090923 snapshot (configured with --with-debug=full).
I'm also running with the following options: bdl_pos_adj=32 probe_mask=1 model=auto
First try just with model=auto and no other options.
I'm attaching output from alsa-info.sh just in case.
Thanks.
Takashi
On Thu, Sep 24, 2009 at 9:31 AM, Takashi Iwai tiwai@suse.de wrote:
First try just with model=auto and no other options.
OK, after a couple days running with the alsa-driver-20090923 snapshot (with model=auto and no other options), I can see that the problem is mostly gone.
The only time I can see "hda_intel: azx_get_response timeout, switching to single_cmd mode", is during a single system shutdown - the last kernel log entries look like this:
Oct 3 15:54:29 localhost kernel: [19194.705513] ALSA hda_intel.c:699: azx_get_response timeout, switching to polling mode: last cmd=0x00cb2001 Oct 3 15:54:30 localhost kernel: [19195.709511] ALSA hda_intel.c:723: hda_intel: azx_get_response timeout, switching to single_cmd mode: last cmd=0x00cb2001 Oct 3 15:54:30 localhost kernel: [19195.709649] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.709714] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.709778] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.709849] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.709918] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.709988] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.710057] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.710127] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.710196] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.710266] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.710335] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.710404] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.710474] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.710543] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.710612] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.710681] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.710751] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.710820] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.710890] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.710960] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.711029] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.711098] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.711168] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.711237] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.711306] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.711376] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.711445] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.711514] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.711584] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.711654] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.711724] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.711793] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.711862] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.711932] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.712001] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.712070] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.712140] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.712209] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.712278] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.712348] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.712417] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.712487] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.712557] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.712626] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.712696] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.712765] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.712834] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.712904] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.712973] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.713043] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.713113] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.713183] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.713252] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.713322] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.713391] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.713460] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.713534] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.713604] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.713673] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.713743] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.713812] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.713882] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.713951] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.714021] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.714091] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.714160] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.714229] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180 Oct 3 15:54:30 localhost kernel: [19195.714299] ALSA hda_intel.c:647: spurious response 0x0:0x0, last cmd=0xc36180
Obviously, I were unable to extract any diagnostic information or test whether recording was possible at the moment, since the system was shutting down.
During subsequent shutdowns, I didn't observe those log messages.
I'm curious what could cause them, though.
At Mon, 5 Oct 2009 02:28:37 +0200, Aleksander Adamowski wrote:
On Thu, Sep 24, 2009 at 9:31 AM, Takashi Iwai tiwai@suse.de wrote:
First try just with model=auto and no other options.
OK, after a couple days running with the alsa-driver-20090923 snapshot (with model=auto and no other options), I can see that the problem is mostly gone.
Does this happen with the later snapshot?
Takashi
On Mon, Oct 5, 2009 at 7:29 AM, Takashi Iwai tiwai@suse.de wrote:
At Mon, 5 Oct 2009 02:28:37 +0200, Aleksander Adamowski wrote:
On Thu, Sep 24, 2009 at 9:31 AM, Takashi Iwai tiwai@suse.de wrote:
First try just with model=auto and no other options.
OK, after a couple days running with the alsa-driver-20090923 snapshot (with model=auto and no other options), I can see that the problem is mostly gone.
Does this happen with the later snapshot?
To be exact, with snapshot 20090923 this has happened only once and I have had several shutdowns on that version of alsa-driver snapshot and kernel.
I've installed alsa-driver-20091005 and will pay attention when/if this will occur again.
On Mon, Oct 5, 2009 at 7:29 AM, Takashi Iwai tiwai@suse.de wrote:
At Mon, 5 Oct 2009 02:28:37 +0200, Aleksander Adamowski wrote:
On Thu, Sep 24, 2009 at 9:31 AM, Takashi Iwai tiwai@suse.de wrote:
First try just with model=auto and no other options.
OK, after a couple days running with the alsa-driver-20090923 snapshot (with model=auto and no other options), I can see that the problem is mostly gone.
Does this happen with the later snapshot?
Hi!
After running for almost ten days with alsa-driver-20091005, I didn't observe that problem.
However, a new one (well, one with slightly different symptoms) has surfaced.
The difference is only in the log files. During a Skype conversation, the other side has stopped hearing us; after trying to record some sound with arecord, I got an empty stream (a 44 byte WAV file with only a header) - just like previously.
However, this time there were no messages in the kernel logs whatsoever - no "azx_get_response timeout", no "Suggest a bigger bdl_pos_adj". Arecord also didn't flood the console with overrun errors - it was completely silent apart from the fact that it did not record anything.
The only hda-related entries I saw in the kernel log were a couple hours earlier at 20:44 - while the failure has occured between 23:00 and 00:00.
At 20:44 the following has been logged:
Oct 13 20:44:25 hostname kernel: [117828.065069] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.073562] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.083367] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.578958] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.584872] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.592909] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.651513] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.657009] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.665794] ALSA hda_intel.c:1187: Too big adjustment 32
The machine is currently still in the failed state - I cannot record anything until I reboot.
Concerning that problem, after a reboot the problem has reoccured two days later:
Oct 17 14:16:09 hostname kernel: [192087.249165] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 17 14:22:08 hostname kernel: [192447.072018] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 17 14:22:38 hostname kernel: [192477.062967] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 17 14:23:06 hostname kernel: [192504.918440] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 17 14:23:37 hostname kernel: [192535.594196] ALSA hda_intel.c:1187: Too big adjustment 32
Uploaded new alsa-info.sh data from the machine: http://www.alsa-project.org/db/?f=e7e696254df6f61fa5e4755e9d1d06403dacf144
Upgrading from alsa-driver-20091005 to alsa-driver-20091017 and will let you know how it worked.
On Wed, Oct 14, 2009 at 9:04 AM, Aleksander Adamowski alsa@olo.org.pl wrote:
After running for almost ten days with alsa-driver-20091005, I didn't observe that problem.
However, a new one (well, one with slightly different symptoms) has surfaced.
The difference is only in the log files. During a Skype conversation, the other side has stopped hearing us; after trying to record some sound with arecord, I got an empty stream (a 44 byte WAV file with only a header) - just like previously.
However, this time there were no messages in the kernel logs whatsoever - no "azx_get_response timeout", no "Suggest a bigger bdl_pos_adj". Arecord also didn't flood the console with overrun errors - it was completely silent apart from the fact that it did not record anything.
The only hda-related entries I saw in the kernel log were a couple hours earlier at 20:44 - while the failure has occured between 23:00 and 00:00.
At 20:44 the following has been logged:
Oct 13 20:44:25 hostname kernel: [117828.065069] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.073562] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.083367] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.578958] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.584872] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.592909] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.651513] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.657009] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.665794] ALSA hda_intel.c:1187: Too big adjustment 32
The machine is currently still in the failed state - I cannot record anything until I reboot.
-- Best Regards, Aleksander Adamowski http://olo.org.pl
BTW, Takashi, if that would be of any help, I could add some #ifdef's to the driver's code that would log additional information, if you could tell me what to log. It seems that the current log messages aren't detailed enough to diagnose the problem.
For starters, I've added this:
diff -ruN alsa-driver-20091017.orig/alsa-kernel/pci/hda/hda_intel.c alsa-driver-20091017/alsa-kernel/pci/hda/hda_intel.c --- alsa-driver-20091017.orig/alsa-kernel/pci/hda/hda_intel.c 2009-10-15 00:05:03.000000000 +0200 +++ alsa-driver-20091017/alsa-kernel/pci/hda/hda_intel.c 2009-10-17 19:07:19.283328740 +0200 @@ -1182,8 +1182,8 @@ pos_align; pos_adj = frames_to_bytes(runtime, pos_adj); if (pos_adj >= period_bytes) { - snd_printk(KERN_WARNING SFX "Too big adjustment %d\n", - bdl_pos_adj[chip->dev_index]); + snd_printk(KERN_WARNING SFX "Too big adjustment %d, pos_adj: %d, period_bytes: %d\n", + bdl_pos_adj[chip->dev_index], pos_adj, period_bytes); pos_adj = 0; } else { ofs = setup_bdle(substream, azx_dev,
On Sat, Oct 17, 2009 at 2:57 PM, Aleksander Adamowski alsa@olo.org.pl wrote:
Concerning that problem, after a reboot the problem has reoccured two days later:
Oct 17 14:16:09 hostname kernel: [192087.249165] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 17 14:22:08 hostname kernel: [192447.072018] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 17 14:22:38 hostname kernel: [192477.062967] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 17 14:23:06 hostname kernel: [192504.918440] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 17 14:23:37 hostname kernel: [192535.594196] ALSA hda_intel.c:1187: Too big adjustment 32
Uploaded new alsa-info.sh data from the machine: http://www.alsa-project.org/db/?f=e7e696254df6f61fa5e4755e9d1d06403dacf144
Upgrading from alsa-driver-20091005 to alsa-driver-20091017 and will let you know how it worked.
On Wed, Oct 14, 2009 at 9:04 AM, Aleksander Adamowski alsa@olo.org.pl wrote:
After running for almost ten days with alsa-driver-20091005, I didn't observe that problem.
However, a new one (well, one with slightly different symptoms) has surfaced.
The difference is only in the log files. During a Skype conversation, the other side has stopped hearing us; after trying to record some sound with arecord, I got an empty stream (a 44 byte WAV file with only a header) - just like previously.
However, this time there were no messages in the kernel logs whatsoever - no "azx_get_response timeout", no "Suggest a bigger bdl_pos_adj". Arecord also didn't flood the console with overrun errors - it was completely silent apart from the fact that it did not record anything.
The only hda-related entries I saw in the kernel log were a couple hours earlier at 20:44 - while the failure has occured between 23:00 and 00:00.
At 20:44 the following has been logged:
Oct 13 20:44:25 hostname kernel: [117828.065069] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.073562] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.083367] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.578958] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.584872] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.592909] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.651513] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.657009] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.665794] ALSA hda_intel.c:1187: Too big adjustment 32
The machine is currently still in the failed state - I cannot record anything until I reboot.
-- Best Regards, Aleksander Adamowski http://olo.org.pl
-- Best Regards, Aleksander Adamowski http://olo.org.pl
Hello again Takashi,
Got no answer from you back in October and I still experience the sound capture problem, no daily release of alsa-driver would observably solve the problem to date. Capture stops working; sometimes arecord is silent but produces no output, sometimes it outputs a flood of "overrun!!! (at least 27.876 ms long)".
The problem persists until system is rebooted.
The kernel log error messages no longer occur at the moment time when capture stops working (previosly they did), but when rebooting I usually get a short burst of either "Too big adjustment 32" or "azx_get_response timeout" errors:
kern.log:Mar 15 13:39:06 stacja kernel: [22003.694323] ALSA hda_intel.c:1220: Too big adjustment 32 kern.log:Mar 15 13:39:06 stacja kernel: [22003.714642] ALSA hda_intel.c:1220: Too big adjustment 32 ...... kern.log:Mar 15 13:42:41 stacja kernel: [22218.254581] ALSA hda_intel.c:1220: Too big adjustment 32 kern.log:Mar 15 13:42:41 stacja kernel: [22218.275689] ALSA hda_intel.c:1220: Too big adjustment 32 kern.log:Mar 15 13:59:01 stacja kernel: [ 22.431420] HDA Intel 0000:00:14.2: PCI INT A -> GSI 16 (level, low) -> IRQ 16 kern.log:Mar 15 13:59:01 stacja kernel: [ 22.577821] ALSA hda_codec.c:3441: hda_codec: model 'auto' is selected kern.log:Mar 15 13:59:01 stacja kernel: [ 22.577828] ALSA hda_codec.c:4356: autoconfig: line_outs=1 (0x14/0x0/0x0/0x0/0x0) kern.log:Mar 15 13:59:01 stacja kernel: [ 22.577832] ALSA hda_codec.c:4360: speaker_outs=0 (0x0/0x0/0x0/0x0/0x0) kern.log:Mar 15 13:59:01 stacja kernel: [ 22.577835] ALSA hda_codec.c:4364: hp_outs=1 (0x1b/0x0/0x0/0x0/0x0) kern.log:Mar 15 13:59:01 stacja kernel: [ 22.577838] ALSA hda_codec.c:4365: mono: mono_out=0x0 kern.log:Mar 15 13:59:01 stacja kernel: [ 22.577840] ALSA hda_codec.c:4368: dig-out=0x1e/0x0 kern.log:Mar 15 13:59:01 stacja kernel: [ 22.577842] ALSA hda_codec.c:4376: inputs: mic=0x18, fmic=0x19, line=0x1a, fline=0x0, cd=0x0, aux=0x0 kern.log:Mar 15 13:59:01 stacja kernel: [ 22.579420] input: HDA Digital PCBeep as /devices/pci0000:00/0000:00:14.2/input/input6 kern.log:Mar 15 13:59:01 stacja kernel: [ 22.583527] HDA Intel 0000:01:05.2: PCI INT B -> GSI 19 (level, low) -> IRQ 19 kern.log:Mar 15 13:59:01 stacja kernel: [ 22.583591] HDA Intel 0000:01:05.2: irq 27 for MSI/MSI-X
Unfortunately, the "azx_get_response timeout" logs occured before 2010-03-07 and were eaten by my logrotate script.
I've uploaded the alsa-info.sh data to the ALSA project hardware database: http://www.alsa-project.org/db/?f=cf97d7cd4a29c306ddc6ca86a64842cb7cb9f634
My current module parameters are: options snd-hda-intel model=auto probe_mask=1
I've also tried several other combinations, none of which really helped. Here's my annotated modprobe config file, annotations explain which options caused what effects. Unannotated entries simply didn't change much WRT to the problem, apart from shuffling available mixer controls:
#options snd-hda-intel model=3stack-6ch #options snd-hda-intel model=6stack-dig # Advised at http://forum.ubuntu.pl/showthread.php?t=67236 : #options snd-hda-intel model=acer-aspire #options snd-hda-intel model=5stack #options snd-hda-intel model=auto
# See http://www.kernel.org/pub/linux/kernel/people/tiwai/docs/HD-Audio.html, "Codec-Probing Problem": #options snd-hda-intel model=auto probe_mask=1 # doesn't help, "hda_intel: azx_get_response timeout, switching to single_cmd mode" still happens. Upgrading kernel to 2.6.29. # upgrading didn't help but the message disappeared.
# See http://kerneltrap.org/mailarchive/git-commits-head/2008/7/14/2478124/thread #options snd-hda-intel bdl_pos_adj=32 probe_mask=1 model=auto
# This conf still has capture problems (e.g. 2010-03-13): options snd-hda-intel model=auto probe_mask=1
# This conf prevents audio from working at all: #options snd-hda-intel model=auto probe_mask=8
# Needs testing: #options snd-hda-intel model=auto probe_mask=1 position_fix=1
# Needs testing: # http://www.linuxhardware.org/forums/viewtopic.php?t=9 : #options snd-hda-intel model=3stack-6ch position_fix=1 bdl_pos_adj=0
http://www.alsa-project.org/db/?f=cf97d7cd4a29c306ddc6ca86a64842cb7cb9f634The most important question for me now is whether the additional logging statements from my patch will assist in debugging this problem?
On Sat, Oct 17, 2009 at 18:09, Aleksander Adamowski alsa@olo.org.pl wrote:
BTW, Takashi, if that would be of any help, I could add some #ifdef's to the driver's code that would log additional information, if you could tell me what to log. It seems that the current log messages aren't detailed enough to diagnose the problem.
For starters, I've added this:
diff -ruN alsa-driver-20091017.orig/alsa-kernel/pci/hda/hda_intel.c alsa-driver-20091017/alsa-kernel/pci/hda/hda_intel.c --- alsa-driver-20091017.orig/alsa-kernel/pci/hda/hda_intel.c 2009-10-15 00:05:03.000000000 +0200 +++ alsa-driver-20091017/alsa-kernel/pci/hda/hda_intel.c 2009-10-17 19:07:19.283328740 +0200 @@ -1182,8 +1182,8 @@ pos_align; pos_adj = frames_to_bytes(runtime, pos_adj); if (pos_adj >= period_bytes) {
snd_printk(KERN_WARNING SFX "Too big adjustment%d\n",
bdl_pos_adj[chip->dev_index]);
snd_printk(KERN_WARNING SFX "Too bigadjustment %d, pos_adj: %d, period_bytes: %d\n",
bdl_pos_adj[chip->dev_index],pos_adj, period_bytes); pos_adj = 0; } else { ofs = setup_bdle(substream, azx_dev,
On Sat, Oct 17, 2009 at 2:57 PM, Aleksander Adamowski alsa@olo.org.pl wrote:
Concerning that problem, after a reboot the problem has reoccured two days later:
Oct 17 14:16:09 hostname kernel: [192087.249165] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 17 14:22:08 hostname kernel: [192447.072018] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 17 14:22:38 hostname kernel: [192477.062967] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 17 14:23:06 hostname kernel: [192504.918440] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 17 14:23:37 hostname kernel: [192535.594196] ALSA hda_intel.c:1187: Too big adjustment 32
Uploaded new alsa-info.sh data from the machine:
http://www.alsa-project.org/db/?f=e7e696254df6f61fa5e4755e9d1d06403dacf144
Upgrading from alsa-driver-20091005 to alsa-driver-20091017 and will let you know how it worked.
On Wed, Oct 14, 2009 at 9:04 AM, Aleksander Adamowski alsa@olo.org.pl
wrote:
After running for almost ten days with alsa-driver-20091005, I didn't observe that problem.
However, a new one (well, one with slightly different symptoms) has
surfaced.
The difference is only in the log files. During a Skype conversation, the other side has stopped hearing us; after trying to record some sound with arecord, I got an empty stream (a 44 byte WAV file with only a header) - just like previously.
However, this time there were no messages in the kernel logs whatsoever - no "azx_get_response timeout", no "Suggest a bigger bdl_pos_adj". Arecord also didn't flood the console with overrun errors - it was completely silent apart from the fact that it did not record anything.
The only hda-related entries I saw in the kernel log were a couple hours earlier at 20:44 - while the failure has occured between 23:00 and 00:00.
At 20:44 the following has been logged:
Oct 13 20:44:25 hostname kernel: [117828.065069] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.073562] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.083367] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.578958] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.584872] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.592909] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.651513] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.657009] ALSA hda_intel.c:1187: Too big adjustment 32 Oct 13 20:44:25 hostname kernel: [117828.665794] ALSA hda_intel.c:1187: Too big adjustment 32
The machine is currently still in the failed state - I cannot record anything until I reboot.
-- Best Regards, Aleksander Adamowski http://olo.org.pl
-- Best Regards, Aleksander Adamowski http://olo.org.pl
-- Best Regards, Aleksander Adamowski http://olo.org.pl
-
Aleksander Adamowski -
Takashi Iwai