Hi,
I have been discussing this problem over the alsa-devel mailing list and
Daniel Mack asked me if I could repost my finding over here.
If I use ALSA for playback while my wifi card is on but not connected to
any AP (it is possibly scanning the air to find APs), I experience what
ALSA calls underruns at regular interval (about every 1-2 seconds).
underruns makes audible short click sounds.
If I connect to a Wifi network or close the Wifi, the crackles and
clicks go away. my explanation of the behavior is that in that specific
state, the rtl8192ce driver is disabling interrupts for too long and
stop my sound device irqs to be timely serviced.
I am currently using kernel 3.12.7 but I had this small problem as far
as I remember. At least since 3.7. This is important as I have noticed
that rtl8192ce did change in 3.12.7
Here is the HW in question:
00:1b.0 Audio device [0403]: Intel Corporation NM10/ICH7 Family High
Definition Audio Controller [8086:27d8] (rev 02)
Subsystem: Hewlett-Packard Company Device [103c:1584]
Flags: bus master, fast devsel, latency 0, IRQ 45
Memory at 96200000 (64-bit, non-prefetchable) [size=16K]
Capabilities: [50] Power Management version 2
Capabilities: [60] MSI: Enable+ Count=1/1 Maskable- 64bit+
Capabilities: [70] Express Root Complex Integrated Endpoint, MSI 00
Capabilities: [100] Virtual Channel
Capabilities: [130] Root Complex Link
Kernel driver in use: snd_hda_intel
Kernel modules: snd_hda_intel
01:00.0 Network controller [0280]: Realtek Semiconductor Co., Ltd.
RTL8188CE 802.11b/g/n WiFi Adapter [10ec:8176] (rev 01)
Subsystem: Hewlett-Packard Company Device [103c:1629]
Flags: bus master, fast devsel, latency 0, IRQ 16
I/O ports at 3000 [size=256]
Memory at 95000000 (64-bit, non-prefetchable) [size=16K]
Capabilities: [40] Power Management version 3
Capabilities: [50] MSI: Enable- Count=1/1 Maskable- 64bit+
Capabilities: [70] Express Endpoint, MSI 00
Capabilities: [100] Advanced Error Reporting
Capabilities: [140] Virtual Channel
Capabilities: [160] Device Serial Number 01-91-81-fe-ff-4c-e0-00
Kernel driver in use: rtl8192ce
Kernel modules: rtl8192ce
How to reproduce:
1. Enable Wifi while not connecting to any AP.
2. lano1106@hpmini ~/Music $ aplay -c1 sine.wav
underrun!!! (at least 1856093977.967 ms long)
On 01/15/2014 12:37 AM, Olivier Langlois wrote:
> How to reproduce:
>
> 1. Enable Wifi while not connecting to any AP.
> 2. lano1106@hpmini ~/Music $ aplay -c1 sine.wav
> underrun!!! (at least 1856093977.967 ms long)
Olivier,
I am certain that rtl8192ce does not disable interrupts for 2 sec, but I need
some more info from you.
What is your CPU situation? I suspect x86_64, but please confirm. How many CPUs?
What is the maximum CPU speed?
What distro?
How do you control the wifi? Is it NetworkManager? This is important because the
device driver does not initiate any scans on its own - scans are initiated and
controlled by upstream.
Please provide a URL for the test file sine.wav. If it is part of your distro,
then put it in a public repository, or E-mail it to me privately.
Larry
On Mon, Jan 27, 2014 at 01:32:03AM -0500, Olivier Langlois wrote:
> Here is the sequence of events that I have traced that seem to cause my
> audio playback underrun.
>
> 1. wpa_supplicant send a start_scan request to the nl80211 driver
> 2. mac80211 module call rtl_op_config with IEEE80211_CONF_CHANGE_IDLE
> 3. rtl_ips_nic_on is called which disable local irqs
> 4. rtl92c_phy_set_rf_power_state() is called
> 5. rtl_ps_enable_nic() is called and enable interrupts on the
> device
> 6. as soon as local irqs are reenabled before exiting rtl_ips_nic_on,
> a RX interrupt is handled and _rtl_pci_interrupt appears to be taking
> about 340 ms to process the interrupt.
Good data. This discovery now points more firmly at the wireless
driver as a contributing cause.
You might further diagnose this by tracing the timing of the interrupt
handler, to see if it is something the handler calls that causes the
delay, or if it is device access that does it.
--
James Cameron
http://quozl.linux.org.au/
Hi Larry,
I have not hear back from you since that I provided the information that
you asked me. Did you find something?
I did some investigation on my side and I think that I have narrow down
quite a bit the cause of my problem unless I receive some assistance, I
am not sure that I can advance very much further by myself.
Is this usual for a Wifi device to spend about 340 ms in a irq
handler???
First, something that I have noticed in net/wireless/rtlwifi/core.c,
function rtl_op_config(), there is a call to mdelay(50). I'm pretty much
certain that this delay could be safely replaced with msleep(50). It
should be ok since the function can already sleep by calling
mutex_lock(). Do you agree?
Here is the sequence of events that I have traced that seem to cause my
audio playback underrun.
1. wpa_supplicant send a start_scan request to the nl80211 driver
2. mac80211 module call rtl_op_config with IEEE80211_CONF_CHANGE_IDLE
3. rtl_ips_nic_on is called which disable local irqs
4. rtl92c_phy_set_rf_power_state() is called
5. rtl_ps_enable_nic() is called and enable interrupts on the
device
6. as soon as local irqs are reenabled before exiting rtl_ips_nic_on,
a RX interrupt is handled and _rtl_pci_interrupt appears to be taking
about 340 ms to process the interrupt.
I have measured that time by placing 2 printks between
spin_unlock_irqrestore(&rtlpriv->locks.ips_lock, flags);
in rtl_ips_nic_on().
[ 69.376012] rtlwifi:rtl_ips_nic_on():<0-1> before
spin_unlock_irqrestore
[ 69.711920] rtl_pci:_rtl_pci_interrupt():<10000-1> Rx ok interrupt!
[ 69.711948] rtlwifi:rtl_ips_nic_on():<0-0> after
spin_unlock_irqrestore
Also from an exchange that I had with Takashi [1], if my audio buffer
size is 371 msec, the playback is smooth. If it is set to 341 msec, I
have underruns.
notice the proximity of values between the time it takes for rtl8192ce
to service its irq and the audio buffer size causing troubles. I think
that it would be very surprising if it is just a coincidence....
[1]
http://mailman.alsa-project.org/pipermail/alsa-devel/2014-January/071569.html
On Wed, 2014-01-15 at 11:01 -0600, Larry Finger wrote:
> On 01/15/2014 12:37 AM, Olivier Langlois wrote:
> > How to reproduce:
> >
> > 1. Enable Wifi while not connecting to any AP.
> > 2. lano1106@hpmini ~/Music $ aplay -c1 sine.wav
> > underrun!!! (at least 1856093977.967 ms long)
>
> Olivier,
>
> I am certain that rtl8192ce does not disable interrupts for 2 sec, but I need
> some more info from you.
>
> What is your CPU situation? I suspect x86_64, but please confirm. How many CPUs?
> What is the maximum CPU speed?
>
> What distro?
>
> How do you control the wifi? Is it NetworkManager? This is important because the
> device driver does not initiate any scans on its own - scans are initiated and
> controlled by upstream.
>
> Please provide a URL for the test file sine.wav. If it is part of your distro,
> then put it in a public repository, or E-mail it to me privately.
>
> Larry
>
>
>
At Thu, 23 Jan 2014 16:15:19 +0000,
LANGLOIS Olivier PIS -EXT wrote:
>
> Takashi,
>
> > > 2. I was expecting to see XRUN entries in dmesg but I didn't. The
> > > closest that I have is [ 1700.756017] PCM: Lost interrupts? [Q]
> > > (stream=0, delta=16108, new_hw_ptr=383756, old_hw_ptr=367648) 3. I
> > > didn't realise that the default ALSA device was a plugin using dmix. I
> > > have no underruns by using directly the ALSA HW device (hw:0,0)
> >
> > The dmix uses the fixed configuration. Did you try playback using hw but
> > with the same configuration (period size, buffer size, format)?
> >
> this is a very good observation.
>
> With the same buffer/period sizes at a sampling rate of 44100 (this slightly modify the buffer/period times), I have 0 underruns. As soon as I resample my wav file to 48kHz, boom the underruns happens.
>
> So if I understand correctly by reducing the buffer time correctly from 371504 usec to 341328 usec and by assuming that the buffer is full, if the snd_hda_intel irq/timer are delayed to a greater amount of time than 341328 usec, this is what is causing the underruns.
Which machine and codec? For example, Lenovo IdeaPad with ALC269 is
known to be broken with 48kHz, so we have a fixed rate limitation in
the driver.
Other than the hardware restriction, you may play more with
position_fix or bdl_pos_adj option of snd-hda-intel driver.
Takashi
>
> Maybe it is important to the discussion that my CONFIG_HZ=1000 and
>
> $ zgrep PREEMPT /proc/config.gz
> CONFIG_TREE_PREEMPT_RCU=y
> CONFIG_PREEMPT_RCU=y
> # CONFIG_PREEMPT_NONE is not set
> # CONFIG_PREEMPT_VOLUNTARY is not set
> CONFIG_PREEMPT=y
> CONFIG_PREEMPT_COUNT=y
> # CONFIG_DEBUG_PREEMPT is not set
> # CONFIG_PREEMPT_TRACER is not set
>
> $ aplay -Dhw:0,0 --period-size=1024 --buffer-size=16384 -v sine.wav
> Playing WAVE 'sine.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo
> Hardware PCM card 0 'HDA Intel' device 0 subdevice 0
> Its setup is:
> stream : PLAYBACK
> access : RW_INTERLEAVED
> format : S16_LE
> subformat : STD
> channels : 2
> rate : 44100
> exact rate : 44100 (44100/1)
> msbits : 16
> buffer_size : 16384
> period_size : 1024
> period_time : 23219
> tstamp_mode : NONE
> period_step : 1
> avail_min : 1024
> period_event : 0
> start_threshold : 16384
> stop_threshold : 16384
> silence_threshold: 0
> silence_size : 0
> boundary : 1073741824
> appl_ptr : 0
> hw_ptr : 0
>
> $ aplay -Dhw:0,0 --period-size=1024 --buffer-size=16384 -v sine_48000.wav
> Playing WAVE 'sine_48000.wav' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
> Hardware PCM card 0 'HDA Intel' device 0 subdevice 0
> Its setup is:
> stream : PLAYBACK
> access : RW_INTERLEAVED
> format : S16_LE
> subformat : STD
> channels : 2
> rate : 48000
> exact rate : 48000 (48000/1)
> msbits : 16
> buffer_size : 16384
> period_size : 1024
> period_time : 21333
> tstamp_mode : NONE
> period_step : 1
> avail_min : 1024
> period_event : 0
> start_threshold : 16384
> stop_threshold : 16384
> silence_threshold: 0
> silence_size : 0
> boundary : 1073741824
> appl_ptr : 0
> hw_ptr : 0
> underrun!!! (at least 0.075 ms long)
> Status:
> state : XRUN
> trigger_time: 2155.298508067
> tstamp : 2155.299242462
> delay : 0
> avail : 16815
> avail_max : 16815
>
>
> ________________________________
> CONFIDENTIALITY : This e-mail and any attachments are confidential and may be privileged. If you are not a named recipient, please notify the sender immediately and do not disclose the contents to another person, use it for any purpose or store or copy the information in any medium.
>
On Thu, Jan 16, 2014 at 12:25:42AM -0500, Olivier Langlois wrote:
> On 01/15/2014 12:01 PM, Larry Finger wrote:
> >On 01/15/2014 12:37 AM, Olivier Langlois wrote:
> >>How to reproduce:
> >>
> >>1. Enable Wifi while not connecting to any AP.
> >>2. lano1106@hpmini ~/Music $ aplay -c1 sine.wav
> >>underrun!!! (at least 1856093977.967 ms long)
Indeed, that timing is fishy.
I've looked at the alsa-devel thread [1] and your problem description
there.
At OLPC during development we found similar symptoms showing up in
ALSA playback that were contributed to other drivers, but the
underlying causes were in the ALSA driver for our codec chip, and the
other drivers were changing the appearance of the fault only because
of timing changes.
But there's no need to conclude that interrupts were disabled or
delayed. There can be many other causes.
The timing miscalculation by ALSA might be important. I can't figure
out how a wireless driver can easily cause that.
1.
http://mailman.alsa-project.org/pipermail/alsa-devel/2014-January/071142.html
--
James Cameron
http://quozl.linux.org.au/
Takashi,
On Thu, 2014-01-23 at 17:29 +0100, Takashi Iwai wrote:
> Which machine and codec? For example, Lenovo IdeaPad with ALC269 is
> known to be broken with 48kHz, so we have a fixed rate limitation in
> the driver.
>
it is a hpmini. I have this from dmesg:
[ 9.638142] hda_codec: 92HD81B1X5: Apply fix-func for HP
[ 9.639859] hda-codec: Enable HP auto-muting on NID 0xb
[ 9.639888] hda-codec: Enable auto-mic switch on NID 0x11/0xa/0x0
[ 9.642312] hda_codec: 92HD81B1X5: Apply fix-func for HP
> Other than the hardware restriction, you may play more with
> position_fix or bdl_pos_adj option of snd-hda-intel driver.
>
thank you for the advice. I'll take a look on these params to see what
they do. However, because my sound card works very well all the time
except that I have underruns that happens only when wpa_supplicant is
doing this:
wlan0: Control interface command 'STATUS'
wlan0: State: DISCONNECTED -> SCANNING
...
wlan0: No suitable network found
wlan0: Setting scan request: 5 sec 0 usec
wlan0: Checking for other virtual interfaces sharing same radio (phy0)
in event_scan_results
wlan0: Starting AP scan for wildcard SSID
WPS: Building WPS IE for Probe Request
WPS: * Version (hardcoded 0x10)
WPS: * Request Type
WPS: * Config Methods (148)
WPS: * UUID-E
WPS: * Primary Device Type
WPS: * RF Bands (1)
WPS: * Association State
WPS: * Configuration Error (0)
WPS: * Device Password ID (0)
WPS: * Device Name
P2P: * P2P IE header
P2P: * Capability dev=21 group=00
P2P: * Listen Channel: Regulatory Class 81 Channel 1
nl80211: Scan SSID - hexdump_ascii(len=0): [NULL]
nl80211: Scan extra IEs - hexdump(len=101): xxx
Scan requested (ret=0) - scan timeout 30 seconds
nl80211: Event message available
nl80211: Scan trigger
nl80211: Event message available
nl80211: New scan results available
wlan0: Event SCAN_RESULTS (3) received
nl80211: Received scan results (19 BSSes)
wlan0: BSS: Start scan result update 2
when wlan0 goes to connected or I just turn off the wifi, underruns go
away, I'll check first what rtl8192ce's nl80211 interface implementation
does when asked to perform a scan.
thank you again for your suggestions,
Olivier
On 01/15/2014 12:01 PM, Larry Finger wrote:
> On 01/15/2014 12:37 AM, Olivier Langlois wrote:
>> How to reproduce:
>>
>> 1. Enable Wifi while not connecting to any AP.
>> 2. lano1106@hpmini ~/Music $ aplay -c1 sine.wav
>> underrun!!! (at least 1856093977.967 ms long)
>
> Olivier,
>
> I am certain that rtl8192ce does not disable interrupts for 2 sec, but
> I need some more info from you.
Larry. That is a fact. I agree with you that rtl8192ce does certainly
not do that.
>
> What is your CPU situation? I suspect x86_64, but please confirm.How
> many CPUs? What is the maximum CPU speed?
>
I'm running 32-bits on that machine.
lano1106@hpmini ~ $ cat /proc/cpuinfo
processor : 0
vendor_id : GenuineIntel
cpu family : 6
model : 28
model name : Intel(R) Atom(TM) CPU N455 @ 1.66GHz
stepping : 10
microcode : 0x107
cpu MHz : 1666.000
cache size : 512 KB
...
this processor has 2 cores.
It is not very powerful by today standard but on the other side, with
running top, I can tell that the system is pretty much idle when I
experience the issue. cpu usage is certainly not higher than 10%.
> What distro?
ArchLinux
>
> How do you control the wifi? Is it NetworkManager? This is important
> because the device driver does not initiate any scans on its own -
> scans are initiated and controlled by upstream.
I am using a collection of shell scripts called 'netcfg'. I suppose that
what you really want to know is this:
lano1106@hpmini ~ $ systemctl status net-auto-wireless
net-auto-wireless.service - Provides automatic netcfg wireless connection
Loaded: loaded (/usr/lib/systemd/system/net-auto-wireless.service; enabled)
Active: active (running) since Wed 2014-01-15 21:47:16 EST; 2h 20min ago
Process: 237 ExecStart=/usr/bin/netcfg-wpa_actiond $WIRELESS_INTERFACE
(code=exited, status=0/SUCCESS)
CGroup: /system.slice/net-auto-wireless.service
├─357 wpa_supplicant -B -P /run/wpa_supplicant_wlan0.pid -i wlan0 -D
nl80211,wext -c/run/network/wpa.wlan0/wpa.conf -W
├─359 /usr/sbin/wpa_actiond -p /run/wpa_supplicant -i wlan0 -P
/run/wpa_actiond_wlan0.pid -a /usr/bin/netcfg-wpa_actiond-action
└─423 dhcpcd -qL -t 30 -K wlan0
and this:
lano1106@hpmini ~ $ pacman -Qs wpa
local/wpa_actiond 1.4-2
Daemon that connects to wpa_supplicant and handles connect and
disconnect events
local/wpa_supplicant 2.0-4
A utility providing key negotiation for WPA wireless networks
>
> Please provide a URL for the test file sine.wav. If it is part of your
> distro, then put it in a public repository, or E-mail it to me privately.
>
>
I have made it available here:
http://www.trillion01.com/sine.wav
but really, there is nothing special to it. It could be any wav file or
mp3 file. What is nice with reproducing the problem with aplay, it is
that it is so simple and talk direcly to ALSA, it eliminates a lot
potential causes.
thank you very much for assisting me!
Olivier
Takashi,
> > 2. I was expecting to see XRUN entries in dmesg but I didn't. The
> > closest that I have is [ 1700.756017] PCM: Lost interrupts? [Q]
> > (stream=0, delta=16108, new_hw_ptr=383756, old_hw_ptr=367648) 3. I
> > didn't realise that the default ALSA device was a plugin using dmix. I
> > have no underruns by using directly the ALSA HW device (hw:0,0)
>
> The dmix uses the fixed configuration. Did you try playback using hw but
> with the same configuration (period size, buffer size, format)?
>
this is a very good observation.
With the same buffer/period sizes at a sampling rate of 44100 (this slightly modify the buffer/period times), I have 0 underruns. As soon as I resample my wav file to 48kHz, boom the underruns happens.
So if I understand correctly by reducing the buffer time correctly from 371504 usec to 341328 usec and by assuming that the buffer is full, if the snd_hda_intel irq/timer are delayed to a greater amount of time than 341328 usec, this is what is causing the underruns.
Maybe it is important to the discussion that my CONFIG_HZ=1000 and
$ zgrep PREEMPT /proc/config.gz
CONFIG_TREE_PREEMPT_RCU=y
CONFIG_PREEMPT_RCU=y
# CONFIG_PREEMPT_NONE is not set
# CONFIG_PREEMPT_VOLUNTARY is not set
CONFIG_PREEMPT=y
CONFIG_PREEMPT_COUNT=y
# CONFIG_DEBUG_PREEMPT is not set
# CONFIG_PREEMPT_TRACER is not set
$ aplay -Dhw:0,0 --period-size=1024 --buffer-size=16384 -v sine.wav
Playing WAVE 'sine.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo
Hardware PCM card 0 'HDA Intel' device 0 subdevice 0
Its setup is:
stream : PLAYBACK
access : RW_INTERLEAVED
format : S16_LE
subformat : STD
channels : 2
rate : 44100
exact rate : 44100 (44100/1)
msbits : 16
buffer_size : 16384
period_size : 1024
period_time : 23219
tstamp_mode : NONE
period_step : 1
avail_min : 1024
period_event : 0
start_threshold : 16384
stop_threshold : 16384
silence_threshold: 0
silence_size : 0
boundary : 1073741824
appl_ptr : 0
hw_ptr : 0
$ aplay -Dhw:0,0 --period-size=1024 --buffer-size=16384 -v sine_48000.wav
Playing WAVE 'sine_48000.wav' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
Hardware PCM card 0 'HDA Intel' device 0 subdevice 0
Its setup is:
stream : PLAYBACK
access : RW_INTERLEAVED
format : S16_LE
subformat : STD
channels : 2
rate : 48000
exact rate : 48000 (48000/1)
msbits : 16
buffer_size : 16384
period_size : 1024
period_time : 21333
tstamp_mode : NONE
period_step : 1
avail_min : 1024
period_event : 0
start_threshold : 16384
stop_threshold : 16384
silence_threshold: 0
silence_size : 0
boundary : 1073741824
appl_ptr : 0
hw_ptr : 0
underrun!!! (at least 0.075 ms long)
Status:
state : XRUN
trigger_time: 2155.298508067
tstamp : 2155.299242462
delay : 0
avail : 16815
avail_max : 16815
________________________________
CONFIDENTIALITY : This e-mail and any attachments are confidential and may be privileged. If you are not a named recipient, please notify the sender immediately and do not disclose the contents to another person, use it for any purpose or store or copy the information in any medium.
On Mon, 2014-01-27 at 17:54 +1100, James Cameron wrote:
> On Mon, Jan 27, 2014 at 01:32:03AM -0500, Olivier Langlois wrote:
> > Here is the sequence of events that I have traced that seem to cause my
> > audio playback underrun.
> >
> > 1. wpa_supplicant send a start_scan request to the nl80211 driver
> > 2. mac80211 module call rtl_op_config with IEEE80211_CONF_CHANGE_IDLE
> > 3. rtl_ips_nic_on is called which disable local irqs
> > 4. rtl92c_phy_set_rf_power_state() is called
> > 5. rtl_ps_enable_nic() is called and enable interrupts on the
> > device
> > 6. as soon as local irqs are reenabled before exiting rtl_ips_nic_on,
> > a RX interrupt is handled and _rtl_pci_interrupt appears to be taking
> > about 340 ms to process the interrupt.
>
> Good data. This discovery now points more firmly at the wireless
> driver as a contributing cause.
>
> You might further diagnose this by tracing the timing of the interrupt
> handler, to see if it is something the handler calls that causes the
> delay, or if it is device access that does it.
>
Are printk timestamps considered accurate inside irq handlers? I'm a bit
suspicious about that point because I have added a printk immediatly
after entering _rtl_pci_interrupt() (that I have omitted to show in my
previous e-mail) and it has appeared out of order in the dmesg output:
[ 69.376012] rtl8192ce:rtl92ce_sw_led_on():<0-1> LedAddr:4E ledpin=1
[ 69.711882] rtl_pci:_rtl_pci_interrupt():<10000-1> entering handler
[ 69.376012] rtlwifi:rtl_ips_nic_on():<0-1> before
spin_unlock_irqrestore
[ 69.711909] rtl_pci:_rtl_pci_interrupt():<10000-1> after
interrupt_recognized
[ 69.711920] rtl_pci:_rtl_pci_interrupt():<10000-1> Rx ok interrupt!
[ 69.711948] rtlwifi:rtl_ips_nic_on():<0-0> after
spin_unlock_irqrestore
Is there any kernel debug CONFIGs that could be useful to track down irq
issues?
James,
I think that I have found and fix the cause of the timing miscalculation
[1]
I have recompiled rtlwifi modules to have access to the debug option
which I have set to 4. I have also compiled ALSA modules with the
XRUN_DEBUG option that I have activated with
echo 1 > /proc/asound/card0/pcm0p/xrun_debug
I have reproduced the problems while collecting dmesg output and using
'watch -n1 cat /proc/interrupts'
I have made a couple of observations.
1. there is a small burst of interrupts for rtl8192ce at a regular
interval which seems to happen during rtl_op_sw_scan and the underruns
appear to coincide with that.
2. I was expecting to see XRUN entries in dmesg but I didn't. The
closest that I have is
[ 1700.756017] PCM: Lost interrupts? [Q] (stream=0, delta=16108,
new_hw_ptr=383756, old_hw_ptr=367648)
3. I didn't realise that the default ALSA device was a plugin using
dmix. I have no underruns by using directly the ALSA HW device (hw:0,0)
4. I have seen this in dmesg logs:
hda-intel: IRQ timing workaround is activated for card #0. Suggest a
bigger bdl_pos_adj.
here is the aplay output with the dmesg logs around this time:
$ aplay -v ~/Music/sine.wav
Playing WAVE '/home/lano1106/Music/sine.wav' : Signed 16 bit Little
Endian, Rate 44100 Hz, Stereo
Plug PCM: Rate conversion PCM (48000, sformat=S32_LE)
Converter: linear-interpolation
Protocol version: 10002
Its setup is:
stream : PLAYBACK
access : RW_INTERLEAVED
format : S16_LE
subformat : STD
channels : 2
rate : 44100
exact rate : 44100 (44100/1)
msbits : 16
buffer_size : 15052
period_size : 940
period_time : 21333
tstamp_mode : NONE
period_step : 1
avail_min : 940
period_event : 0
start_threshold : 15052
stop_threshold : 15052
silence_threshold: 0
silence_size : 0
boundary : 986447872
Slave: Soft volume PCM
Control: PCM Playback Volume
min_dB: -51
max_dB: 0
resolution: 256
Its setup is:
stream : PLAYBACK
access : MMAP_INTERLEAVED
format : S32_LE
subformat : STD
channels : 2
rate : 48000
exact rate : 48000 (48000/1)
msbits : 32
buffer_size : 16384
period_size : 1024
period_time : 21333
tstamp_mode : NONE
period_step : 1
avail_min : 1024
period_event : 0
start_threshold : 16384
stop_threshold : 16384
silence_threshold: 0
silence_size : 0
boundary : 1073741824
Slave: Direct Stream Mixing PCM
Its setup is:
stream : PLAYBACK
access : MMAP_INTERLEAVED
format : S32_LE
subformat : STD
channels : 2
rate : 48000
exact rate : 48000 (48000/1)
msbits : 32
buffer_size : 16384
period_size : 1024
period_time : 21333
tstamp_mode : NONE
period_step : 1
avail_min : 1024
period_event : 0
start_threshold : 16384
stop_threshold : 16384
silence_threshold: 0
silence_size : 0
boundary : 1073741824
Hardware PCM card 0 'HDA Intel' device 0 subdevice 0
Its setup is:
stream : PLAYBACK
access : MMAP_INTERLEAVED
format : S32_LE
subformat : STD
channels : 2
rate : 48000
exact rate : 48000 (48000/1)
msbits : 32
buffer_size : 16384
period_size : 1024
period_time : 21333
tstamp_mode : ENABLE
period_step : 1
avail_min : 1024
period_event : 0
start_threshold : 1
stop_threshold : 1073741824
silence_threshold: 0
silence_size : 1073741824
boundary : 1073741824
appl_ptr : 0
hw_ptr : 0
underrun!!! (at least 7098.589 ms long)
Status:
state : XRUN
trigger_time: 1692.774265154
tstamp : 1700.760145135
delay : -301
avail : 15353
avail_max : 15341
[ 1692.761247] hda-intel 0000:00:1b.0: azx_pcm_prepare: bufsize=0x20000, format=0x31
[ 1692.761268] hda_codec_setup_stream: NID=0x13, stream=0x8, channel=0, format=0x31
[ 1692.761275] hda_codec_setup_stream: NID=0x14, stream=0x8, channel=0, format=0x31
[ 1694.303968] rtl8192ce:_rtl92ce_phy_set_rf_power_state():<0-1> IPS Set eRf nic enable
[ 1694.304021] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
[ 1694.304086] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
[ 1694.304200] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
[ 1694.304314] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
[ 1694.304427] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
[ 1694.304541] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
[ 1694.304655] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
[ 1694.304693] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
[ 1694.304693] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
[ 1694.304693] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
[ 1694.304693] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
[ 1694.304693] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:98053f15:10
[ 1694.304693] rtl8192ce:rtl92ce_sw_led_on():<0-1> LedAddr:4E ledpin=1
[ 1694.304693] rtl8192c_common:rtl92c_download_fw():<0-1> Firmware Version(49), Signature(0x88c1),Size(32)
[ 1694.318113] rtl8192ce:rtl92ce_enable_hw_security_config():<0-1> PairwiseEncAlgorithm = 0 GroupEncAlgorithm = 0
[ 1694.318113] rtl8192ce:rtl92ce_enable_hw_security_config():<0-1> The SECR-value cc
[ 1694.318113] rtl8192c_common:rtl92c_dm_check_txpower_tracking_thermal_meter():<0-1> Schedule TxPowerTracking direct call!!
[ 1694.318113] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> rtl92c_dm_txpower_tracking_callback_thermalmeter
[ 1694.318113] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> Readback Thermal Meter = 0xd pre thermal meter 0xf eeprom_thermalmeter 0xf
[ 1694.318113] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> Initial pathA ele_d reg0xc80 = 0x40000000, ofdm_index=0xc
[ 1694.318113] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> Initial reg0xa24 = 0x90e1317, cck_index=0xc, ch14 0
[ 1694.318113] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> Readback Thermal Meter = 0xd pre thermal meter 0xf eeprom_thermalmeter 0xf delta 0x2 delta_lck 0x1 delta_iqk 0x1
[ 1694.318113] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> <===
[ 1694.318113] rtl8192c_common:rtl92c_dm_initialize_txpower_tracking_thermalmeter():<0-1> pMgntInfo->txpower_tracking = 1
[ 1694.318113] rtl8192ce:rtl92ce_led_control():<0-1> ledaction 3
[ 1694.318113] rtl8192ce:rtl92ce_sw_led_on():<0-1> LedAddr:4E ledpin=1
[ 1694.640920] PCM: Lost interrupts? [Q] (stream=0, delta=14444, new_hw_ptr=90248, old_hw_ptr=75804)
[ 1694.641440] rtl8192c_common:rtl92c_dm_dynamic_bb_powersaving():<0-0> Not connected to any
[ 1694.641454] rtl8192c_common:rtl92c_dm_dynamic_bb_powersaving():<0-0> AP Ext Port PWDB = 0x0
[ 1694.641472] rtl8192c_common:rtl92c_dm_check_txpower_tracking_thermal_meter():<0-0> Trigger 92S Thermal Meter!!
[ 1694.641517] rtlwifi:rtl_op_sw_scan_start():<0-0>
[ 1694.641530] rtl8192ce:rtl92ce_led_control():<0-0> ledaction 6
[ 1694.641545] rtl8192c_common:rtl92c_dm_write_dig():<0-0> cur_igvalue = 0x20, pre_igvalue = 0x0, back_val = 10
[ 1694.654779] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
[ 1694.654786] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
[ 1694.724173] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
[ 1694.724179] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
[ 1694.794176] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
[ 1694.794181] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
[ 1694.864217] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
[ 1694.864226] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
[ 1694.934184] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
[ 1694.934193] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
[ 1695.004187] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
[ 1695.004196] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
[ 1695.074187] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
[ 1695.074196] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
[ 1695.144185] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
[ 1695.144194] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
[ 1695.214184] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
[ 1695.214196] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
[ 1695.284182] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
[ 1695.284192] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
[ 1695.354186] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
[ 1695.354195] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
[ 1695.424207] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
[ 1695.424217] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
[ 1695.424275] rtlwifi:rtl_op_sw_scan_complete():<0-0>
[ 1695.424282] rtl8192c_common:rtl92c_dm_write_dig():<0-0> cur_igvalue = 0x22, pre_igvalue = 0x22, back_val = 10
[ 1695.524091] rtl8192ce:_rtl92ce_phy_set_rf_power_state():<0-0> IPS Set eRf nic disable
[ 1695.524141] rtl8192ce:rtl92ce_led_control():<0-0> ledaction 2
[ 1695.524147] rtl8192ce:rtl92ce_sw_led_on():<0-0> LedAddr:4E ledpin=1
[ 1700.419054] rtl8192ce:_rtl92ce_phy_set_rf_power_state():<0-1> IPS Set eRf nic enable
[ 1700.419106] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
[ 1700.419172] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
[ 1700.419286] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
[ 1700.419399] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
[ 1700.419513] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
[ 1700.419627] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
[ 1700.419745] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
[ 1700.419866] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
[ 1700.419984] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
[ 1700.420015] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
[ 1700.420015] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
[ 1700.420015] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:98053f15:10
[ 1700.420015] rtl8192ce:rtl92ce_sw_led_on():<0-1> LedAddr:4E ledpin=1
[ 1700.420015] rtl8192c_common:rtl92c_download_fw():<0-1> Firmware Version(49), Signature(0x88c1),Size(32)
[ 1700.420015] rtl8192ce:rtl92ce_enable_hw_security_config():<0-1> PairwiseEncAlgorithm = 0 GroupEncAlgorithm = 0
[ 1700.420015] rtl8192ce:rtl92ce_enable_hw_security_config():<0-1> The SECR-value cc
[ 1700.420015] rtl8192c_common:rtl92c_dm_check_txpower_tracking_thermal_meter():<0-1> Schedule TxPowerTracking direct call!!
[ 1700.420015] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> rtl92c_dm_txpower_tracking_callback_thermalmeter
[ 1700.420015] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> Readback Thermal Meter = 0xd pre thermal meter 0xf eeprom_thermalmeter 0xf
[ 1700.420015] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> Initial pathA ele_d reg0xc80 = 0x40000000, ofdm_index=0xc
[ 1700.420015] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> Initial reg0xa24 = 0x90e1317, cck_index=0xc, ch14 0
[ 1700.420015] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> Readback Thermal Meter = 0xd pre thermal meter 0xf eeprom_thermalmeter 0xf delta 0x2 delta_lck 0x1 delta_iqk 0x1
[ 1700.420015] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> <===
[ 1700.420015] rtl8192c_common:rtl92c_dm_initialize_txpower_tracking_thermalmeter():<0-1> pMgntInfo->txpower_tracking = 1
[ 1700.420015] rtl8192ce:rtl92ce_led_control():<0-1> ledaction 3
[ 1700.420015] rtl8192ce:rtl92ce_sw_led_on():<0-1> LedAddr:4E ledpin=1
[ 1700.756017] PCM: Lost interrupts? [Q] (stream=0, delta=16108, new_hw_ptr=383756, old_hw_ptr=367648)
[ 1700.756513] rtlwifi:rtl_op_sw_scan_start():<0-0>
[1]
http://mailman.alsa-project.org/pipermail/alsa-devel/2014-January/071521.html
On Thu, 2014-01-16 at 16:55 +1100, James Cameron wrote:
> On Thu, Jan 16, 2014 at 12:25:42AM -0500, Olivier Langlois wrote:
> > On 01/15/2014 12:01 PM, Larry Finger wrote:
> > >On 01/15/2014 12:37 AM, Olivier Langlois wrote:
> > >>How to reproduce:
> > >>
> > >>1. Enable Wifi while not connecting to any AP.
> > >>2. lano1106@hpmini ~/Music $ aplay -c1 sine.wav
> > >>underrun!!! (at least 1856093977.967 ms long)
>
> Indeed, that timing is fishy.
>
> I've looked at the alsa-devel thread [1] and your problem description
> there.
>
> At OLPC during development we found similar symptoms showing up in
> ALSA playback that were contributed to other drivers, but the
> underlying causes were in the ALSA driver for our codec chip, and the
> other drivers were changing the appearance of the fault only because
> of timing changes.
>
> But there's no need to conclude that interrupts were disabled or
> delayed. There can be many other causes.
>
> The timing miscalculation by ALSA might be important. I can't figure
> out how a wireless driver can easily cause that.
>
> 1.
> http://mailman.alsa-project.org/pipermail/alsa-devel/2014-January/071142.html
>
At Thu, 23 Jan 2014 03:13:20 -0500,
Olivier Langlois wrote:
>
> James,
>
> I think that I have found and fix the cause of the timing miscalculation
> [1]
>
> I have recompiled rtlwifi modules to have access to the debug option
> which I have set to 4. I have also compiled ALSA modules with the
> XRUN_DEBUG option that I have activated with
>
> echo 1 > /proc/asound/card0/pcm0p/xrun_debug
>
> I have reproduced the problems while collecting dmesg output and using
> 'watch -n1 cat /proc/interrupts'
>
> I have made a couple of observations.
>
> 1. there is a small burst of interrupts for rtl8192ce at a regular
> interval which seems to happen during rtl_op_sw_scan and the underruns
> appear to coincide with that.
> 2. I was expecting to see XRUN entries in dmesg but I didn't. The
> closest that I have is
> [ 1700.756017] PCM: Lost interrupts? [Q] (stream=0, delta=16108,
> new_hw_ptr=383756, old_hw_ptr=367648)
> 3. I didn't realise that the default ALSA device was a plugin using
> dmix. I have no underruns by using directly the ALSA HW device (hw:0,0)
The dmix uses the fixed configuration. Did you try playback using hw
but with the same configuration (period size, buffer size, format)?
Takashi
> 4. I have seen this in dmesg logs:
> hda-intel: IRQ timing workaround is activated for card #0. Suggest a
> bigger bdl_pos_adj.
>
> here is the aplay output with the dmesg logs around this time:
>
> $ aplay -v ~/Music/sine.wav
> Playing WAVE '/home/lano1106/Music/sine.wav' : Signed 16 bit Little
> Endian, Rate 44100 Hz, Stereo
> Plug PCM: Rate conversion PCM (48000, sformat=S32_LE)
> Converter: linear-interpolation
> Protocol version: 10002
> Its setup is:
> stream : PLAYBACK
> access : RW_INTERLEAVED
> format : S16_LE
> subformat : STD
> channels : 2
> rate : 44100
> exact rate : 44100 (44100/1)
> msbits : 16
> buffer_size : 15052
> period_size : 940
> period_time : 21333
> tstamp_mode : NONE
> period_step : 1
> avail_min : 940
> period_event : 0
> start_threshold : 15052
> stop_threshold : 15052
> silence_threshold: 0
> silence_size : 0
> boundary : 986447872
> Slave: Soft volume PCM
> Control: PCM Playback Volume
> min_dB: -51
> max_dB: 0
> resolution: 256
> Its setup is:
> stream : PLAYBACK
> access : MMAP_INTERLEAVED
> format : S32_LE
> subformat : STD
> channels : 2
> rate : 48000
> exact rate : 48000 (48000/1)
> msbits : 32
> buffer_size : 16384
> period_size : 1024
> period_time : 21333
> tstamp_mode : NONE
> period_step : 1
> avail_min : 1024
> period_event : 0
> start_threshold : 16384
> stop_threshold : 16384
> silence_threshold: 0
> silence_size : 0
> boundary : 1073741824
> Slave: Direct Stream Mixing PCM
> Its setup is:
> stream : PLAYBACK
> access : MMAP_INTERLEAVED
> format : S32_LE
> subformat : STD
> channels : 2
> rate : 48000
> exact rate : 48000 (48000/1)
> msbits : 32
> buffer_size : 16384
> period_size : 1024
> period_time : 21333
> tstamp_mode : NONE
> period_step : 1
> avail_min : 1024
> period_event : 0
> start_threshold : 16384
> stop_threshold : 16384
> silence_threshold: 0
> silence_size : 0
> boundary : 1073741824
> Hardware PCM card 0 'HDA Intel' device 0 subdevice 0
> Its setup is:
> stream : PLAYBACK
> access : MMAP_INTERLEAVED
> format : S32_LE
> subformat : STD
> channels : 2
> rate : 48000
> exact rate : 48000 (48000/1)
> msbits : 32
> buffer_size : 16384
> period_size : 1024
> period_time : 21333
> tstamp_mode : ENABLE
> period_step : 1
> avail_min : 1024
> period_event : 0
> start_threshold : 1
> stop_threshold : 1073741824
> silence_threshold: 0
> silence_size : 1073741824
> boundary : 1073741824
> appl_ptr : 0
> hw_ptr : 0
> underrun!!! (at least 7098.589 ms long)
> Status:
> state : XRUN
> trigger_time: 1692.774265154
> tstamp : 1700.760145135
> delay : -301
> avail : 15353
> avail_max : 15341
>
> [ 1692.761247] hda-intel 0000:00:1b.0: azx_pcm_prepare: bufsize=0x20000, format=0x31
> [ 1692.761268] hda_codec_setup_stream: NID=0x13, stream=0x8, channel=0, format=0x31
> [ 1692.761275] hda_codec_setup_stream: NID=0x14, stream=0x8, channel=0, format=0x31
> [ 1694.303968] rtl8192ce:_rtl92ce_phy_set_rf_power_state():<0-1> IPS Set eRf nic enable
> [ 1694.304021] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
> [ 1694.304086] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
> [ 1694.304200] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
> [ 1694.304314] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
> [ 1694.304427] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
> [ 1694.304541] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
> [ 1694.304655] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
> [ 1694.304693] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
> [ 1694.304693] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
> [ 1694.304693] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
> [ 1694.304693] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
> [ 1694.304693] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:98053f15:10
> [ 1694.304693] rtl8192ce:rtl92ce_sw_led_on():<0-1> LedAddr:4E ledpin=1
> [ 1694.304693] rtl8192c_common:rtl92c_download_fw():<0-1> Firmware Version(49), Signature(0x88c1),Size(32)
> [ 1694.318113] rtl8192ce:rtl92ce_enable_hw_security_config():<0-1> PairwiseEncAlgorithm = 0 GroupEncAlgorithm = 0
> [ 1694.318113] rtl8192ce:rtl92ce_enable_hw_security_config():<0-1> The SECR-value cc
> [ 1694.318113] rtl8192c_common:rtl92c_dm_check_txpower_tracking_thermal_meter():<0-1> Schedule TxPowerTracking direct call!!
> [ 1694.318113] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> rtl92c_dm_txpower_tracking_callback_thermalmeter
> [ 1694.318113] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> Readback Thermal Meter = 0xd pre thermal meter 0xf eeprom_thermalmeter 0xf
> [ 1694.318113] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> Initial pathA ele_d reg0xc80 = 0x40000000, ofdm_index=0xc
> [ 1694.318113] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> Initial reg0xa24 = 0x90e1317, cck_index=0xc, ch14 0
> [ 1694.318113] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> Readback Thermal Meter = 0xd pre thermal meter 0xf eeprom_thermalmeter 0xf delta 0x2 delta_lck 0x1 delta_iqk 0x1
> [ 1694.318113] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> <===
> [ 1694.318113] rtl8192c_common:rtl92c_dm_initialize_txpower_tracking_thermalmeter():<0-1> pMgntInfo->txpower_tracking = 1
> [ 1694.318113] rtl8192ce:rtl92ce_led_control():<0-1> ledaction 3
> [ 1694.318113] rtl8192ce:rtl92ce_sw_led_on():<0-1> LedAddr:4E ledpin=1
> [ 1694.640920] PCM: Lost interrupts? [Q] (stream=0, delta=14444, new_hw_ptr=90248, old_hw_ptr=75804)
> [ 1694.641440] rtl8192c_common:rtl92c_dm_dynamic_bb_powersaving():<0-0> Not connected to any
> [ 1694.641454] rtl8192c_common:rtl92c_dm_dynamic_bb_powersaving():<0-0> AP Ext Port PWDB = 0x0
> [ 1694.641472] rtl8192c_common:rtl92c_dm_check_txpower_tracking_thermal_meter():<0-0> Trigger 92S Thermal Meter!!
> [ 1694.641517] rtlwifi:rtl_op_sw_scan_start():<0-0>
> [ 1694.641530] rtl8192ce:rtl92ce_led_control():<0-0> ledaction 6
> [ 1694.641545] rtl8192c_common:rtl92c_dm_write_dig():<0-0> cur_igvalue = 0x20, pre_igvalue = 0x0, back_val = 10
> [ 1694.654779] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
> [ 1694.654786] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
> [ 1694.724173] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
> [ 1694.724179] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
> [ 1694.794176] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
> [ 1694.794181] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
> [ 1694.864217] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
> [ 1694.864226] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
> [ 1694.934184] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
> [ 1694.934193] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
> [ 1695.004187] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
> [ 1695.004196] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
> [ 1695.074187] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
> [ 1695.074196] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
> [ 1695.144185] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
> [ 1695.144194] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
> [ 1695.214184] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
> [ 1695.214196] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
> [ 1695.284182] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
> [ 1695.284192] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
> [ 1695.354186] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
> [ 1695.354195] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
> [ 1695.424207] rtl8192c_common:rtl92c_phy_sw_chnl():<0-0> sw_chnl_inprogress false schedule workitem
> [ 1695.424217] rtl8192ce:rtl92ce_set_hw_reg():<0-0> HW_VAR_SLOT_TIME 14
> [ 1695.424275] rtlwifi:rtl_op_sw_scan_complete():<0-0>
> [ 1695.424282] rtl8192c_common:rtl92c_dm_write_dig():<0-0> cur_igvalue = 0x22, pre_igvalue = 0x22, back_val = 10
> [ 1695.524091] rtl8192ce:_rtl92ce_phy_set_rf_power_state():<0-0> IPS Set eRf nic disable
> [ 1695.524141] rtl8192ce:rtl92ce_led_control():<0-0> ledaction 2
> [ 1695.524147] rtl8192ce:rtl92ce_sw_led_on():<0-0> LedAddr:4E ledpin=1
> [ 1700.419054] rtl8192ce:_rtl92ce_phy_set_rf_power_state():<0-1> IPS Set eRf nic enable
> [ 1700.419106] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
> [ 1700.419172] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
> [ 1700.419286] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
> [ 1700.419399] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
> [ 1700.419513] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
> [ 1700.419627] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
> [ 1700.419745] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
> [ 1700.419866] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
> [ 1700.419984] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
> [ 1700.420015] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
> [ 1700.420015] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:18051d59:11
> [ 1700.420015] rtl8192ce:_rtl92ce_init_mac():<0-1> reg0xec:98053f15:10
> [ 1700.420015] rtl8192ce:rtl92ce_sw_led_on():<0-1> LedAddr:4E ledpin=1
> [ 1700.420015] rtl8192c_common:rtl92c_download_fw():<0-1> Firmware Version(49), Signature(0x88c1),Size(32)
> [ 1700.420015] rtl8192ce:rtl92ce_enable_hw_security_config():<0-1> PairwiseEncAlgorithm = 0 GroupEncAlgorithm = 0
> [ 1700.420015] rtl8192ce:rtl92ce_enable_hw_security_config():<0-1> The SECR-value cc
> [ 1700.420015] rtl8192c_common:rtl92c_dm_check_txpower_tracking_thermal_meter():<0-1> Schedule TxPowerTracking direct call!!
> [ 1700.420015] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> rtl92c_dm_txpower_tracking_callback_thermalmeter
> [ 1700.420015] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> Readback Thermal Meter = 0xd pre thermal meter 0xf eeprom_thermalmeter 0xf
> [ 1700.420015] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> Initial pathA ele_d reg0xc80 = 0x40000000, ofdm_index=0xc
> [ 1700.420015] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> Initial reg0xa24 = 0x90e1317, cck_index=0xc, ch14 0
> [ 1700.420015] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> Readback Thermal Meter = 0xd pre thermal meter 0xf eeprom_thermalmeter 0xf delta 0x2 delta_lck 0x1 delta_iqk 0x1
> [ 1700.420015] rtl8192c_common:rtl92c_dm_txpower_tracking_callback_thermalmeter():<0-1> <===
> [ 1700.420015] rtl8192c_common:rtl92c_dm_initialize_txpower_tracking_thermalmeter():<0-1> pMgntInfo->txpower_tracking = 1
> [ 1700.420015] rtl8192ce:rtl92ce_led_control():<0-1> ledaction 3
> [ 1700.420015] rtl8192ce:rtl92ce_sw_led_on():<0-1> LedAddr:4E ledpin=1
> [ 1700.756017] PCM: Lost interrupts? [Q] (stream=0, delta=16108, new_hw_ptr=383756, old_hw_ptr=367648)
> [ 1700.756513] rtlwifi:rtl_op_sw_scan_start():<0-0>
>
>
> [1]
> http://mailman.alsa-project.org/pipermail/alsa-devel/2014-January/071521.html
>
> On Thu, 2014-01-16 at 16:55 +1100, James Cameron wrote:
> > On Thu, Jan 16, 2014 at 12:25:42AM -0500, Olivier Langlois wrote:
> > > On 01/15/2014 12:01 PM, Larry Finger wrote:
> > > >On 01/15/2014 12:37 AM, Olivier Langlois wrote:
> > > >>How to reproduce:
> > > >>
> > > >>1. Enable Wifi while not connecting to any AP.
> > > >>2. lano1106@hpmini ~/Music $ aplay -c1 sine.wav
> > > >>underrun!!! (at least 1856093977.967 ms long)
> >
> > Indeed, that timing is fishy.
> >
> > I've looked at the alsa-devel thread [1] and your problem description
> > there.
> >
> > At OLPC during development we found similar symptoms showing up in
> > ALSA playback that were contributed to other drivers, but the
> > underlying causes were in the ALSA driver for our codec chip, and the
> > other drivers were changing the appearance of the fault only because
> > of timing changes.
> >
> > But there's no need to conclude that interrupts were disabled or
> > delayed. There can be many other causes.
> >
> > The timing miscalculation by ALSA might be important. I can't figure
> > out how a wireless driver can easily cause that.
> >
> > 1.
> > http://mailman.alsa-project.org/pipermail/alsa-devel/2014-January/071142.html
> >
>
>
>
> _______________________________________________
> Alsa-devel mailing list
> [email protected]
> http://mailman.alsa-project.org/mailman/listinfo/alsa-devel
>