* [ISSUE] rtl8192ce appears to interfere with ALSA playback @ 2014-01-15 6:37 Olivier Langlois 2014-01-15 17:01 ` Larry Finger 0 siblings, 1 reply; 12+ messages in thread From: Olivier Langlois @ 2014-01-15 6:37 UTC (permalink / raw) To: linux-wireless, Larry.Finger, chaoming_li; +Cc: daniel 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) ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [ISSUE] rtl8192ce appears to interfere with ALSA playback 2014-01-15 6:37 [ISSUE] rtl8192ce appears to interfere with ALSA playback Olivier Langlois @ 2014-01-15 17:01 ` Larry Finger 2014-01-16 5:25 ` Olivier Langlois 2014-01-27 6:32 ` Olivier Langlois 0 siblings, 2 replies; 12+ messages in thread From: Larry Finger @ 2014-01-15 17:01 UTC (permalink / raw) To: Olivier Langlois, linux-wireless; +Cc: daniel 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 ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [ISSUE] rtl8192ce appears to interfere with ALSA playback 2014-01-15 17:01 ` Larry Finger @ 2014-01-16 5:25 ` Olivier Langlois 2014-01-16 5:55 ` James Cameron 2014-01-27 6:32 ` Olivier Langlois 1 sibling, 1 reply; 12+ messages in thread From: Olivier Langlois @ 2014-01-16 5:25 UTC (permalink / raw) To: Larry Finger, linux-wireless; +Cc: daniel 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 ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [ISSUE] rtl8192ce appears to interfere with ALSA playback 2014-01-16 5:25 ` Olivier Langlois @ 2014-01-16 5:55 ` James Cameron 2014-01-23 8:13 ` Olivier Langlois 0 siblings, 1 reply; 12+ messages in thread From: James Cameron @ 2014-01-16 5:55 UTC (permalink / raw) To: Olivier Langlois; +Cc: linux-wireless, daniel 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/ ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [ISSUE] rtl8192ce appears to interfere with ALSA playback 2014-01-16 5:55 ` James Cameron @ 2014-01-23 8:13 ` Olivier Langlois 2014-01-23 8:51 ` [alsa-devel] " Takashi Iwai 0 siblings, 1 reply; 12+ messages in thread From: Olivier Langlois @ 2014-01-23 8:13 UTC (permalink / raw) To: James Cameron; +Cc: linux-wireless, daniel, alsa-devel 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 > ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [alsa-devel] [ISSUE] rtl8192ce appears to interfere with ALSA playback 2014-01-23 8:13 ` Olivier Langlois @ 2014-01-23 8:51 ` Takashi Iwai 2014-01-23 16:15 ` LANGLOIS Olivier PIS -EXT 0 siblings, 1 reply; 12+ messages in thread From: Takashi Iwai @ 2014-01-23 8:51 UTC (permalink / raw) To: Olivier Langlois; +Cc: James Cameron, alsa-devel, linux-wireless, daniel 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 > Alsa-devel@alsa-project.org > http://mailman.alsa-project.org/mailman/listinfo/alsa-devel > ^ permalink raw reply [flat|nested] 12+ messages in thread
* RE: [alsa-devel] [ISSUE] rtl8192ce appears to interfere with ALSA playback 2014-01-23 8:51 ` [alsa-devel] " Takashi Iwai @ 2014-01-23 16:15 ` LANGLOIS Olivier PIS -EXT 2014-01-23 16:29 ` Takashi Iwai 0 siblings, 1 reply; 12+ messages in thread From: LANGLOIS Olivier PIS -EXT @ 2014-01-23 16:15 UTC (permalink / raw) To: Takashi Iwai, Olivier Langlois Cc: alsa-devel@alsa-project.org, linux-wireless@vger.kernel.org, James Cameron, daniel@zonque.org 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. ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [alsa-devel] [ISSUE] rtl8192ce appears to interfere with ALSA playback 2014-01-23 16:15 ` LANGLOIS Olivier PIS -EXT @ 2014-01-23 16:29 ` Takashi Iwai 2014-01-24 5:32 ` Olivier Langlois 0 siblings, 1 reply; 12+ messages in thread From: Takashi Iwai @ 2014-01-23 16:29 UTC (permalink / raw) To: LANGLOIS Olivier PIS -EXT Cc: Olivier Langlois, alsa-devel@alsa-project.org, linux-wireless@vger.kernel.org, James Cameron, daniel@zonque.org 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. > ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [alsa-devel] [ISSUE] rtl8192ce appears to interfere with ALSA playback 2014-01-23 16:29 ` Takashi Iwai @ 2014-01-24 5:32 ` Olivier Langlois 0 siblings, 0 replies; 12+ messages in thread From: Olivier Langlois @ 2014-01-24 5:32 UTC (permalink / raw) To: Takashi Iwai Cc: LANGLOIS Olivier PIS -EXT, alsa-devel@alsa-project.org, linux-wireless@vger.kernel.org, James Cameron, daniel@zonque.org 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 ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [ISSUE] rtl8192ce appears to interfere with ALSA playback 2014-01-15 17:01 ` Larry Finger 2014-01-16 5:25 ` Olivier Langlois @ 2014-01-27 6:32 ` Olivier Langlois 2014-01-27 6:54 ` James Cameron 1 sibling, 1 reply; 12+ messages in thread From: Olivier Langlois @ 2014-01-27 6:32 UTC (permalink / raw) To: Larry Finger; +Cc: linux-wireless, daniel 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 > > > ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [ISSUE] rtl8192ce appears to interfere with ALSA playback 2014-01-27 6:32 ` Olivier Langlois @ 2014-01-27 6:54 ` James Cameron 2014-01-27 7:08 ` Olivier Langlois 0 siblings, 1 reply; 12+ messages in thread From: James Cameron @ 2014-01-27 6:54 UTC (permalink / raw) To: Olivier Langlois, linux-wireless 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/ ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [ISSUE] rtl8192ce appears to interfere with ALSA playback 2014-01-27 6:54 ` James Cameron @ 2014-01-27 7:08 ` Olivier Langlois 0 siblings, 0 replies; 12+ messages in thread From: Olivier Langlois @ 2014-01-27 7:08 UTC (permalink / raw) To: James Cameron; +Cc: linux-wireless 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? ^ permalink raw reply [flat|nested] 12+ messages in thread
end of thread, other threads:[~2014-01-27 7:15 UTC | newest] Thread overview: 12+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2014-01-15 6:37 [ISSUE] rtl8192ce appears to interfere with ALSA playback Olivier Langlois 2014-01-15 17:01 ` Larry Finger 2014-01-16 5:25 ` Olivier Langlois 2014-01-16 5:55 ` James Cameron 2014-01-23 8:13 ` Olivier Langlois 2014-01-23 8:51 ` [alsa-devel] " Takashi Iwai 2014-01-23 16:15 ` LANGLOIS Olivier PIS -EXT 2014-01-23 16:29 ` Takashi Iwai 2014-01-24 5:32 ` Olivier Langlois 2014-01-27 6:32 ` Olivier Langlois 2014-01-27 6:54 ` James Cameron 2014-01-27 7:08 ` Olivier Langlois
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).