2019-01-04 14:01:43

by Bernd Edlinger

[permalink] [raw]
Subject: [PATCH 1/4] rtlwifi: rtl8723ae: Take the FW LPS mode handling out

This appears to trigger a firmware bug and causes severe
problems with rtl8723ae PCI devices.

When the power save mode is activated for longer periods
of time the firmware stops to receive any packets.

This problem was exposed by commit 873ffe154ae0 ("rtlwifi:
Fix logic error in enter/exit power-save mode").

Previously the power save mode was only active rarely and
only for a short time so that the problem was not noticeable.

Signed-off-by: Bernd Edlinger <[email protected]>
---
.../net/wireless/realtek/rtlwifi/rtl8723ae/fw.c | 20 --------
.../net/wireless/realtek/rtlwifi/rtl8723ae/fw.h | 1 -
.../net/wireless/realtek/rtlwifi/rtl8723ae/hw.c | 56 +---------------------
3 files changed, 1 insertion(+), 76 deletions(-)

diff --git a/drivers/net/wireless/realtek/rtlwifi/rtl8723ae/fw.c b/drivers/net/wireless/realtek/rtlwifi/rtl8723ae/fw.c
index bf9859f..77833fb 100644
--- a/drivers/net/wireless/realtek/rtlwifi/rtl8723ae/fw.c
+++ b/drivers/net/wireless/realtek/rtlwifi/rtl8723ae/fw.c
@@ -268,26 +268,6 @@ void rtl8723e_fill_h2c_cmd(struct ieee80211_hw *hw,
(u8 *)&tmp_cmdbuf);
}

-void rtl8723e_set_fw_pwrmode_cmd(struct ieee80211_hw *hw, u8 mode)
-{
- struct rtl_priv *rtlpriv = rtl_priv(hw);
- u8 u1_h2c_set_pwrmode[3] = { 0 };
- struct rtl_ps_ctl *ppsc = rtl_psc(rtl_priv(hw));
-
- RT_TRACE(rtlpriv, COMP_POWER, DBG_LOUD, "FW LPS mode = %d\n", mode);
-
- SET_H2CCMD_PWRMODE_PARM_MODE(u1_h2c_set_pwrmode, mode);
- SET_H2CCMD_PWRMODE_PARM_SMART_PS(u1_h2c_set_pwrmode,
- (rtlpriv->mac80211.p2p) ? ppsc->smart_ps : 1);
- SET_H2CCMD_PWRMODE_PARM_BCN_PASS_TIME(u1_h2c_set_pwrmode,
- ppsc->reg_max_lps_awakeintvl);
-
- RT_PRINT_DATA(rtlpriv, COMP_CMD, DBG_DMESG,
- "rtl8723e_set_fw_rsvdpagepkt(): u1_h2c_set_pwrmode\n",
- u1_h2c_set_pwrmode, 3);
- rtl8723e_fill_h2c_cmd(hw, H2C_SETPWRMODE, 3, u1_h2c_set_pwrmode);
-}
-
#define BEACON_PG 0 /* ->1 */
#define PSPOLL_PG 2
#define NULL_PG 3
diff --git a/drivers/net/wireless/realtek/rtlwifi/rtl8723ae/fw.h b/drivers/net/wireless/realtek/rtlwifi/rtl8723ae/fw.h
index 2e668fc..8618b82 100644
--- a/drivers/net/wireless/realtek/rtlwifi/rtl8723ae/fw.h
+++ b/drivers/net/wireless/realtek/rtlwifi/rtl8723ae/fw.h
@@ -55,7 +55,6 @@

