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@xxxxxxxxxxxxxxxx > http://mailman.alsa-project.org/mailman/listinfo/alsa-devel > -- To unsubscribe from this list: send the line "unsubscribe linux-wireless" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
