Re: [alsa-devel] [ISSUE] rtl8192ce appears to interfere with ALSA playback
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.htm...
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:
- Enable Wifi while not connecting to any AP.
- 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.
http://mailman.alsa-project.org/pipermail/alsa-devel/2014-January/071142.htm...
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.
- 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
- 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.htm...
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:
- Enable Wifi while not connecting to any AP.
- 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.
http://mailman.alsa-project.org/pipermail/alsa-devel/2014-January/071142.htm...
Alsa-devel mailing list Alsa-devel@alsa-project.org http://mailman.alsa-project.org/mailman/listinfo/alsa-devel
Takashi,
- 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.
As small unrelated sidenote,
If I let aplay choose the hw params itself, how comes it ends up with 16 periods when it calculates the period time to have 4 periods?
If noone knows, I guess that I'll need to reactivate the REFINE_DEBUGs to figure out...
-----Original Message----- From: alsa-devel-bounces@alsa-project.org [mailto:alsa-devel- bounces@alsa-project.org] On Behalf Of LANGLOIS Olivier PIS -EXT Sent: Thursday, January 23, 2014 11:15 AM To: Takashi Iwai; Olivier Langlois Cc: alsa-devel@alsa-project.org; linux-wireless@vger.kernel.org; James Cameron; daniel@zonque.org Subject: Re: [alsa-devel] [ISSUE] rtl8192ce appears to interfere with ALSA playback
Takashi,
- 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. _______________________________________________ Alsa-devel mailing list Alsa-devel@alsa-project.org http://mailman.alsa-project.org/mailman/listinfo/alsa-devel
________________________________ 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.
At Thu, 23 Jan 2014 16:21:39 +0000, LANGLOIS Olivier PIS -EXT wrote:
As small unrelated sidenote,
If I let aplay choose the hw params itself, how comes it ends up with 16 periods when it calculates the period time to have 4 periods?
How 4 periods come up...? period_time = period_size / rate.
Takashi
If noone knows, I guess that I'll need to reactivate the REFINE_DEBUGs to figure out...
-----Original Message----- From: alsa-devel-bounces@alsa-project.org [mailto:alsa-devel- bounces@alsa-project.org] On Behalf Of LANGLOIS Olivier PIS -EXT Sent: Thursday, January 23, 2014 11:15 AM To: Takashi Iwai; Olivier Langlois Cc: alsa-devel@alsa-project.org; linux-wireless@vger.kernel.org; James Cameron; daniel@zonque.org Subject: Re: [alsa-devel] [ISSUE] rtl8192ce appears to interfere with ALSA playback
Takashi,
- 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. _______________________________________________ Alsa-devel mailing list Alsa-devel@alsa-project.org http://mailman.alsa-project.org/mailman/listinfo/alsa-devel
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.
As small unrelated sidenote,
If I let aplay choose the hw params itself, how comes it ends up with 16
periods when it calculates the period time to have 4 periods?
How 4 periods come up...? period_time = period_size / rate.
I was referring to this code in aplay.c:set_params():
if (period_time == 0 && period_frames == 0) { if (buffer_time > 0) period_time = buffer_time / 4; else period_frames = buffer_frames / 4; }
and I think that usually periods_num ~= buffer_time/period_time or buffer_size/period_size
aplay -Dhw:0,0 sine_48000.wav
I have:
buffer_size : 24000 period_size : 6000 period_time : 125000
but with the default dmix setup: aplay -v sine_48000.wav:
buffer_size : 16384 period_size : 1024 period_time : 21333
________________________________ 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.
At Thu, 23 Jan 2014 16:36:45 +0000, LANGLOIS Olivier PIS -EXT wrote:
As small unrelated sidenote,
If I let aplay choose the hw params itself, how comes it ends up with 16
periods when it calculates the period time to have 4 periods?
How 4 periods come up...? period_time = period_size / rate.
I was referring to this code in aplay.c:set_params():
if (period_time == 0 && period_frames == 0) { if (buffer_time > 0) period_time = buffer_time / 4; else period_frames = buffer_frames / 4; }
But you passed --buffer-size and --period-size options.
and I think that usually periods_num ~= buffer_time/period_time or buffer_size/period_size
aplay -Dhw:0,0 sine_48000.wav
I have:
buffer_size : 24000 period_size : 6000 period_time : 125000
but with the default dmix setup: aplay -v sine_48000.wav:
buffer_size : 16384 period_size : 1024 period_time : 21333
As already mentioned, dmix has the fixed setup for its slave PCM. See src/conf/pcm/dmix.conf.
Takashi
But you passed --buffer-size and --period-size options.
only to have the same params with hw:0,0 that I am giving with the dmix setup to reproduce the underruns. Otherwise the numbers below are what I have by letting aplay pick them for me by varying only the device.
I have done a lot of experiments with mildly complex alsa setup during the past holiday [1] to understand that ALSA may come up with different params for different setups but the choosen 16 periods value is puzzling me...
1. http://mailman.alsa-project.org/pipermail/alsa-devel/2013-December/070561.ht...
and I think that usually periods_num ~= buffer_time/period_time or
buffer_size/period_size
aplay -Dhw:0,0 sine_48000.wav
I have:
buffer_size : 24000 period_size : 6000 period_time : 125000
but with the default dmix setup: aplay -v sine_48000.wav:
buffer_size : 16384 period_size : 1024 period_time : 21333
As already mentioned, dmix has the fixed setup for its slave PCM. See src/conf/pcm/dmix.conf.
Takashi
________________________________ 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.
At Thu, 23 Jan 2014 16:50:56 +0000, LANGLOIS Olivier PIS -EXT wrote:
But you passed --buffer-size and --period-size options.
only to have the same params with hw:0,0 that I am giving with the dmix setup to reproduce the underruns. Otherwise the numbers below are what I have by letting aplay pick them for me by varying only the device.
I have done a lot of experiments with mildly complex alsa setup during the past holiday [1] to understand that ALSA may come up with different params for different setups but the choosen 16 periods value is puzzling me...
I repeatedly wrote that it's a fixed number. See src/conf/pcm/dmix.conf.
Takashi
http://mailman.alsa-project.org/pipermail/alsa-devel/2013-December/070561.ht...
and I think that usually periods_num ~= buffer_time/period_time or
buffer_size/period_size
aplay -Dhw:0,0 sine_48000.wav
I have:
buffer_size : 24000 period_size : 6000 period_time : 125000
but with the default dmix setup: aplay -v sine_48000.wav:
buffer_size : 16384 period_size : 1024 period_time : 21333
As already mentioned, dmix has the fixed setup for its slave PCM. See src/conf/pcm/dmix.conf.
Takashi
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.
At Thu, 23 Jan 2014 16:15:19 +0000, LANGLOIS Olivier PIS -EXT wrote:
Takashi,
- 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.
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
participants (3)
-
LANGLOIS Olivier PIS -EXT -
Olivier Langlois -
Takashi Iwai