[alsa-devel] [ISSUE] rtl8192ce appears to interfere with ALSA playback
Takashi Iwai
tiwai at suse.de
Thu Jan 23 09:51:47 CET 2014
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 at 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 at alsa-project.org
> http://mailman.alsa-project.org/mailman/listinfo/alsa-devel
>
More information about the Alsa-devel
mailing list