void rtl8723e_fill_h2c_cmd(struct ieee80211_hw *hw, u8 element_id,
u32 cmd_len, u8 *p_cmdbuffer);
-void rtl8723e_set_fw_pwrmode_cmd(struct ieee80211_hw *hw, u8 mode);
void rtl8723e_set_fw_rsvdpagepkt(struct ieee80211_hw *hw, bool b_dl_finished);
void rtl8723e_set_fw_joinbss_report_cmd(struct ieee80211_hw *hw, u8 mstatus);
void rtl8723e_set_p2p_ps_offload_cmd(struct ieee80211_hw *hw, u8 p2p_ps_state);
diff --git a/drivers/net/wireless/realtek/rtlwifi/rtl8723ae/hw.c b/drivers/net/wireless/realtek/rtlwifi/rtl8723ae/hw.c
index f783e4a..f0eb356 100644
--- a/drivers/net/wireless/realtek/rtlwifi/rtl8723ae/hw.c
+++ b/drivers/net/wireless/realtek/rtlwifi/rtl8723ae/hw.c
@@ -408,29 +408,7 @@ void rtl8723e_set_hw_reg(struct ieee80211_hw *hw, u8 variable, u8 *val)
case HW_VAR_WPA_CONFIG:
rtl_write_byte(rtlpriv, REG_SECCFG, *((u8 *)val));
break;
- case HW_VAR_SET_RPWM:{
- u8 rpwm_val;
-
- rpwm_val = rtl_read_byte(rtlpriv, REG_PCIE_HRPWM);
- udelay(1);
-
- if (rpwm_val & BIT(7)) {
- rtl_write_byte(rtlpriv, REG_PCIE_HRPWM,
- (*(u8 *)val));
- } else {
- rtl_write_byte(rtlpriv, REG_PCIE_HRPWM,
- ((*(u8 *)val) | BIT(7)));
- }
-
- break;
- }
case HW_VAR_H2C_FW_PWRMODE:{
- u8 psmode = (*(u8 *)val);
-
- if (psmode != FW_PS_ACTIVE_MODE)
- rtl8723e_dm_rf_saving(hw, true);
-
- rtl8723e_set_fw_pwrmode_cmd(hw, (*(u8 *)val));
break;
}
case HW_VAR_FW_PSMODE_STATUS:
@@ -513,39 +491,7 @@ void rtl8723e_set_hw_reg(struct ieee80211_hw *hw, u8 variable, u8 *val)
break;
}
case HW_VAR_FW_LPS_ACTION:{
- bool b_enter_fwlps = *((bool *)val);
- u8 rpwm_val, fw_pwrmode;
- bool fw_current_inps;
-
- if (b_enter_fwlps) {
- rpwm_val = 0x02; /* RF off */
- fw_current_inps = true;
- rtlpriv->cfg->ops->set_hw_reg(hw,
- HW_VAR_FW_PSMODE_STATUS,
- (u8 *)(&fw_current_inps));
- rtlpriv->cfg->ops->set_hw_reg(hw,
- HW_VAR_H2C_FW_PWRMODE,
- (u8 *)(&ppsc->fwctrl_psmode));
-
- rtlpriv->cfg->ops->set_hw_reg(hw,
- HW_VAR_SET_RPWM,
- (u8 *)(&rpwm_val));
- } else {
- rpwm_val = 0x0C; /* RF on */
- fw_pwrmode = FW_PS_ACTIVE_MODE;
- fw_current_inps = false;
- rtlpriv->cfg->ops->set_hw_reg(hw,
- HW_VAR_SET_RPWM,
- (u8 *)(&rpwm_val));
- rtlpriv->cfg->ops->set_hw_reg(hw,
- HW_VAR_H2C_FW_PWRMODE,
- (u8 *)(&fw_pwrmode));
-
- rtlpriv->cfg->ops->set_hw_reg(hw,
- HW_VAR_FW_PSMODE_STATUS,
- (u8 *)(&fw_current_inps));
- }
- break;
+ break;
}
default:
RT_TRACE(rtlpriv, COMP_ERR, DBG_LOUD,
--
1.9.1


2019-01-05 02:46:03

by Larry Finger

[permalink] [raw]
Subject: Re: [PATCH 1/4] rtlwifi: rtl8723ae: Take the FW LPS mode handling out

On 1/4/19 6:48 AM, Bernd Edlinger wrote:
> This appears to trigger a firmware bug and causes severe
> problems with rtl8723ae PCI devices.
>
> When the power save mode is activated for longer periods
> of time the firmware stops to receive any packets.
>
> This problem was exposed by commit 873ffe154ae0 ("rtlwifi:
> Fix logic error in enter/exit power-save mode").
>
> Previously the power save mode was only active rarely and
> only for a short time so that the problem was not noticeable.
>
> Signed-off-by: Bernd Edlinger <[email protected]>
> ---

While the Realtek firmware group has a chance to look for a bug, I would like
you to perform a couple of tests on the original code.

The driver has three module parameters that affect power save. The 'modinfo
rtl8723ae' command lists them as

parm: ips:Set to 0 to not use link power save (default 1) (bool)
parm: swlps:Set to 1 to use SW control power save (default 0) (bool)
parm: fwlps:Set to 1 to use FW control power save (default 1) (bool)

If you were to load rtl8723ae with 'ips=0', does it still fail?
If you were to load the driver with 'swlps=1 fwlps=0', does it still fail?

Thanks for debugging this problem.

Larry


2019-01-05 11:36:42

by Bernd Edlinger

[permalink] [raw]
Subject: Re: [PATCH 1/4] rtlwifi: rtl8723ae: Take the FW LPS mode handling out

On 1/5/19 3:44 AM, Larry Finger wrote:
> On 1/4/19 6:48 AM, Bernd Edlinger wrote:
>> This appears to trigger a firmware bug and causes severe
>> problems with rtl8723ae PCI devices.
>>
>> When the power save mode is activated for longer periods
>> of time the firmware stops to receive any packets.
>>
>> This problem was exposed by commit 873ffe154ae0 ("rtlwifi:
>> Fix logic error in enter/exit power-save mode").
>>
>> Previously the power save mode was only active rarely and
>> only for a short time so that the problem was not noticeable.
>>
>> Signed-off-by: Bernd Edlinger <[email protected]>
>> ---
>
> While the Realtek firmware group has a chance to look for a bug, I would like you to perform a couple of tests on the original code.
>
> The driver has three module parameters that affect power save. The 'modinfo rtl8723ae' command lists them as
>
> parm:   ips:Set to 0 to not use link power save (default 1) (bool)
> parm:   swlps:Set to 1 to use SW control power save (default 0) (bool)
> parm:   fwlps:Set to 1 to use FW control power save (default 1) (bool)
>
> If you were to load rtl8723ae with 'ips=0', does it still fail?
> If you were to load the driver with 'swlps=1 fwlps=0', does it still fail?
>

this does not work:

modprobe rtl8723ae debug_mask=0xFFFFFFFF debug_level=5 ips=0

tail -f /var/log/syslog|grep "AP off"
Jan 5 11:42:06 w-ed kernel: [ 7267.229713] rtlwifi: :<0> AP off for 2 s
Jan 5 11:42:08 w-ed kernel: [ 7269.276761] rtlwifi: :<0> AP off for 4 s
Jan 5 11:42:10 w-ed kernel: [ 7271.323758] rtlwifi: :<0> AP off for 6 s
Jan 5 11:42:12 w-ed kernel: [ 7273.370759] rtlwifi: :<0> AP off for 8 s
Jan 5 11:42:14 w-ed kernel: [ 7275.417753] rtlwifi: :<0> AP off for 10 s
Jan 5 11:42:14 w-ed kernel: [ 7275.417754] rtlwifi: AP off, try to reconnect now
Jan 5 11:42:28 w-ed kernel: [ 7289.746676] rtlwifi: :<0> AP off for 2 s
Jan 5 11:42:40 w-ed kernel: [ 7302.028327] rtlwifi: :<0> AP off for 2 s
Jan 5 11:42:43 w-ed kernel: [ 7304.075327] rtlwifi: :<0> AP off for 4 s
Jan 5 11:42:45 w-ed kernel: [ 7306.122330] rtlwifi: :<0> AP off for 6 s
Jan 5 11:42:47 w-ed kernel: [ 7308.169292] rtlwifi: :<0> AP off for 8 s
Jan 5 11:42:49 w-ed kernel: [ 7310.216236] rtlwifi: :<0> AP off for 10 s
Jan 5 11:42:49 w-ed kernel: [ 7310.216238] rtlwifi: AP off, try to reconnect now
Jan 5 11:43:05 w-ed kernel: [ 7326.592222] rtlwifi: :<0> AP off for 2 s
Jan 5 11:43:07 w-ed kernel: [ 7328.639076] rtlwifi: :<0> AP off for 4 s
Jan 5 11:43:09 w-ed kernel: [ 7330.686220] rtlwifi: :<0> AP off for 6 s
Jan 5 11:43:11 w-ed kernel: [ 7332.733078] rtlwifi: :<0> AP off for 8 s
Jan 5 11:43:13 w-ed kernel: [ 7334.779988] rtlwifi: :<0> AP off for 10 s
Jan 5 11:43:13 w-ed kernel: [ 7334.779989] rtlwifi: AP off, try to reconnect now
Jan 5 11:43:28 w-ed kernel: [ 7349.108839] rtlwifi: :<0> AP off for 2 s
Jan 5 11:43:30 w-ed kernel: [ 7351.155837] rtlwifi: :<0> AP off for 4 s
Jan 5 11:43:32 w-ed kernel: [ 7353.202838] rtlwifi: :<0> AP off for 6 s
Jan 5 11:43:42 w-ed kernel: [ 7363.437779] rtlwifi: :<0> AP off for 2 s
Jan 5 11:43:46 w-ed kernel: [ 7367.531622] rtlwifi: :<0> AP off for 2 s
Jan 5 11:43:48 w-ed kernel: [ 7369.578597] rtlwifi: :<0> AP off for 4 s
Jan 5 11:43:50 w-ed kernel: [ 7371.625694] rtlwifi: :<0> AP off for 6 s
Jan 5 11:43:52 w-ed kernel: [ 7373.672691] rtlwifi: :<0> AP off for 8 s
Jan 5 11:43:54 w-ed kernel: [ 7375.719690] rtlwifi: :<0> AP off for 10 s
Jan 5 11:43:54 w-ed kernel: [ 7375.719691] rtlwifi: AP off, try to reconnect now
Jan 5 11:44:09 w-ed kernel: [ 7390.048406] rtlwifi: :<0> AP off for 2 s
Jan 5 11:44:11 w-ed kernel: [ 7392.095678] rtlwifi: :<0> AP off for 4 s
Jan 5 11:44:13 w-ed kernel: [ 7394.142349] rtlwifi: :<0> AP off for 6 s
Jan 5 11:44:15 w-ed kernel: [ 7396.189352] rtlwifi: :<0> AP off for 8 s
Jan 5 11:44:17 w-ed kernel: [ 7398.236352] rtlwifi: :<0> AP off for 10 s
Jan 5 11:44:17 w-ed kernel: [ 7398.236353] rtlwifi: AP off, try to reconnect now
Jan 5 11:44:31 w-ed kernel: [ 7412.565079] rtlwifi: :<0> AP off for 2 s
Jan 5 11:44:33 w-ed kernel: [ 7414.612167] rtlwifi: :<0> AP off for 4 s
Jan 5 11:44:35 w-ed kernel: [ 7416.659101] rtlwifi: :<0> AP off for 6 s
Jan 5 11:44:37 w-ed kernel: [ 7418.706035] rtlwifi: :<0> AP off for 8 s
Jan 5 11:44:39 w-ed kernel: [ 7420.753100] rtlwifi: :<0> AP off for 10 s
Jan 5 11:44:39 w-ed kernel: [ 7420.753101] rtlwifi: AP off, try to reconnect now
Jan 5 11:44:54 w-ed kernel: [ 7435.081860] rtlwifi: :<0> AP off for 2 s
Jan 5 11:44:56 w-ed kernel: [ 7437.128857] rtlwifi: :<0> AP off for 4 s
Jan 5 11:45:08 w-ed kernel: [ 7449.410653] rtlwifi: :<0> AP off for 2 s
Jan 5 11:45:10 w-ed kernel: [ 7451.457650] rtlwifi: :<0> AP off for 4 s
Jan 5 11:45:12 w-ed kernel: [ 7453.504647] rtlwifi: :<0> AP off for 6 s
Jan 5 11:45:14 w-ed kernel: [ 7455.551607] rtlwifi: :<0> AP off for 8 s
Jan 5 11:45:16 w-ed kernel: [ 7457.598645] rtlwifi: :<0> AP off for 10 s
Jan 5 11:45:16 w-ed kernel: [ 7457.598646] rtlwifi: AP off, try to reconnect now


but this works:

modprobe rtl8723ae debug_mask=0xFFFFFFFF debug_level=5 swlps=1 fwlps=0

and this works too:

modprobe rtl8723ae debug_mask=0xFFFFFFFF debug_level=5 ips=0 swlps=1 fwlps=0


so I think I should change the default of swlps and fwlps with this patch,
unless someone comes up with a better solution?


Thanks
Bernd.

FYI: complete trace of one of the outages below:

Jan 5 11:45:02 w-ed kernel: [ 7443.362985] rtlwifi: :<10000> Rx ok interrupt!
Jan 5 11:45:02 w-ed kernel: [ 7443.465386] rtlwifi: :<10000> Rx ok interrupt!
Jan 5 11:45:02 w-ed kernel: [ 7443.567782] rtlwifi: :<10000> Rx ok interrupt!
Jan 5 11:45:02 w-ed kernel: [ 7443.670183] rtlwifi: :<10000> Rx ok interrupt!
Jan 5 11:45:02 w-ed kernel: [ 7443.772581] rtlwifi: :<10000> Rx ok interrupt!
Jan 5 11:45:02 w-ed kernel: [ 7443.874981] rtlwifi: :<10000> Rx ok interrupt!
Jan 5 11:45:02 w-ed kernel: [ 7443.977379] rtlwifi: :<10000> Rx ok interrupt!
Jan 5 11:45:03 w-ed kernel: [ 7444.079779] rtlwifi: :<10000> Rx ok interrupt!
Jan 5 11:45:03 w-ed kernel: [ 7444.182176] rtlwifi: :<10000> Rx ok interrupt!
Jan 5 11:45:03 w-ed kernel: [ 7444.284577] rtlwifi: :<10000> Rx ok interrupt!
Jan 5 11:45:03 w-ed kernel: [ 7444.386975] rtlwifi: :<10000> Rx ok interrupt!
Jan 5 11:45:03 w-ed kernel: [ 7444.489375] rtlwifi: :<10000> Rx ok interrupt!
Jan 5 11:45:03 w-ed kernel: [ 7444.591774] rtlwifi: :<10000> Rx ok interrupt!
Jan 5 11:45:03 w-ed kernel: [ 7444.694171] rtlwifi: :<10000> Rx ok interrupt!
Jan 5 11:45:03 w-ed kernel: [ 7444.796570] rtlwifi: :<10000> Rx ok interrupt!
Jan 5 11:45:03 w-ed kernel: [ 7444.898969] rtlwifi: :<10000> Rx ok interrupt!
Jan 5 11:45:04 w-ed kernel: [ 7445.001369] rtlwifi: :<10000> Rx ok interrupt!
Jan 5 11:45:04 w-ed kernel: [ 7445.103768] rtlwifi: :<10000> Rx ok interrupt!
Jan 5 11:45:04 w-ed kernel: [ 7445.206167] rtlwifi: :<10000> Rx ok interrupt!
Jan 5 11:45:04 w-ed kernel: [ 7445.308566] rtlwifi: :<10000> Rx ok interrupt!
Jan 5 11:45:04 w-ed kernel: [ 7445.316563] rtlwifi: :<0> Enter 802.11 power save mode...
Jan 5 11:45:04 w-ed kernel: [ 7445.316568] rtlwifi: :<0> FW LPS enter ps_mode:3
Jan 5 11:45:04 w-ed kernel: [ 7445.316572] rtlwifi: :<0> FW LPS mode = 3
Jan 5 11:45:04 w-ed kernel: [ 7445.316576] rtlwifi: In process "kworker/0:1" (pid 12): rtl8723e_set_fw_rsvdpagepkt(): u1_h2c_set_pwrmode
Jan 5 11:45:04 w-ed kernel: [ 7445.316576]
Jan 5 11:45:04 w-ed kernel: [ 7445.316577] rtlwifi: :<0> come in
Jan 5 11:45:04 w-ed kernel: [ 7445.316618] rtlwifi: :<0> Write element_id box_reg( 1dc) = 1
Jan 5 11:45:04 w-ed kernel: [ 7445.316628] rtlwifi: :<0> pHalData->last_hmeboxnum = 0
Jan 5 11:45:04 w-ed kernel: [ 7445.316629] rtlwifi: :<0> go out
Jan 5 11:45:04 w-ed kernel: [ 7445.410964] rtlwifi: :<10000> Rx ok interrupt!
Jan 5 11:45:06 w-ed kernel: [ 7447.363540] rtlwifi: :<0> Enter 802.11 power save mode...
Jan 5 11:45:06 w-ed kernel: [ 7447.363545] rtlwifi: :<0> FW LPS enter ps_mode:3
Jan 5 11:45:06 w-ed kernel: [ 7447.363549] rtlwifi: :<0> FW LPS mode = 3
Jan 5 11:45:06 w-ed kernel: [ 7447.363552] rtlwifi: In process "kworker/0:1" (pid 12): rtl8723e_set_fw_rsvdpagepkt(): u1_h2c_set_pwrmode
Jan 5 11:45:06 w-ed kernel: [ 7447.363552]
Jan 5 11:45:06 w-ed kernel: [ 7447.363554] rtlwifi: :<0> come in
Jan 5 11:45:06 w-ed kernel: [ 7447.363594] rtlwifi: :<0> Write element_id box_reg( 1d0) = 1
Jan 5 11:45:06 w-ed kernel: [ 7447.363605] rtlwifi: :<0> pHalData->last_hmeboxnum = 1
Jan 5 11:45:06 w-ed kernel: [ 7447.363606] rtlwifi: :<0> go out
Jan 5 11:45:08 w-ed kernel: [ 7449.410541] rtlwifi: :<0> Enter 802.11 power save mode...
Jan 5 11:45:08 w-ed kernel: [ 7449.410546] rtlwifi: :<0> FW LPS enter ps_mode:3
Jan 5 11:45:08 w-ed kernel: [ 7449.410550] rtlwifi: :<0> FW LPS mode = 3
Jan 5 11:45:08 w-ed kernel: [ 7449.410553] rtlwifi: In process "kworker/0:1" (pid 12): rtl8723e_set_fw_rsvdpagepkt(): u1_h2c_set_pwrmode
Jan 5 11:45:08 w-ed kernel: [ 7449.410553]
Jan 5 11:45:08 w-ed kernel: [ 7449.410555] rtlwifi: :<0> come in
Jan 5 11:45:08 w-ed kernel: [ 7449.410595] rtlwifi: :<0> Write element_id box_reg( 1d4) = 1
Jan 5 11:45:08 w-ed kernel: [ 7449.410606] rtlwifi: :<0> pHalData->last_hmeboxnum = 2
Jan 5 11:45:08 w-ed kernel: [ 7449.410607] rtlwifi: :<0> go out
Jan 5 11:45:08 w-ed kernel: [ 7449.410653] rtlwifi: :<0> AP off for 2 s
Jan 5 11:45:10 w-ed kernel: [ 7451.457537] rtlwifi: :<0> Enter 802.11 power save mode...
Jan 5 11:45:10 w-ed kernel: [ 7451.457542] rtlwifi: :<0> FW LPS enter ps_mode:3
Jan 5 11:45:10 w-ed kernel: [ 7451.457546] rtlwifi: :<0> FW LPS mode = 3
Jan 5 11:45:10 w-ed kernel: [ 7451.457550] rtlwifi: In process "kworker/0:1" (pid 12): rtl8723e_set_fw_rsvdpagepkt(): u1_h2c_set_pwrmode
Jan 5 11:45:10 w-ed kernel: [ 7451.457550]
Jan 5 11:45:10 w-ed kernel: [ 7451.457552] rtlwifi: :<0> come in
Jan 5 11:45:10 w-ed kernel: [ 7451.457593] rtlwifi: :<0> Write element_id box_reg( 1d8) = 1
Jan 5 11:45:10 w-ed kernel: [ 7451.457603] rtlwifi: :<0> pHalData->last_hmeboxnum = 3
Jan 5 11:45:10 w-ed kernel: [ 7451.457604] rtlwifi: :<0> go out
Jan 5 11:45:10 w-ed kernel: [ 7451.457650] rtlwifi: :<0> AP off for 4 s
Jan 5 11:45:12 w-ed kernel: [ 7453.504535] rtlwifi: :<0> Enter 802.11 power save mode...
Jan 5 11:45:12 w-ed kernel: [ 7453.504540] rtlwifi: :<0> FW LPS enter ps_mode:3
Jan 5 11:45:12 w-ed kernel: [ 7453.504544] rtlwifi: :<0> FW LPS mode = 3
Jan 5 11:45:12 w-ed kernel: [ 7453.504547] rtlwifi: In process "kworker/0:1" (pid 12): rtl8723e_set_fw_rsvdpagepkt(): u1_h2c_set_pwrmode
Jan 5 11:45:12 w-ed kernel: [ 7453.504547]
Jan 5 11:45:12 w-ed kernel: [ 7453.504549] rtlwifi: :<0> come in
Jan 5 11:45:12 w-ed kernel: [ 7453.504589] rtlwifi: :<0> Write element_id box_reg( 1dc) = 1
Jan 5 11:45:12 w-ed kernel: [ 7453.504600] rtlwifi: :<0> pHalData->last_hmeboxnum = 0
Jan 5 11:45:12 w-ed kernel: [ 7453.504601] rtlwifi: :<0> go out
Jan 5 11:45:12 w-ed kernel: [ 7453.504647] rtlwifi: :<0> AP off for 6 s
Jan 5 11:45:14 w-ed kernel: [ 7455.551495] rtlwifi: :<0> Enter 802.11 power save mode...
Jan 5 11:45:14 w-ed kernel: [ 7455.551500] rtlwifi: :<0> FW LPS enter ps_mode:3
Jan 5 11:45:14 w-ed kernel: [ 7455.551504] rtlwifi: :<0> FW LPS mode = 3
Jan 5 11:45:14 w-ed kernel: [ 7455.551507] rtlwifi: In process "kworker/0:1" (pid 12): rtl8723e_set_fw_rsvdpagepkt(): u1_h2c_set_pwrmode
Jan 5 11:45:14 w-ed kernel: [ 7455.551507]
Jan 5 11:45:14 w-ed kernel: [ 7455.551509] rtlwifi: :<0> come in
Jan 5 11:45:14 w-ed kernel: [ 7455.551550] rtlwifi: :<0> Write element_id box_reg( 1d0) = 1
Jan 5 11:45:14 w-ed kernel: [ 7455.551560] rtlwifi: :<0> pHalData->last_hmeboxnum = 1
Jan 5 11:45:14 w-ed kernel: [ 7455.551562] rtlwifi: :<0> go out
Jan 5 11:45:14 w-ed kernel: [ 7455.551607] rtlwifi: :<0> AP off for 8 s
Jan 5 11:45:16 w-ed kernel: [ 7457.598533] rtlwifi: :<0> Enter 802.11 power save mode...
Jan 5 11:45:16 w-ed kernel: [ 7457.598538] rtlwifi: :<0> FW LPS enter ps_mode:3
Jan 5 11:45:16 w-ed kernel: [ 7457.598542] rtlwifi: :<0> FW LPS mode = 3
Jan 5 11:45:16 w-ed kernel: [ 7457.598545] rtlwifi: In process "kworker/0:1" (pid 12): rtl8723e_set_fw_rsvdpagepkt(): u1_h2c_set_pwrmode
Jan 5 11:45:16 w-ed kernel: [ 7457.598545]
Jan 5 11:45:16 w-ed kernel: [ 7457.598547] rtlwifi: :<0> come in
Jan 5 11:45:16 w-ed kernel: [ 7457.598588] rtlwifi: :<0> Write element_id box_reg( 1d4) = 1
Jan 5 11:45:16 w-ed kernel: [ 7457.598598] rtlwifi: :<0> pHalData->last_hmeboxnum = 2
Jan 5 11:45:16 w-ed kernel: [ 7457.598599] rtlwifi: :<0> go out
Jan 5 11:45:16 w-ed kernel: [ 7457.598645] rtlwifi: :<0> AP off for 10 s
Jan 5 11:45:16 w-ed kernel: [ 7457.598646] rtlwifi: AP off, try to reconnect now
Jan 5 11:45:16 w-ed kernel: [ 7457.598765] wlan0: Connection to AP 44:4e:6d:66:4c:d5 lost
Jan 5 11:45:16 w-ed kernel: [ 7457.608457] rtlwifi: :<200>
Jan 5 11:45:16 w-ed kernel: [ 7457.608502] rtlwifi: :<0> IEEE80211_AMPDU_RX_STOP:TID:0
Jan 5 11:45:16 w-ed kernel: [ 7457.608506] rtlwifi: :<0> on ra = 44:4e:6d:66:4c:d5 tid = 0
Jan 5 11:45:16 w-ed kernel: [ 7457.608510] rtlwifi: :<0> IEEE80211_AMPDU_RX_STOP:TID:6
Jan 5 11:45:16 w-ed kernel: [ 7457.608513] rtlwifi: :<0> on ra = 44:4e:6d:66:4c:d5 tid = 6
Jan 5 11:45:16 w-ed kernel: [ 7457.608549] rtlwifi: :<10000> Manage ok interrupt!
Jan 5 11:45:16 w-ed kernel: [ 7457.608559] rtlwifi: :<10000> new ring->idx:124, free: skb_queue_len:0, free: seq:fb0
Jan 5 11:45:16 w-ed kernel: [ 7457.614945] rtlwifi: :<10000> Rx ok interrupt!
Jan 5 11:45:16 w-ed kernel: [ 7457.614966] rtlwifi: :<10000> regaddr(0x824), bitmask(0x200)
Jan 5 11:45:16 w-ed kernel: [ 7457.615004] rtlwifi: :<10000> BBR MASK=0x200 Addr[0x824]=0x80390004
Jan 5 11:45:16 w-ed kernel: [ 7457.620509] rtlwifi: :<0> IEEE80211_AMPDU_TX_STOP: TID:0
Jan 5 11:45:16 w-ed kernel: [ 7457.620515] rtlwifi: :<0> on ra = 44:4e:6d:66:4c:d5 tid = 0
Jan 5 11:45:16 w-ed wpa_supplicant[1424]: nl80211: Event message available
Jan 5 11:45:16 w-ed wpa_supplicant[1424]: nl80211: Drv Event 20 (NL80211_CMD_DEL_STATION) received for wlan0
Jan 5 11:45:16 w-ed wpa_supplicant[1424]: nl80211: Delete station 44:4e:6d:66:4c:d5
Jan 5 11:45:16 w-ed kernel: [ 7457.636371] rtlwifi: :<0> Disabling hardware based encryption for keyidx: 0, mac: 44:4e:6d:66:4c:d5
Jan 5 11:45:16 w-ed kernel: [ 7457.636378] rtlwifi: :<0> alg:CCMP
Jan 5 11:45:16 w-ed kernel: [ 7457.636381] rtlwifi: :<0> set enable_hw_sec, key_type:4(OPEN:0 WEP40:1 TKIP:2 AES:4 WEP104:5)
Jan 5 11:45:16 w-ed kernel: [ 7457.636383] rtlwifi: :<0> PairwiseEncAlgorithm = 4 GroupEncAlgorithm = 4
Jan 5 11:45:16 w-ed kernel: [ 7457.636422] rtlwifi: :<0> The SECR-value cc
Jan 5 11:45:16 w-ed kernel: [ 7457.636427] rtlwifi: :<0> disable key delete one entry
Jan 5 11:45:16 w-ed kernel: [ 7457.636429] rtlwifi: :<0> key_idx:0
Jan 5 11:45:16 w-ed kernel: [ 7457.636471] rtlwifi: :<0> rtl_cam_delete_one_entry(): WRITE A4: 0
Jan 5 11:45:16 w-ed kernel: [ 7457.636473] rtlwifi: :<0> rtl_cam_delete_one_entry(): WRITE A0: 80010000
Jan 5 11:45:16 w-ed kernel: [ 7457.636542] rtlwifi: :<0> Remove sta addr is 44:4e:6d:66:4c:d5
Jan 5 11:45:16 w-ed kernel: [ 7457.636627] rtlwifi: :<0> Busy Traffic,Leave 802.11 power save..
Jan 5 11:45:16 w-ed kernel: [ 7457.636629] rtlwifi: :<0> FW LPS leave ps_mode:0
Jan 5 11:45:16 w-ed kernel: [ 7457.636675] rtlwifi: :<0> FW LPS mode = 0
Jan 5 11:45:16 w-ed kernel: [ 7457.636678] rtlwifi: In process "kworker/u8:4" (pid 6479): rtl8723e_set_fw_rsvdpagepkt(): u1_h2c_set_pwrmode
Jan 5 11:45:16 w-ed kernel: [ 7457.636678]
Jan 5 11:45:16 w-ed kernel: [ 7457.636680] rtlwifi: :<0> come in
Jan 5 11:45:16 w-ed kernel: [ 7457.636721] rtlwifi: :<0> Write element_id box_reg( 1d8) = 1
Jan 5 11:45:16 w-ed kernel: [ 7457.636769] rtlwifi: :<0> pHalData->last_hmeboxnum = 3
Jan 5 11:45:16 w-ed kernel: [ 7457.636771] rtlwifi: :<0> go out
Jan 5 11:45:16 w-ed kernel: [ 7457.636777] rtlwifi: :<0> bssid = 44-4e-6d-66-4c-d5
Jan 5 11:45:16 w-ed kernel: [ 7457.636779] rtlwifi: :<0> BSS_CHANGED_UN_ASSOC
Jan 5 11:45:16 w-ed kernel: [ 7457.636820] rtlwifi: :<0> clear 0x550 when set HW_VAR_MEDIA_STATUS
Jan 5 11:45:16 w-ed kernel: [ 7457.636822] rtlwifi: :<0> Set Network type to STA!
Jan 5 11:45:16 w-ed kernel: [ 7457.636876] rtlwifi: :<0> ledaction 3,
Jan 5 11:45:16 w-ed kernel: [ 7457.636878] rtlwifi: :<0> LedAddr:4E ledpin=1
Jan 5 11:45:16 w-ed kernel: [ 7457.636926] rtlwifi: :<0> come in
Jan 5 11:45:16 w-ed kernel: [ 7457.636932] rtlwifi: :<0> Write element_id box_reg( 1dc) = 2
Jan 5 11:45:16 w-ed kernel: [ 7457.636944] rtlwifi: :<0> pHalData->last_hmeboxnum = 0
Jan 5 11:45:16 w-ed kernel: [ 7457.636945] rtlwifi: :<0> go out
Jan 5 11:45:16 w-ed kernel: [ 7457.636949] rtlwifi: :<0> BSS_CHANGED_ERP_CTS_PROT
Jan 5 11:45:16 w-ed kernel: [ 7457.636951] rtlwifi: :<0> BSS_CHANGED_ERP_PREAMBLE use short preamble:0
Jan 5 11:45:16 w-ed kernel: [ 7457.636990] rtlwifi: :<0> BSS_CHANGED_ERP_SLOT
Jan 5 11:45:16 w-ed kernel: [ 7457.636992] rtlwifi: :<0> HW_VAR_SLOT_TIME 14
Jan 5 11:45:16 w-ed kernel: [ 7457.636998] rtlwifi: :<0> BSS_CHANGED_HT
Jan 5 11:45:16 w-ed kernel: [ 7457.637002] rtlwifi: :<0> Set HW_VAR_SHORTGI_DENSITY: 0x7
Jan 5 11:45:16 w-ed kernel: [ 7457.637049] rtlwifi: :<0> Set HW_VAR_AMPDU_FACTOR: 0xf
Jan 5 11:45:16 w-ed kernel: [ 7457.637052] rtlwifi: :<0> Set HW_VAR_AMPDU_MIN_SPACE: 0x7
Jan 5 11:45:16 w-ed kernel: [ 7457.637106] rtlwifi: :<0> bssid: 00:00:00:00:00:00
Jan 5 11:45:16 w-ed kernel: [ 7457.637160] rtlwifi: :<0> switch to channel13

now after time index 7457.614945 the "Rx ok interrupt" start again.

2019-01-05 16:14:36

by Larry Finger

[permalink] [raw]
Subject: Re: [PATCH 1/4] rtlwifi: rtl8723ae: Take the FW LPS mode handling out

On 1/5/19 5:31 AM, Bernd Edlinger wrote:
> On 1/5/19 3:44 AM, Larry Finger wrote:
>> On 1/4/19 6:48 AM, Bernd Edlinger wrote:
>>> This appears to trigger a firmware bug and causes severe
>>> problems with rtl8723ae PCI devices.
>>>
>>> When the power save mode is activated for longer periods
>>> of time the firmware stops to receive any packets.
>>>
>>> This problem was exposed by commit 873ffe154ae0 ("rtlwifi:
>>> Fix logic error in enter/exit power-save mode").
>>>
>>> Previously the power save mode was only active rarely and
>>> only for a short time so that the problem was not noticeable.
>>>
>>> Signed-off-by: Bernd Edlinger <[email protected]>
>>> ---
>>
>> While the Realtek firmware group has a chance to look for a bug, I would like you to perform a couple of tests on the original code.
>>
>> The driver has three module parameters that affect power save. The 'modinfo rtl8723ae' command lists them as
>>
>> parm:   ips:Set to 0 to not use link power save (default 1) (bool)
>> parm:   swlps:Set to 1 to use SW control power save (default 0) (bool)
>> parm:   fwlps:Set to 1 to use FW control power save (default 1) (bool)
>>
>> If you were to load rtl8723ae with 'ips=0', does it still fail?
>> If you were to load the driver with 'swlps=1 fwlps=0', does it still fail?
>>
>
> this does not work:
>
> modprobe rtl8723ae debug_mask=0xFFFFFFFF debug_level=5 ips=0
>
> tail -f /var/log/syslog|grep "AP off"
> Jan 5 11:42:06 w-ed kernel: [ 7267.229713] rtlwifi: :<0> AP off for 2 s
> Jan 5 11:42:08 w-ed kernel: [ 7269.276761] rtlwifi: :<0> AP off for 4 s
> Jan 5 11:42:10 w-ed kernel: [ 7271.323758] rtlwifi: :<0> AP off for 6 s
> Jan 5 11:42:12 w-ed kernel: [ 7273.370759] rtlwifi: :<0> AP off for 8 s
> Jan 5 11:42:14 w-ed kernel: [ 7275.417753] rtlwifi: :<0> AP off for 10 s
> Jan 5 11:42:14 w-ed kernel: [ 7275.417754] rtlwifi: AP off, try to reconnect now
> Jan 5 11:42:28 w-ed kernel: [ 7289.746676] rtlwifi: :<0> AP off for 2 s
> Jan 5 11:42:40 w-ed kernel: [ 7302.028327] rtlwifi: :<0> AP off for 2 s
> Jan 5 11:42:43 w-ed kernel: [ 7304.075327] rtlwifi: :<0> AP off for 4 s
> Jan 5 11:42:45 w-ed kernel: [ 7306.122330] rtlwifi: :<0> AP off for 6 s
> Jan 5 11:42:47 w-ed kernel: [ 7308.169292] rtlwifi: :<0> AP off for 8 s
> Jan 5 11:42:49 w-ed kernel: [ 7310.216236] rtlwifi: :<0> AP off for 10 s
> Jan 5 11:42:49 w-ed kernel: [ 7310.216238] rtlwifi: AP off, try to reconnect now
> Jan 5 11:43:05 w-ed kernel: [ 7326.592222] rtlwifi: :<0> AP off for 2 s
> Jan 5 11:43:07 w-ed kernel: [ 7328.639076] rtlwifi: :<0> AP off for 4 s
> Jan 5 11:43:09 w-ed kernel: [ 7330.686220] rtlwifi: :<0> AP off for 6 s
> Jan 5 11:43:11 w-ed kernel: [ 7332.733078] rtlwifi: :<0> AP off for 8 s
> Jan 5 11:43:13 w-ed kernel: [ 7334.779988] rtlwifi: :<0> AP off for 10 s
> Jan 5 11:43:13 w-ed kernel: [ 7334.779989] rtlwifi: AP off, try to reconnect now
> Jan 5 11:43:28 w-ed kernel: [ 7349.108839] rtlwifi: :<0> AP off for 2 s
> Jan 5 11:43:30 w-ed kernel: [ 7351.155837] rtlwifi: :<0> AP off for 4 s
> Jan 5 11:43:32 w-ed kernel: [ 7353.202838] rtlwifi: :<0> AP off for 6 s
> Jan 5 11:43:42 w-ed kernel: [ 7363.437779] rtlwifi: :<0> AP off for 2 s
> Jan 5 11:43:46 w-ed kernel: [ 7367.531622] rtlwifi: :<0> AP off for 2 s
> Jan 5 11:43:48 w-ed kernel: [ 7369.578597] rtlwifi: :<0> AP off for 4 s
> Jan 5 11:43:50 w-ed kernel: [ 7371.625694] rtlwifi: :<0> AP off for 6 s
> Jan 5 11:43:52 w-ed kernel: [ 7373.672691] rtlwifi: :<0> AP off for 8 s
> Jan 5 11:43:54 w-ed kernel: [ 7375.719690] rtlwifi: :<0> AP off for 10 s
> Jan 5 11:43:54 w-ed kernel: [ 7375.719691] rtlwifi: AP off, try to reconnect now
> Jan 5 11:44:09 w-ed kernel: [ 7390.048406] rtlwifi: :<0> AP off for 2 s
> Jan 5 11:44:11 w-ed kernel: [ 7392.095678] rtlwifi: :<0> AP off for 4 s
> Jan 5 11:44:13 w-ed kernel: [ 7394.142349] rtlwifi: :<0> AP off for 6 s
> Jan 5 11:44:15 w-ed kernel: [ 7396.189352] rtlwifi: :<0> AP off for 8 s
> Jan 5 11:44:17 w-ed kernel: [ 7398.236352] rtlwifi: :<0> AP off for 10 s
> Jan 5 11:44:17 w-ed kernel: [ 7398.236353] rtlwifi: AP off, try to reconnect now
> Jan 5 11:44:31 w-ed kernel: [ 7412.565079] rtlwifi: :<0> AP off for 2 s
> Jan 5 11:44:33 w-ed kernel: [ 7414.612167] rtlwifi: :<0> AP off for 4 s
> Jan 5 11:44:35 w-ed kernel: [ 7416.659101] rtlwifi: :<0> AP off for 6 s
> Jan 5 11:44:37 w-ed kernel: [ 7418.706035] rtlwifi: :<0> AP off for 8 s
> Jan 5 11:44:39 w-ed kernel: [ 7420.753100] rtlwifi: :<0> AP off for 10 s
> Jan 5 11:44:39 w-ed kernel: [ 7420.753101] rtlwifi: AP off, try to reconnect now
> Jan 5 11:44:54 w-ed kernel: [ 7435.081860] rtlwifi: :<0> AP off for 2 s
> Jan 5 11:44:56 w-ed kernel: [ 7437.128857] rtlwifi: :<0> AP off for 4 s
> Jan 5 11:45:08 w-ed kernel: [ 7449.410653] rtlwifi: :<0> AP off for 2 s
> Jan 5 11:45:10 w-ed kernel: [ 7451.457650] rtlwifi: :<0> AP off for 4 s
> Jan 5 11:45:12 w-ed kernel: [ 7453.504647] rtlwifi: :<0> AP off for 6 s
> Jan 5 11:45:14 w-ed kernel: [ 7455.551607] rtlwifi: :<0> AP off for 8 s
> Jan 5 11:45:16 w-ed kernel: [ 7457.598645] rtlwifi: :<0> AP off for 10 s
> Jan 5 11:45:16 w-ed kernel: [ 7457.598646] rtlwifi: AP off, try to reconnect now
>
>
> but this works:
>
> modprobe rtl8723ae debug_mask=0xFFFFFFFF debug_level=5 swlps=1 fwlps=0

Yes, I think that is a better thing to do now. If and when Realtek finds a
firmware bug, and when the new firmware is readily available, then there will
not be a lot of code to reinstall.

Thanks for testing,

Larry



2019-01-05 16:32:49

by Bernd Edlinger

[permalink] [raw]
Subject: Re: [PATCH 1/4] rtlwifi: rtl8723ae: Take the FW LPS mode handling out

On 1/5/19 5:13 PM, Larry Finger wrote:
>> but this works:
>>
>> modprobe rtl8723ae debug_mask=0xFFFFFFFF debug_level=5 swlps=1 fwlps=0
>
> Yes, I think that is a better thing to do now. If and when Realtek finds a firmware bug, and when the new firmware is readily available, then there will not be a lot of code to reinstall.
>

Okay, my assumption of how the firmware bug "works" is this:

Once the firmware enters power save mode, it will deliver exactly one (or maybe two)
Rx interrupts. If one of those triggers the driver to leave the power save mode again,
the firmware continues to work.
If those are only beacons, they won't leave the power save mode. Then the firmware
will usually not recover.
Since prior to commit 873ffe154ae0 ("rtlwifi: Fix logic error in enter/exit power-save mode")
the power save mode was only activated when there _is_ busy traffic, the next
packet did usually wake the firmware, rarely it did freeze however.
Other things like changing the cck_packet_detection_threshold or refresh_rate_adaptive_mask
can also kick the firmware back to life.

Hope this helps to track down the root cause of this bug.


Thanks
Bernd.

2019-01-05 16:38:29

by Larry Finger

[permalink] [raw]
Subject: Re: [PATCH 1/4] rtlwifi: rtl8723ae: Take the FW LPS mode handling out

On 1/5/19 10:30 AM, Bernd Edlinger wrote:
> On 1/5/19 5:13 PM, Larry Finger wrote:
>>> but this works:
>>>
>>> modprobe rtl8723ae debug_mask=0xFFFFFFFF debug_level=5 swlps=1 fwlps=0
>>
>> Yes, I think that is a better thing to do now. If and when Realtek finds a firmware bug, and when the new firmware is readily available, then there will not be a lot of code to reinstall.
>>
>
> Okay, my assumption of how the firmware bug "works" is this:
>
> Once the firmware enters power save mode, it will deliver exactly one (or maybe two)
> Rx interrupts. If one of those triggers the driver to leave the power save mode again,
> the firmware continues to work.
> If those are only beacons, they won't leave the power save mode. Then the firmware
> will usually not recover.
> Since prior to commit 873ffe154ae0 ("rtlwifi: Fix logic error in enter/exit power-save mode")
> the power save mode was only activated when there _is_ busy traffic, the next
> packet did usually wake the firmware, rarely it did freeze however.
> Other things like changing the cck_packet_detection_threshold or refresh_rate_adaptive_mask
> can also kick the firmware back to life.
>
> Hope this helps to track down the root cause of this bug.

As I know nothing of the firmware, that is outside my expertise, but that
observation should be of great help to PK Shih, and his colleagues at Realtek.

Larry