RFC: wilc1000 module parameter to disable chip sleep

RFC: wilc1000 module parameter to disable chip sleep

[David Mosberger-Tang]

At least on our SAMA5-based platform, the chip-sleep in the wilc1000
driver degrades WILC1000 transmit throughput by more than three times,
without providing significant power-savings.  Because of that, I have
been considering adding a module parameter that would make the chip
sleep optional.  Something along these lines:

diff --git a/drivers/net/wireless/microchip/wilc1000/wlan.c b/drivers/net/wireless/microchip/wilc1000/wlan.c
index 757bd4471fd4..421672488100 100644
--- a/drivers/net/wireless/microchip/wilc1000/wlan.c
+++ b/drivers/net/wireless/microchip/wilc1000/wlan.c
@@ -10,6 +10,12 @@
 #include "cfg80211.h"
 #include "wlan_cfg.h"
 
+static bool enable_sleep;
+module_param(enable_sleep, bool, 0644);
+MODULE_PARM_DESC(enable_sleep,
+		 "Enable chip sleep whenever the host is done communicating\n"
+		 "\t\t\twith the WILC1000 chip.");
+
 static inline bool is_wilc1000(u32 id)
 {
 	return (id & (~WILC_CHIP_REV_FIELD)) == WILC_1000_BASE_ID;
@@ -18,13 +24,13 @@ static inline bool is_wilc1000(u32 id)
 static inline void acquire_bus(struct wilc *wilc, enum bus_acquire acquire)
 {
 	mutex_lock(&wilc->hif_cs);
-	if (acquire == WILC_BUS_ACQUIRE_AND_WAKEUP)
+	if (enable_sleep && acquire == WILC_BUS_ACQUIRE_AND_WAKEUP)
 		chip_wakeup(wilc);
 }
 
 static inline void release_bus(struct wilc *wilc, enum bus_release release)
 {
-	if (release == WILC_BUS_RELEASE_ALLOW_SLEEP)
+	if (enable_sleep && release == WILC_BUS_RELEASE_ALLOW_SLEEP)
 		chip_allow_sleep(wilc);
 	mutex_unlock(&wilc->hif_cs);
 }

However, based on the numbers below, I'm now wondering if it wouldn't
make more sense to remove the chip-sleep code altogether.

Here is what I see: on a system configured for minimum power consumption
(all unnecessary daemons disabled, Ethernet unplugged) I measured 1,180 mW
when the WILC chip is in RESET (the ENABLE pin is always high on our platform).

With the wilc1000-spi/wilc1000 modules loaded and the WILC chip
running but without being associated with a WLAN network, measured
power consumption was 1,460 mW, regardless of whether chip sleep was
enabled or disabled.

On the other hand, chip-sleep makes a huge difference for TX
throughput and also reduces RX throughput, but to a smaller
extent.  Specifically, I used ttcp to measure throughput on the
test system 5 times in a row, both in TX and RX direction
(TX meaning "ttcp -t" is run from the test system to a desktop
machine):

TX throughput ("./ttcp -t DESKTOPIPADDR" on the DUT):
enable_sleep=1: 16777216 bytes in 41.22 real seconds = 397.50 KB/sec +++
enable_sleep=1: 16777216 bytes in 40.67 real seconds = 402.81 KB/sec +++
enable_sleep=1: 16777216 bytes in 41.08 real seconds = 398.83 KB/sec +++
enable_sleep=1: 16777216 bytes in 41.35 real seconds = 396.25 KB/sec +++

enable_sleep=0: 16777216 bytes in 11.12 real seconds = 1472.78 KB/sec +++
enable_sleep=0: 16777216 bytes in 10.76 real seconds = 1523.10 KB/sec +++
enable_sleep=0: 16777216 bytes in 11.83 real seconds = 1385.21 KB/sec +++
enable_sleep=0: 16777216 bytes in 10.94 real seconds = 1497.66 KB/sec +++
enable_sleep=0: 16777216 bytes in 10.13 real seconds = 1617.21 KB/sec +++

RX throughput ("./ttcp -r" on the DUT):

enable_sleep=1: 16777216 bytes in 8.44 real seconds = 1941.97 KB/sec +++
enable_sleep=1: wilc1000, w/ sleep: 16777216 bytes in 12.69 real seconds = 1290.94 KB/sec +++
enable_sleep=1: 16777216 bytes in 12.79 real seconds = 1280.93 KB/sec +++
enable_sleep=1: 16777216 bytes in 12.39 real seconds = 1322.33 KB/sec +++

enable_sleep=0: 16777216 bytes in 5.83 real seconds = 2811.94 KB/sec +++
enable_sleep=0: 16777216 bytes in 5.75 real seconds = 2848.09 KB/sec +++
enable_sleep=0: 16777216 bytes in 5.97 real seconds = 2744.44 KB/sec +++
enable_sleep=0: 16777216 bytes in 6.11 real seconds = 2681.96 KB/sec +++
enable_sleep=0: 16777216 bytes in 6.01 real seconds = 2724.09 KB/sec +++

From what I can tell, the chip-sleep code either isn't working or the chip
sleep just isn't making any real difference in power consumption.

Given this, is there any reason to keep the chip-sleep code around?

  --david

Re: RFC: wilc1000 module parameter to disable chip sleep

[Kalle Valo]

David Mosberger-Tang <davidm@egauge.net> writes:

> At least on our SAMA5-based platform, the chip-sleep in the wilc1000
> driver degrades WILC1000 transmit throughput by more than three times,
> without providing significant power-savings.  Because of that, I have
> been considering adding a module parameter that would make the chip
> sleep optional.  Something along these lines:
>
> diff --git a/drivers/net/wireless/microchip/wilc1000/wlan.c b/drivers/net/wireless/microchip/wilc1000/wlan.c
> index 757bd4471fd4..421672488100 100644
> --- a/drivers/net/wireless/microchip/wilc1000/wlan.c
> +++ b/drivers/net/wireless/microchip/wilc1000/wlan.c
> @@ -10,6 +10,12 @@
>  #include "cfg80211.h"
>  #include "wlan_cfg.h"
>  
> +static bool enable_sleep;
> +module_param(enable_sleep, bool, 0644);
> +MODULE_PARM_DESC(enable_sleep,
> +		 "Enable chip sleep whenever the host is done communicating\n"
> +		 "\t\t\twith the WILC1000 chip.");
> +
>  static inline bool is_wilc1000(u32 id)
>  {
>  	return (id & (~WILC_CHIP_REV_FIELD)) == WILC_1000_BASE_ID;
> @@ -18,13 +24,13 @@ static inline bool is_wilc1000(u32 id)
>  static inline void acquire_bus(struct wilc *wilc, enum bus_acquire acquire)
>  {
>  	mutex_lock(&wilc->hif_cs);
> -	if (acquire == WILC_BUS_ACQUIRE_AND_WAKEUP)
> +	if (enable_sleep && acquire == WILC_BUS_ACQUIRE_AND_WAKEUP)
>  		chip_wakeup(wilc);
>  }
>  
>  static inline void release_bus(struct wilc *wilc, enum bus_release release)
>  {
> -	if (release == WILC_BUS_RELEASE_ALLOW_SLEEP)
> +	if (enable_sleep && release == WILC_BUS_RELEASE_ALLOW_SLEEP)
>  		chip_allow_sleep(wilc);
>  	mutex_unlock(&wilc->hif_cs);
>  }
>
> However, based on the numbers below, I'm now wondering if it wouldn't
> make more sense to remove the chip-sleep code altogether.
>
> Here is what I see: on a system configured for minimum power consumption
> (all unnecessary daemons disabled, Ethernet unplugged) I measured 1,180 mW
> when the WILC chip is in RESET (the ENABLE pin is always high on our platform).
>
> With the wilc1000-spi/wilc1000 modules loaded and the WILC chip
> running but without being associated with a WLAN network, measured
> power consumption was 1,460 mW, regardless of whether chip sleep was
> enabled or disabled.
>
> On the other hand, chip-sleep makes a huge difference for TX
> throughput and also reduces RX throughput, but to a smaller
> extent.  Specifically, I used ttcp to measure throughput on the
> test system 5 times in a row, both in TX and RX direction
> (TX meaning "ttcp -t" is run from the test system to a desktop
> machine):
>
> TX throughput ("./ttcp -t DESKTOPIPADDR" on the DUT):
> enable_sleep=1: 16777216 bytes in 41.22 real seconds = 397.50 KB/sec +++
> enable_sleep=1: 16777216 bytes in 40.67 real seconds = 402.81 KB/sec +++
> enable_sleep=1: 16777216 bytes in 41.08 real seconds = 398.83 KB/sec +++
> enable_sleep=1: 16777216 bytes in 41.35 real seconds = 396.25 KB/sec +++
>
> enable_sleep=0: 16777216 bytes in 11.12 real seconds = 1472.78 KB/sec +++
> enable_sleep=0: 16777216 bytes in 10.76 real seconds = 1523.10 KB/sec +++
> enable_sleep=0: 16777216 bytes in 11.83 real seconds = 1385.21 KB/sec +++
> enable_sleep=0: 16777216 bytes in 10.94 real seconds = 1497.66 KB/sec +++
> enable_sleep=0: 16777216 bytes in 10.13 real seconds = 1617.21 KB/sec +++
>
> RX throughput ("./ttcp -r" on the DUT):
>
> enable_sleep=1: 16777216 bytes in 8.44 real seconds = 1941.97 KB/sec +++
> enable_sleep=1: wilc1000, w/ sleep: 16777216 bytes in 12.69 real seconds = 1290.94 KB/sec +++
> enable_sleep=1: 16777216 bytes in 12.79 real seconds = 1280.93 KB/sec +++
> enable_sleep=1: 16777216 bytes in 12.39 real seconds = 1322.33 KB/sec +++
>
> enable_sleep=0: 16777216 bytes in 5.83 real seconds = 2811.94 KB/sec +++
> enable_sleep=0: 16777216 bytes in 5.75 real seconds = 2848.09 KB/sec +++
> enable_sleep=0: 16777216 bytes in 5.97 real seconds = 2744.44 KB/sec +++
> enable_sleep=0: 16777216 bytes in 6.11 real seconds = 2681.96 KB/sec +++
> enable_sleep=0: 16777216 bytes in 6.01 real seconds = 2724.09 KB/sec +++
>
>>From what I can tell, the chip-sleep code either isn't working or the chip
> sleep just isn't making any real difference in power consumption.
>
> Given this, is there any reason to keep the chip-sleep code around?

If it doesn't work I would just remove it to keep things simple. It can
always added back if somebody fixes it.

-- 
https://patchwork.kernel.org/project/linux-wireless/list/

https://wireless.wiki.kernel.org/en/developers/documentation/submittingpatches

Re: RFC: wilc1000 module parameter to disable chip sleep

[Ajay.Kathat]

On 09/12/21 00:20, David Mosberger-Tang wrote:
> EXTERNAL EMAIL: Do not click links or open attachments unless you know the content is safe
>
> At least on our SAMA5-based platform, the chip-sleep in the wilc1000
> driver degrades WILC1000 transmit throughput by more than three times,
> without providing significant power-savings.  Because of that, I have
> been considering adding a module parameter that would make the chip
> sleep optional.  Something along these lines:
>
> diff --git a/drivers/net/wireless/microchip/wilc1000/wlan.c b/drivers/net/wireless/microchip/wilc1000/wlan.c
> index 757bd4471fd4..421672488100 100644
> --- a/drivers/net/wireless/microchip/wilc1000/wlan.c
> +++ b/drivers/net/wireless/microchip/wilc1000/wlan.c
> @@ -10,6 +10,12 @@
>   #include "cfg80211.h"
>   #include "wlan_cfg.h"
>
> +static bool enable_sleep;
> +module_param(enable_sleep, bool, 0644);
> +MODULE_PARM_DESC(enable_sleep,
> +                "Enable chip sleep whenever the host is done communicating\n"
> +                "\t\t\twith the WILC1000 chip.");
> +
>   static inline bool is_wilc1000(u32 id)
>   {
>          return (id & (~WILC_CHIP_REV_FIELD)) == WILC_1000_BASE_ID;
> @@ -18,13 +24,13 @@ static inline bool is_wilc1000(u32 id)
>   static inline void acquire_bus(struct wilc *wilc, enum bus_acquire acquire)
>   {
>          mutex_lock(&wilc->hif_cs);
> -       if (acquire == WILC_BUS_ACQUIRE_AND_WAKEUP)
> +       if (enable_sleep && acquire == WILC_BUS_ACQUIRE_AND_WAKEUP)
>                  chip_wakeup(wilc);
>   }
>
>   static inline void release_bus(struct wilc *wilc, enum bus_release release)
>   {
> -       if (release == WILC_BUS_RELEASE_ALLOW_SLEEP)
> +       if (enable_sleep && release == WILC_BUS_RELEASE_ALLOW_SLEEP)
>                  chip_allow_sleep(wilc);
>          mutex_unlock(&wilc->hif_cs);
>   }
>
> However, based on the numbers below, I'm now wondering if it wouldn't
> make more sense to remove the chip-sleep code altogether.


The "chip_wakeup" & "chip_allow_sleep" API's are required to configure 
the wake-up registers in wilc. These registers must be configured 
correctly when the power save mode is enabled. These API's get used for 
both SPI/SDIO bus.


> Here is what I see: on a system configured for minimum power consumption
> (all unnecessary daemons disabled, Ethernet unplugged) I measured 1,180 mW
> when the WILC chip is in RESET (the ENABLE pin is always high on our platform).
>
> With the wilc1000-spi/wilc1000 modules loaded and the WILC chip
> running but without being associated with a WLAN network, measured
> power consumption was 1,460 mW, regardless of whether chip sleep was
> enabled or disabled.


Did you test by enabling the power-save mode with "wpa_supplicant" or 
using "iw" command. For power consumption measurement, please try by 
disabling the PSM mode.


Below command can be used to enable/disable PSM mode.

iw dev wlan0 set power_save on/off


There is a document(link below) which contain details about the power 
consumption measured for WILC1000. Please check, it may be useful.

https://ww1.microchip.com/downloads/en/Appnotes/ATWILC1000-Power-Measurement-for-Wi-Fi-Link-Controller-00002797A.pdf


> On the other hand, chip-sleep makes a huge difference for TX
> throughput and also reduces RX throughput, but to a smaller
> extent.  Specifically, I used ttcp to measure throughput on the
> test system 5 times in a row, both in TX and RX direction
> (TX meaning "ttcp -t" is run from the test system to a desktop
> machine):
> TX throughput ("./ttcp -t DESKTOPIPADDR" on the DUT):
> enable_sleep=1: 16777216 bytes in 41.22 real seconds = 397.50 KB/sec +++
> enable_sleep=1: 16777216 bytes in 40.67 real seconds = 402.81 KB/sec +++
> enable_sleep=1: 16777216 bytes in 41.08 real seconds = 398.83 KB/sec +++
> enable_sleep=1: 16777216 bytes in 41.35 real seconds = 396.25 KB/sec +++
>
> enable_sleep=0: 16777216 bytes in 11.12 real seconds = 1472.78 KB/sec +++
> enable_sleep=0: 16777216 bytes in 10.76 real seconds = 1523.10 KB/sec +++
> enable_sleep=0: 16777216 bytes in 11.83 real seconds = 1385.21 KB/sec +++
> enable_sleep=0: 16777216 bytes in 10.94 real seconds = 1497.66 KB/sec +++
> enable_sleep=0: 16777216 bytes in 10.13 real seconds = 1617.21 KB/sec +++
>
> RX throughput ("./ttcp -r" on the DUT):
>
> enable_sleep=1: 16777216 bytes in 8.44 real seconds = 1941.97 KB/sec +++
> enable_sleep=1: wilc1000, w/ sleep: 16777216 bytes in 12.69 real seconds = 1290.94 KB/sec +++
> enable_sleep=1: 16777216 bytes in 12.79 real seconds = 1280.93 KB/sec +++
> enable_sleep=1: 16777216 bytes in 12.39 real seconds = 1322.33 KB/sec +++
>
> enable_sleep=0: 16777216 bytes in 5.83 real seconds = 2811.94 KB/sec +++
> enable_sleep=0: 16777216 bytes in 5.75 real seconds = 2848.09 KB/sec +++
> enable_sleep=0: 16777216 bytes in 5.97 real seconds = 2744.44 KB/sec +++
> enable_sleep=0: 16777216 bytes in 6.11 real seconds = 2681.96 KB/sec +++
> enable_sleep=0: 16777216 bytes in 6.01 real seconds = 2724.09 KB/sec +++


These throughput number are low in your setup though I am not sure about 
the reason. Actually, the throughput depends on many factors.

Below are the number, I got using iPerf on my setup in open environment 
with/without PS mode. The iPerf test duration was 100sec and the SPI 
max_speed_hz at 48Mhz.

The test is executed with chip-sleep code.


*power-save enabled*

TCP Tx :  [ 4] 0.0-100.1 sec 47.8 MBytes 4.01 Mbits/sec

TCP Rx : [ 4] 0.0-100.3 sec 115 MBytes 9.65 Mbits/sec


*power-save disabled*

TCP Tx :  [ 4] 0.0-100.1 sec 61.9 MBytes 5.19 Mbits/sec

TCP Rx : [ 4] 0.0-100.0 sec 122 MBytes 10.2 Mbits/sec


As I observed, there is an improvement of around ~1Mbps when the PS mode 
is disabled. These numbers would be higher when the test is performed in 
the shield room.

For SDIO bus, the throughput numbers are higher and may cross 20Mbps+ 
for both Tx/Rx path.


>  From what I can tell, the chip-sleep code either isn't working or the chip
> sleep just isn't making any real difference in power consumption.
>
> Given this, is there any reason to keep the chip-sleep code around?


The chip-sleep code is needed to configure the registers properly for 
wilc and not using these sequence would have impact on sending the data 
to wilc, especially when the PS mode is enabled.


Regards,

Ajay

Re: RFC: wilc1000 module parameter to disable chip sleep

[David Mosberger-Tang]

[-- Attachment #1: Type: text/plain, Size: 2141 bytes --]

On Thu, 2021-12-09 at 09:20 +0000, Ajay.Kathat@microchip.com wrote:
> On 09/12/21 00:20, David Mosberger-Tang wrote:

> The "chip_wakeup" & "chip_allow_sleep" API's are required to configure 
> the wake-up registers in wilc. These registers must be configured 
> correctly when the power save mode is enabled.

I see.

> > Here is what I see: on a system configured for minimum power consumption
> > (all unnecessary daemons disabled, Ethernet unplugged) I measured 1,180 mW
> > when the WILC chip is in RESET (the ENABLE pin is always high on our
> > platform).
> > 
> > With the wilc1000-spi/wilc1000 modules loaded and the WILC chip
> > running but without being associated with a WLAN network, measured
> > power consumption was 1,460 mW, regardless of whether chip sleep was
> > enabled or disabled.
> 
> Did you test by enabling the power-save mode with "wpa_supplicant" or 
> using "iw" command. For power consumption measurement, please try by 
> disabling the PSM mode.

No, I have not played with power-saving mode.  There are some disconcerting
messages when turning PSM on:

[ 1764.070375] wilc1000_spi spi1.0: Failed cmd, cmd (ca), resp (00)
[ 1764.076403] wilc1000_spi spi1.0: Failed cmd, read reg (000013f4)...

The driver does still work, but occasionally, I get long streams of these
messages, sometimes it gets to the point where there are so many that the
watchdog timer ends up rebooting the system.

> The chip-sleep code is needed to configure the registers properly for 
> wilc and not using these sequence would have impact on sending the data 
> to wilc, especially when the PS mode is enabled.

How about something along the patch below then?

With this patch, I see the following iperf3 performance (120 second average):

PSM on:
[  4]   0.00-120.00 sec  47.6 MBytes  3.33 Mbits/sec    0             sender

PSM off:
[  4]   0.00-120.00 sec   201 MBytes  14.0 Mbits/sec   12             sender

In terms of power consumption:

   baseline                : 1.2 W
   PSM on, idle            : 1.2 W
   PSM on, TX @ 3.33 Mbps  : 1.7 W
   PSM off, idle           : 1.5 W
   PSM off, TX @ 14.0 Mbps : 2.4 W

  --david


[-- Attachment #2: wip-chip-sleep.diff --]
[-- Type: text/x-patch, Size: 2082 bytes --]

diff --git a/drivers/net/wireless/microchip/wilc1000/hif.c b/drivers/net/wireless/microchip/wilc1000/hif.c
index 44e93cd5e3df..09aa5ced19d3 100644
--- a/drivers/net/wireless/microchip/wilc1000/hif.c
+++ b/drivers/net/wireless/microchip/wilc1000/hif.c
@@ -1912,6 +1912,7 @@ int wilc_edit_station(struct wilc_vif *vif, const u8 *mac,
 
 int wilc_set_power_mgmt(struct wilc_vif *vif, bool enabled, u32 timeout)
 {
+	struct wilc *wilc = vif->wilc;
 	struct wid wid;
 	int result;
 	s8 power_mode;
@@ -1927,6 +1928,8 @@ int wilc_set_power_mgmt(struct wilc_vif *vif, bool enabled, u32 timeout)
 	result = wilc_send_config_pkt(vif, WILC_SET_CFG, &wid, 1);
 	if (result)
 		netdev_err(vif->ndev, "Failed to send power management\n");
+	else
+		wilc->power_save_mode = enabled;
 
 	return result;
 }
diff --git a/drivers/net/wireless/microchip/wilc1000/netdev.h b/drivers/net/wireless/microchip/wilc1000/netdev.h
index 152408232d51..db149abc5d0d 100644
--- a/drivers/net/wireless/microchip/wilc1000/netdev.h
+++ b/drivers/net/wireless/microchip/wilc1000/netdev.h
@@ -267,6 +267,7 @@ struct wilc {
 
 	int clients_count;
 	struct workqueue_struct *hif_workqueue;
+	bool power_save_mode;
 	enum chip_ps_states chip_ps_state;
 	struct wilc_cfg cfg;
 	void *bus_data;
diff --git a/drivers/net/wireless/microchip/wilc1000/wlan.c b/drivers/net/wireless/microchip/wilc1000/wlan.c
index ddd382996275..0e0e325d396e 100644
--- a/drivers/net/wireless/microchip/wilc1000/wlan.c
+++ b/drivers/net/wireless/microchip/wilc1000/wlan.c
@@ -18,13 +18,13 @@ static inline bool is_wilc1000(u32 id)
 static inline void acquire_bus(struct wilc *wilc, enum bus_acquire acquire)
 {
 	mutex_lock(&wilc->hif_cs);
-	if (acquire == WILC_BUS_ACQUIRE_AND_WAKEUP)
+	if (acquire == WILC_BUS_ACQUIRE_AND_WAKEUP && wilc->power_save_mode)
 		chip_wakeup(wilc);
 }
 
 static inline void release_bus(struct wilc *wilc, enum bus_release release)
 {
-	if (release == WILC_BUS_RELEASE_ALLOW_SLEEP)
+	if (release == WILC_BUS_RELEASE_ALLOW_SLEEP && wilc->power_save_mode)
 		chip_allow_sleep(wilc);
 	mutex_unlock(&wilc->hif_cs);
 }

Re: RFC: wilc1000 module parameter to disable chip sleep

[David Mosberger-Tang]

[Sorry, my first email was accidentally had the patch appended as a MIME
 attachment.]

On Thu, 2021-12-09 at 09:20 +0000, Ajay.Kathat@microchip.com wrote:
> On 09/12/21 00:20, David Mosberger-Tang wrote:

> The "chip_wakeup" & "chip_allow_sleep" API's are required to configure 
> the wake-up registers in wilc. These registers must be configured 
> correctly when the power save mode is enabled.

I see.

> > Here is what I see: on a system configured for minimum power consumption
> > (all unnecessary daemons disabled, Ethernet unplugged) I measured 1,180 mW
> > when the WILC chip is in RESET (the ENABLE pin is always high on our
> > platform).
> > 
> > With the wilc1000-spi/wilc1000 modules loaded and the WILC chip
> > running but without being associated with a WLAN network, measured
> > power consumption was 1,460 mW, regardless of whether chip sleep was
> > enabled or disabled.
> 
> Did you test by enabling the power-save mode with "wpa_supplicant" or 
> using "iw" command. For power consumption measurement, please try by 
> disabling the PSM mode.

No, I have not played with power-saving mode.  There are some disconcerting
messages when turning PSM on:

[ 1764.070375] wilc1000_spi spi1.0: Failed cmd, cmd (ca), resp (00)
[ 1764.076403] wilc1000_spi spi1.0: Failed cmd, read reg (000013f4)...

The driver does still work, but occasionally, I get long streams of these
messages, sometimes it gets to the point where there are so many that the
watchdog timer ends up rebooting the system.

> The chip-sleep code is needed to configure the registers properly for 
> wilc and not using these sequence would have impact on sending the data 
> to wilc, especially when the PS mode is enabled.

How about something along the patch below then?

With this patch, I see the following iperf3 performance (120 second average):

PSM on:
[  4]   0.00-120.00 sec  47.6 MBytes  3.33 Mbits/sec    0             sender

PSM off:
[  4]   0.00-120.00 sec   201 MBytes  14.0 Mbits/sec   12             sender

In terms of power consumption:

   baseline                : 1.2 W
   PSM on, idle            : 1.2 W
   PSM on, TX @ 3.33 Mbps  : 1.7 W
   PSM off, idle           : 1.5 W
   PSM off, TX @ 14.0 Mbps : 2.4 W

  --david

diff --git a/drivers/net/wireless/microchip/wilc1000/hif.c
b/drivers/net/wireless/microchip/wilc1000/hif.c
index 44e93cd5e3df..09aa5ced19d3 100644
--- a/drivers/net/wireless/microchip/wilc1000/hif.c
+++ b/drivers/net/wireless/microchip/wilc1000/hif.c
@@ -1912,6 +1912,7 @@ int wilc_edit_station(struct wilc_vif *vif, const u8 *mac,
 
 int wilc_set_power_mgmt(struct wilc_vif *vif, bool enabled, u32 timeout)
 {
+	struct wilc *wilc = vif->wilc;
 	struct wid wid;
 	int result;
 	s8 power_mode;
@@ -1927,6 +1928,8 @@ int wilc_set_power_mgmt(struct wilc_vif *vif, bool
enabled, u32 timeout)
 	result = wilc_send_config_pkt(vif, WILC_SET_CFG, &wid, 1);
 	if (result)
 		netdev_err(vif->ndev, "Failed to send power management\n");
+	else
+		wilc->power_save_mode = enabled;
 
 	return result;
 }
diff --git a/drivers/net/wireless/microchip/wilc1000/netdev.h
b/drivers/net/wireless/microchip/wilc1000/netdev.h
index 152408232d51..db149abc5d0d 100644
--- a/drivers/net/wireless/microchip/wilc1000/netdev.h
+++ b/drivers/net/wireless/microchip/wilc1000/netdev.h
@@ -267,6 +267,7 @@ struct wilc {
 
 	int clients_count;
 	struct workqueue_struct *hif_workqueue;
+	bool power_save_mode;
 	enum chip_ps_states chip_ps_state;
 	struct wilc_cfg cfg;
 	void *bus_data;
diff --git a/drivers/net/wireless/microchip/wilc1000/wlan.c
b/drivers/net/wireless/microchip/wilc1000/wlan.c
index ddd382996275..0e0e325d396e 100644
--- a/drivers/net/wireless/microchip/wilc1000/wlan.c
+++ b/drivers/net/wireless/microchip/wilc1000/wlan.c
@@ -18,13 +18,13 @@ static inline bool is_wilc1000(u32 id)
 static inline void acquire_bus(struct wilc *wilc, enum bus_acquire acquire)
 {
 	mutex_lock(&wilc->hif_cs);
-	if (acquire == WILC_BUS_ACQUIRE_AND_WAKEUP)
+	if (acquire == WILC_BUS_ACQUIRE_AND_WAKEUP && wilc->power_save_mode)
 		chip_wakeup(wilc);
 }
 
 static inline void release_bus(struct wilc *wilc, enum bus_release release)
 {
-	if (release == WILC_BUS_RELEASE_ALLOW_SLEEP)
+	if (release == WILC_BUS_RELEASE_ALLOW_SLEEP && wilc->power_save_mode)
 		chip_allow_sleep(wilc);
 	mutex_unlock(&wilc->hif_cs);
 }

Re: RFC: wilc1000 module parameter to disable chip sleep

[David Mosberger-Tang]

On Thu, 2021-12-09 at 11:15 -0700, David Mosberger-Tang wrote:

> > Did you test by enabling the power-save mode with "wpa_supplicant" or 
> > using "iw" command. For power consumption measurement, please try by 
> > disabling the PSM mode.
> 
> No, I have not played with power-saving mode.  There are some disconcerting
> messages when turning PSM on:
> 
> [ 1764.070375] wilc1000_spi spi1.0: Failed cmd, cmd (ca), resp (00)
> [ 1764.076403] wilc1000_spi spi1.0: Failed cmd, read reg (000013f4)...

As far as I can see, chip_wakeup() can trigger this legitimately:

		do {
			h->hif_read_reg(wilc, WILC_SPI_WAKEUP_REG, &reg);
			h->hif_write_reg(wilc, WILC_SPI_WAKEUP_REG,
					 reg | WILC_SPI_WAKEUP_BIT);
			h->hif_write_reg(wilc, WILC_SPI_WAKEUP_REG,
					 reg & ~WILC_SPI_WAKEUP_BIT);

			do {
				usleep_range(2000, 2500);
				wilc_get_chipid(wilc, true);
			} while (wilc_get_chipid(wilc, true) == 0);
		} while (wilc_get_chipid(wilc, true) == 0);

Actually, the above looks rather gross.  wilc_get_chip() reads both WILC_CHIPID
and WILC_RF_REVISION_ID and we do this at least three times in a row on each
chip_wakeup().  Wow.  Is this really necessary?

In any case, for now, the below supresses the error messages:

diff --git a/drivers/net/wireless/microchip/wilc1000/spi.c b/drivers/net/wireless/microchip/wilc1000/spi.c
index b778284247f7..516787aa4a23 100644
--- a/drivers/net/wireless/microchip/wilc1000/spi.c
+++ b/drivers/net/wireless/microchip/wilc1000/spi.c
@@ -498,7 +498,7 @@ static int wilc_spi_single_read(struct wilc *wilc, u8 cmd, u32 adr, void *b,
 	r = (struct wilc_spi_rsp_data *)&rb[cmd_len];
 	if (r->rsp_cmd_type != cmd) {
 		if (!spi_priv->probing_crc)
-			dev_err(&spi->dev,
+			dev_dbg(&spi->dev,
 				"Failed cmd, cmd (%02x), resp (%02x)\n",
 				cmd, r->rsp_cmd_type);
 		return -EINVAL;
@@ -754,7 +754,8 @@ static int wilc_spi_read_reg(struct wilc *wilc, u32 addr, u32 *data)
 
 	result = wilc_spi_single_read(wilc, cmd, addr, data, clockless);
 	if (result) {
-		dev_err(&spi->dev, "Failed cmd, read reg (%08x)...\n", addr);
+		/* Register reads may fail legitimately, e.g., during chip_wakeup(). */
+		dev_dbg(&spi->dev, "Failed cmd, read reg (%08x)...\n", addr);
 		return result;
 	}
 

Maybe a parameter should be added to hif_read_reg() to indicate whether failure is an option?

  --david

Re: RFC: wilc1000 module parameter to disable chip sleep

[David Mosberger-Tang]

On Thu, 2021-12-09 at 12:12 -0700, David Mosberger-Tang wrote:
> On Thu, 2021-12-09 at 11:15 -0700, David Mosberger-Tang wrote:
> 
> > > Did you test by enabling the power-save mode with "wpa_supplicant" or 
> > > using "iw" command. For power consumption measurement, please try by 
> > > disabling the PSM mode.
> > 
> > No, I have not played with power-saving mode.  There are some disconcerting
> > messages when turning PSM on:
> > 
> > [ 1764.070375] wilc1000_spi spi1.0: Failed cmd, cmd (ca), resp (00)
> > [ 1764.076403] wilc1000_spi spi1.0: Failed cmd, read reg (000013f4)...
> 
> As far as I can see, chip_wakeup() can trigger this legitimately:
> 
> 		do {
> 			h->hif_read_reg(wilc, WILC_SPI_WAKEUP_REG, &reg);
> 			h->hif_write_reg(wilc, WILC_SPI_WAKEUP_REG,
> 					 reg | WILC_SPI_WAKEUP_BIT);
> 			h->hif_write_reg(wilc, WILC_SPI_WAKEUP_REG,
> 					 reg & ~WILC_SPI_WAKEUP_BIT);
> 
> 			do {
> 				usleep_range(2000, 2500);
> 				wilc_get_chipid(wilc, true);
> 			} while (wilc_get_chipid(wilc, true) == 0);
> 		} while (wilc_get_chipid(wilc, true) == 0);
> 
> Actually, the above looks rather gross.  wilc_get_chip() reads both WILC_CHIPID
> and WILC_RF_REVISION_ID and we do this at least three times in a row on each
> chip_wakeup().  Wow.  Is this really necessary?

Looks like I'm on to something.  If I replace the gross code with:

		h->hif_read_reg(wilc, WILC_SPI_WAKEUP_REG, &reg);
		h->hif_write_reg(wilc, WILC_SPI_WAKEUP_REG, reg | WILC_SPI_WAKEUP_BIT);
		h->hif_write_reg(wilc, WILC_SPI_WAKEUP_REG, reg & ~WILC_SPI_WAKEUP_BIT);

		while (1) {
			if (wilc->hif_func->hif_read_reg(wilc, WILC_CHIPID, &chipid) == 0)
				break;
			usleep_range(2000, 2500);
		}

Look what happens to TX throughput:

[  4]   0.00-120.00 sec   142 MBytes  9.92 Mbits/sec    6             sender

This is with power_save mode turned on.  Almost exactly 3 times faster than the
3.33 Mbits/sec I was seeing before.

  --david

Re: RFC: wilc1000 module parameter to disable chip sleep

[David Mosberger-Tang]

I took linux-wireless off the CC list...

On Thu, 2021-12-09 at 12:28 -0700, David Mosberger-Tang wrote:
> On Thu, 2021-12-09 at 12:12 -0700, David Mosberger-Tang wrote:
> > On Thu, 2021-12-09 at 11:15 -0700, David Mosberger-Tang wrote:
> > 
> > As far as I can see, chip_wakeup() can trigger this legitimately:
> > 
> > 		do {
> > 			h->hif_read_reg(wilc, WILC_SPI_WAKEUP_REG, &reg);
> > 			h->hif_write_reg(wilc, WILC_SPI_WAKEUP_REG,
> > 					 reg | WILC_SPI_WAKEUP_BIT);
> > 			h->hif_write_reg(wilc, WILC_SPI_WAKEUP_REG,
> > 					 reg & ~WILC_SPI_WAKEUP_BIT);
> > 
> > 			do {
> > 				usleep_range(2000, 2500);
> > 				wilc_get_chipid(wilc, true);
> > 			} while (wilc_get_chipid(wilc, true) == 0);
> > 		} while (wilc_get_chipid(wilc, true) == 0);
> > 
> > Actually, the above looks rather gross.  wilc_get_chip() reads both WILC_CHIPID
> > and WILC_RF_REVISION_ID and we do this at least three times in a row on each
> > chip_wakeup().  Wow.  Is this really necessary?
> 
> Looks like I'm on to something.  If I replace the gross code with:
> 
> 		h->hif_read_reg(wilc, WILC_SPI_WAKEUP_REG, &reg);
> 		h->hif_write_reg(wilc, WILC_SPI_WAKEUP_REG, reg | WILC_SPI_WAKEUP_BIT);
> 		h->hif_write_reg(wilc, WILC_SPI_WAKEUP_REG, reg & ~WILC_SPI_WAKEUP_BIT);
> 
> 		while (1) {
> 			if (wilc->hif_func->hif_read_reg(wilc, WILC_CHIPID, &chipid) == 0)
> 				break;
> 			usleep_range(2000, 2500);
> 		}
> 
> Look what happens to TX throughput:
> 
> [  4]   0.00-120.00 sec   142 MBytes  9.92 Mbits/sec    6             sender
> 
> This is with power_save mode turned on.  Almost exactly 3 times faster than the
> 3.33 Mbits/sec I was seeing before.

Over 120 seconds of iperf3, a histogram of the number of WILC_CHIPID reads
required to get a successful read looked like this:

[  493.918785] hist[  0]=70417
[  493.921609] hist[  1]=0
[  493.923997] hist[  2]=0
[  493.926424] hist[  3]=0
[  493.928957] hist[  4]=0
[  493.931359] hist[  5]=0
[  493.933781] hist[  6]=0
[  493.936210] hist[  7]=0
[  493.938702] hist[  8]=0
[  493.941097] hist[  9]=0
[  493.943523] hist[ 10]=0
[  493.945951] hist[ 11]=0
[  493.948418] hist[ 12]=0
[  493.950812] hist[ 13]=0
[  493.953238] hist[ 14]=0
[  493.955667] hist[ 15]=0
[  493.958126] hist[ 16]=0
[  493.960527] hist[ 17]=0
[  493.962954] hist[ 18]=1
[  493.965382] hist[ 19]=7
[  493.967840] hist[ 20]=1
[  493.970242] hist[ 21]=13

Based on this, I changed the above code to:

		while (1) {
			h->hif_read_reg(wilc, WILC_SPI_WAKEUP_REG, &reg);
			h->hif_write_reg(wilc, WILC_SPI_WAKEUP_REG,
					 reg | WILC_SPI_WAKEUP_BIT);
			h->hif_write_reg(wilc, WILC_SPI_WAKEUP_REG,
					 reg & ~WILC_SPI_WAKEUP_BIT);

			if (wilc->hif_func->hif_read_reg(wilc, WILC_CHIPID, &chipid) == 0)
				break;
			usleep_range(2000, 2500);
		}

This gets me:

   TX/PSM off: [  4]   0.00-120.00 sec   198 MBytes  13.8 Mbits/sec    9             sender
   TX/PSM on : [  4]   0.00-120.00 sec   140 MBytes  9.78 Mbits/sec    9             sender
   RX/PSM off: [  5]   0.00-120.10 sec   304 MBytes  21.2 Mbits/sec                  receiver
   RX/PSM on : [  5]   0.00-120.11 sec   288 MBytes  20.1 Mbits/sec                  receive

Ajay, I'm guessing your kernel is either configured for tickless timer or
HZ=1000?  That would explain why you'd see higher throughput with the original
code.  My system is configured for HZ=100, so the usleep_range() would typically
take 10ms.

Any objections to the latest code?

  --david

Re: RFC: wilc1000 module parameter to disable chip sleep

[Ajay.Kathat]

On 09/12/21 23:45, David Mosberger-Tang wrote:
> EXTERNAL EMAIL: Do not click links or open attachments unless you know the content is safe
>
> [Sorry, my first email was accidentally had the patch appended as a MIME
>   attachment.]
>
> On Thu, 2021-12-09 at 09:20 +0000, Ajay.Kathat@microchip.com wrote:
>> On 09/12/21 00:20, David Mosberger-Tang wrote:
>> The "chip_wakeup" & "chip_allow_sleep" API's are required to configure
>> the wake-up registers in wilc. These registers must be configured
>> correctly when the power save mode is enabled.
> I see.
>
>>> Here is what I see: on a system configured for minimum power consumption
>>> (all unnecessary daemons disabled, Ethernet unplugged) I measured 1,180 mW
>>> when the WILC chip is in RESET (the ENABLE pin is always high on our
>>> platform).
>>>
>>> With the wilc1000-spi/wilc1000 modules loaded and the WILC chip
>>> running but without being associated with a WLAN network, measured
>>> power consumption was 1,460 mW, regardless of whether chip sleep was
>>> enabled or disabled.
>> Did you test by enabling the power-save mode with "wpa_supplicant" or
>> using "iw" command. For power consumption measurement, please try by
>> disabling the PSM mode.
> No, I have not played with power-saving mode.  There are some disconcerting
> messages when turning PSM on:
>
> [ 1764.070375] wilc1000_spi spi1.0: Failed cmd, cmd (ca), resp (00)
> [ 1764.076403] wilc1000_spi spi1.0: Failed cmd, read reg (000013f4)...
>
> The driver does still work, but occasionally, I get long streams of these
> messages, sometimes it gets to the point where there are so many that the
> watchdog timer ends up rebooting the system.
>
>> The chip-sleep code is needed to configure the registers properly for
>> wilc and not using these sequence would have impact on sending the data
>> to wilc, especially when the PS mode is enabled.
> How about something along the patch below then?


Thanks.


The changes looks okay to me.


> With this patch, I see the following iperf3 performance (120 second average):
>
> PSM on:
> [  4]   0.00-120.00 sec  47.6 MBytes  3.33 Mbits/sec    0             sender
>
> PSM off:
> [  4]   0.00-120.00 sec   201 MBytes  14.0 Mbits/sec   12             sender
>
> In terms of power consumption:
>
>     baseline                : 1.2 W
>     PSM on, idle            : 1.2 W
>     PSM on, TX @ 3.33 Mbps  : 1.7 W
>     PSM off, idle           : 1.5 W
>     PSM off, TX @ 14.0 Mbps : 2.4 W
>
>    --david
>
> diff --git a/drivers/net/wireless/microchip/wilc1000/hif.c
> b/drivers/net/wireless/microchip/wilc1000/hif.c
> index 44e93cd5e3df..09aa5ced19d3 100644
> --- a/drivers/net/wireless/microchip/wilc1000/hif.c
> +++ b/drivers/net/wireless/microchip/wilc1000/hif.c
> @@ -1912,6 +1912,7 @@ int wilc_edit_station(struct wilc_vif *vif, const u8 *mac,
>
>   int wilc_set_power_mgmt(struct wilc_vif *vif, bool enabled, u32 timeout)
>   {
> +       struct wilc *wilc = vif->wilc;
>          struct wid wid;
>          int result;
>          s8 power_mode;
> @@ -1927,6 +1928,8 @@ int wilc_set_power_mgmt(struct wilc_vif *vif, bool
> enabled, u32 timeout)
>          result = wilc_send_config_pkt(vif, WILC_SET_CFG, &wid, 1);
>          if (result)
>                  netdev_err(vif->ndev, "Failed to send power management\n");
> +       else
> +               wilc->power_save_mode = enabled;
>
>          return result;
>   }
> diff --git a/drivers/net/wireless/microchip/wilc1000/netdev.h
> b/drivers/net/wireless/microchip/wilc1000/netdev.h
> index 152408232d51..db149abc5d0d 100644
> --- a/drivers/net/wireless/microchip/wilc1000/netdev.h
> +++ b/drivers/net/wireless/microchip/wilc1000/netdev.h
> @@ -267,6 +267,7 @@ struct wilc {
>
>          int clients_count;
>          struct workqueue_struct *hif_workqueue;
> +       bool power_save_mode;
>          enum chip_ps_states chip_ps_state;
>          struct wilc_cfg cfg;
>          void *bus_data;
> diff --git a/drivers/net/wireless/microchip/wilc1000/wlan.c
> b/drivers/net/wireless/microchip/wilc1000/wlan.c
> index ddd382996275..0e0e325d396e 100644
> --- a/drivers/net/wireless/microchip/wilc1000/wlan.c
> +++ b/drivers/net/wireless/microchip/wilc1000/wlan.c
> @@ -18,13 +18,13 @@ static inline bool is_wilc1000(u32 id)
>   static inline void acquire_bus(struct wilc *wilc, enum bus_acquire acquire)
>   {
>          mutex_lock(&wilc->hif_cs);
> -       if (acquire == WILC_BUS_ACQUIRE_AND_WAKEUP)
> +       if (acquire == WILC_BUS_ACQUIRE_AND_WAKEUP && wilc->power_save_mode)
>                  chip_wakeup(wilc);
>   }
>
>   static inline void release_bus(struct wilc *wilc, enum bus_release release)
>   {
> -       if (release == WILC_BUS_RELEASE_ALLOW_SLEEP)
> +       if (release == WILC_BUS_RELEASE_ALLOW_SLEEP && wilc->power_save_mode)
>                  chip_allow_sleep(wilc);
>          mutex_unlock(&wilc->hif_cs);
>   }
>

Re: RFC: wilc1000 module parameter to disable chip sleep

[Ajay.Kathat]

On 10/12/21 00:42, David Mosberger-Tang wrote:
> EXTERNAL EMAIL: Do not click links or open attachments unless you know the content is safe
>
> On Thu, 2021-12-09 at 11:15 -0700, David Mosberger-Tang wrote:
>
>>> Did you test by enabling the power-save mode with "wpa_supplicant" or
>>> using "iw" command. For power consumption measurement, please try by
>>> disabling the PSM mode.
>> No, I have not played with power-saving mode.  There are some disconcerting
>> messages when turning PSM on:
>>
>> [ 1764.070375] wilc1000_spi spi1.0: Failed cmd, cmd (ca), resp (00)
>> [ 1764.076403] wilc1000_spi spi1.0: Failed cmd, read reg (000013f4)...
> As far as I can see, chip_wakeup() can trigger this legitimately:
>
>                  do {
>                          h->hif_read_reg(wilc, WILC_SPI_WAKEUP_REG, &reg);
>                          h->hif_write_reg(wilc, WILC_SPI_WAKEUP_REG,
>                                           reg | WILC_SPI_WAKEUP_BIT);
>                          h->hif_write_reg(wilc, WILC_SPI_WAKEUP_REG,
>                                           reg & ~WILC_SPI_WAKEUP_BIT);
>
>                          do {
>                                  usleep_range(2000, 2500);
>                                  wilc_get_chipid(wilc, true);
>                          } while (wilc_get_chipid(wilc, true) == 0);
>                  } while (wilc_get_chipid(wilc, true) == 0);
>
> Actually, the above looks rather gross.  wilc_get_chip() reads both WILC_CHIPID
> and WILC_RF_REVISION_ID and we do this at least three times in a row on each
> chip_wakeup().  Wow.  Is this really necessary?


I believe you are using the old driver code so please check with latest 
code. 'chip_wakeup()' was changed recently so I don't think 
'wilc_get_chipid()' call is valid anymore inside this API.


https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/drivers/net/wireless/microchip/wilc1000?h=v5.15&id=5bb9de8bcb18c38ea089a287b77944ef8ee71abd


> In any case, for now, the below supresses the error messages:
>
> diff --git a/drivers/net/wireless/microchip/wilc1000/spi.c b/drivers/net/wireless/microchip/wilc1000/spi.c
> index b778284247f7..516787aa4a23 100644
> --- a/drivers/net/wireless/microchip/wilc1000/spi.c
> +++ b/drivers/net/wireless/microchip/wilc1000/spi.c
> @@ -498,7 +498,7 @@ static int wilc_spi_single_read(struct wilc *wilc, u8 cmd, u32 adr, void *b,
>          r = (struct wilc_spi_rsp_data *)&rb[cmd_len];
>          if (r->rsp_cmd_type != cmd) {
>                  if (!spi_priv->probing_crc)
> -                       dev_err(&spi->dev,
> +                       dev_dbg(&spi->dev,
>                                  "Failed cmd, cmd (%02x), resp (%02x)\n",
>                                  cmd, r->rsp_cmd_type);
>                  return -EINVAL;
> @@ -754,7 +754,8 @@ static int wilc_spi_read_reg(struct wilc *wilc, u32 addr, u32 *data)
>
>          result = wilc_spi_single_read(wilc, cmd, addr, data, clockless);
>          if (result) {
> -               dev_err(&spi->dev, "Failed cmd, read reg (%08x)...\n", addr);
> +               /* Register reads may fail legitimately, e.g., during chip_wakeup(). */
> +               dev_dbg(&spi->dev, "Failed cmd, read reg (%08x)...\n", addr);
>                  return result;
>          }
>
>
> Maybe a parameter should be added to hif_read_reg() to indicate whether failure is an option?


I have not observed the failure log specifically during 'chip_wakeup' 
but if you see them often then we can add the information in comments.


Regards,

Ajay

Re: RFC: wilc1000 module parameter to disable chip sleep

[Ajay.Kathat]

On 10/12/21 01:38, David Mosberger-Tang wrote:
> EXTERNAL EMAIL: Do not click links or open attachments unless you know the content is safe
>
> I took linux-wireless off the CC list...
>
> On Thu, 2021-12-09 at 12:28 -0700, David Mosberger-Tang wrote:
>> On Thu, 2021-12-09 at 12:12 -0700, David Mosberger-Tang wrote:
>>> On Thu, 2021-12-09 at 11:15 -0700, David Mosberger-Tang wrote:
>>>
>>> As far as I can see, chip_wakeup() can trigger this legitimately:
>>>
>>>              do {
>>>                      h->hif_read_reg(wilc, WILC_SPI_WAKEUP_REG, &reg);
>>>                      h->hif_write_reg(wilc, WILC_SPI_WAKEUP_REG,
>>>                                       reg | WILC_SPI_WAKEUP_BIT);
>>>                      h->hif_write_reg(wilc, WILC_SPI_WAKEUP_REG,
>>>                                       reg & ~WILC_SPI_WAKEUP_BIT);
>>>
>>>                      do {
>>>                              usleep_range(2000, 2500);
>>>                              wilc_get_chipid(wilc, true);
>>>                      } while (wilc_get_chipid(wilc, true) == 0);
>>>              } while (wilc_get_chipid(wilc, true) == 0);
>>>
>>> Actually, the above looks rather gross.  wilc_get_chip() reads both WILC_CHIPID
>>> and WILC_RF_REVISION_ID and we do this at least three times in a row on each
>>> chip_wakeup().  Wow.  Is this really necessary?
>> Looks like I'm on to something.  If I replace the gross code with:
>>
>>                h->hif_read_reg(wilc, WILC_SPI_WAKEUP_REG, &reg);
>>                h->hif_write_reg(wilc, WILC_SPI_WAKEUP_REG, reg | WILC_SPI_WAKEUP_BIT);
>>                h->hif_write_reg(wilc, WILC_SPI_WAKEUP_REG, reg & ~WILC_SPI_WAKEUP_BIT);
>>
>>                while (1) {
>>                        if (wilc->hif_func->hif_read_reg(wilc, WILC_CHIPID, &chipid) == 0)
>>                                break;
>>                        usleep_range(2000, 2500);
>>                }
>>
>> Look what happens to TX throughput:
>>
>> [  4]   0.00-120.00 sec   142 MBytes  9.92 Mbits/sec    6             sender
>>
>> This is with power_save mode turned on.  Almost exactly 3 times faster than the
>> 3.33 Mbits/sec I was seeing before.
> Over 120 seconds of iperf3, a histogram of the number of WILC_CHIPID reads
> required to get a successful read looked like this:
>
> [  493.918785] hist[  0]=70417
> [  493.921609] hist[  1]=0
> [  493.923997] hist[  2]=0
> [  493.926424] hist[  3]=0
> [  493.928957] hist[  4]=0
> [  493.931359] hist[  5]=0
> [  493.933781] hist[  6]=0
> [  493.936210] hist[  7]=0
> [  493.938702] hist[  8]=0
> [  493.941097] hist[  9]=0
> [  493.943523] hist[ 10]=0
> [  493.945951] hist[ 11]=0
> [  493.948418] hist[ 12]=0
> [  493.950812] hist[ 13]=0
> [  493.953238] hist[ 14]=0
> [  493.955667] hist[ 15]=0
> [  493.958126] hist[ 16]=0
> [  493.960527] hist[ 17]=0
> [  493.962954] hist[ 18]=1
> [  493.965382] hist[ 19]=7
> [  493.967840] hist[ 20]=1
> [  493.970242] hist[ 21]=13
>
> Based on this, I changed the above code to:
>
>                  while (1) {
>                          h->hif_read_reg(wilc, WILC_SPI_WAKEUP_REG, &reg);
>                          h->hif_write_reg(wilc, WILC_SPI_WAKEUP_REG,
>                                           reg | WILC_SPI_WAKEUP_BIT);
>                          h->hif_write_reg(wilc, WILC_SPI_WAKEUP_REG,
>                                           reg & ~WILC_SPI_WAKEUP_BIT);
>
>                          if (wilc->hif_func->hif_read_reg(wilc, WILC_CHIPID, &chipid) == 0)
>                                  break;
>                          usleep_range(2000, 2500);
>                  }
>
> This gets me:
>
>     TX/PSM off: [  4]   0.00-120.00 sec   198 MBytes  13.8 Mbits/sec    9             sender
>     TX/PSM on : [  4]   0.00-120.00 sec   140 MBytes  9.78 Mbits/sec    9             sender
>     RX/PSM off: [  5]   0.00-120.10 sec   304 MBytes  21.2 Mbits/sec                  receiver
>     RX/PSM on : [  5]   0.00-120.11 sec   288 MBytes  20.1 Mbits/sec                  receive
>
> Ajay, I'm guessing your kernel is either configured for tickless timer or
> HZ=1000?  That would explain why you'd see higher throughput with the original
> code.  My system is configured for HZ=100, so the usleep_range() would typically
> take 10ms.

I think the issue may not be related to the HZ configuration because the 
"usleep_range" API may have a delay of the same magnitude.Btw I too have 
CONFIG_HZ=100 configured for my setup. I overlooked that the throughput 
number for ttcp was in Bytes/sec whereas iPerf specified in (bits/sec) 
so it looks like the numbers are in same range.


>
> Any objections to the latest code?


The above modification are not required because the API is already 
changed but it would be good to have the other patch which uses 
"power_save_mode" flag to avoid calling of chip-sleep code.


Regards,

Ajay

Re: RFC: wilc1000 module parameter to disable chip sleep

[David Mosberger-Tang]

On Fri, 2021-12-10 at 09:05 +0000, Ajay.Kathat@microchip.com wrote:
> On 10/12/21 00:42, David Mosberger-Tang wrote:
> > EXTERNAL EMAIL: Do not click links or open attachments unless you know the content is safe
> > 
> > On Thu, 2021-12-09 at 11:15 -0700, David Mosberger-Tang wrote:
> > 
> > > > Did you test by enabling the power-save mode with "wpa_supplicant" or
> > > > using "iw" command. For power consumption measurement, please try by
> > > > disabling the PSM mode.
> > > No, I have not played with power-saving mode.  There are some disconcerting
> > > messages when turning PSM on:
> > > 
> > > [ 1764.070375] wilc1000_spi spi1.0: Failed cmd, cmd (ca), resp (00)
> > > [ 1764.076403] wilc1000_spi spi1.0: Failed cmd, read reg (000013f4)...
> > As far as I can see, chip_wakeup() can trigger this legitimately:
> > 
> >                  do {
> >                          h->hif_read_reg(wilc, WILC_SPI_WAKEUP_REG, &reg);
> >                          h->hif_write_reg(wilc, WILC_SPI_WAKEUP_REG,
> >                                           reg | WILC_SPI_WAKEUP_BIT);
> >                          h->hif_write_reg(wilc, WILC_SPI_WAKEUP_REG,
> >                                           reg & ~WILC_SPI_WAKEUP_BIT);
> > 
> >                          do {
> >                                  usleep_range(2000, 2500);
> >                                  wilc_get_chipid(wilc, true);
> >                          } while (wilc_get_chipid(wilc, true) == 0);
> >                  } while (wilc_get_chipid(wilc, true) == 0);
> > 
> > Actually, the above looks rather gross.  wilc_get_chip() reads both WILC_CHIPID
> > and WILC_RF_REVISION_ID and we do this at least three times in a row on each
> > chip_wakeup().  Wow.  Is this really necessary?
> 
> I believe you are using the old driver code so please check with latest 
> code. 'chip_wakeup()' was changed recently so I don't think 
> 'wilc_get_chipid()' call is valid anymore inside this API.
> 
> 
> https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/drivers/net/wireless/microchip/wilc1000?h=v5.15&id=5bb9de8bcb18c38ea089a287b77944ef8ee71abd

Indeed I was.  I switched to 5.15 recently but thought I had backported all
patches, but I was missing a handful.  Yes, the new code is much better, thanks!

> > In any case, for now, the below supresses the error messages:
> > 
> > diff --git a/drivers/net/wireless/microchip/wilc1000/spi.c b/drivers/net/wireless/microchip/wilc1000/spi.c
> > index b778284247f7..516787aa4a23 100644
> > --- a/drivers/net/wireless/microchip/wilc1000/spi.c
> > +++ b/drivers/net/wireless/microchip/wilc1000/spi.c
> > @@ -498,7 +498,7 @@ static int wilc_spi_single_read(struct wilc *wilc, u8 cmd, u32 adr, void *b,
> >          r = (struct wilc_spi_rsp_data *)&rb[cmd_len];
> >          if (r->rsp_cmd_type != cmd) {
> >                  if (!spi_priv->probing_crc)
> > -                       dev_err(&spi->dev,
> > +                       dev_dbg(&spi->dev,
> >                                  "Failed cmd, cmd (%02x), resp (%02x)\n",
> >                                  cmd, r->rsp_cmd_type);
> >                  return -EINVAL;
> > @@ -754,7 +754,8 @@ static int wilc_spi_read_reg(struct wilc *wilc, u32 addr, u32 *data)
> > 
> >          result = wilc_spi_single_read(wilc, cmd, addr, data, clockless);
> >          if (result) {
> > -               dev_err(&spi->dev, "Failed cmd, read reg (%08x)...\n", addr);
> > +               /* Register reads may fail legitimately, e.g., during chip_wakeup(). */
> > +               dev_dbg(&spi->dev, "Failed cmd, read reg (%08x)...\n", addr);
> >                  return result;
> >          }
> > 
> > 
> > Maybe a parameter should be added to hif_read_reg() to indicate whether failure is an option?
> 
> I have not observed the failure log specifically during 'chip_wakeup' 
> but if you see them often then we can add the information in comments.

My tree was missing the clockless register fixes as well so perhaps that's what
caused these.  It seems to be good now.

This is actually starting to look quite good!  Here is the current iperf3
throughput I'm getting:

PSM off:
[  4]   0.00-120.00 sec   137 MBytes  9.60 Mbits/sec    7             sender
[  5]   0.00-120.03 sec   281 MBytes  19.6 Mbits/sec                  receiver

PSM on:
[  4]   0.00-120.01 sec   140 MBytes  9.82 Mbits/sec    9             sender
[  5]   0.00-120.69 sec   283 MBytes  19.6 Mbits/sec                  receiver

I'll submit a patch to skip wakeup/allow_sleep if power-save mode is off.

The only remaining issue I'm seeing is that if I turn on power-save mode right
after starting wpa_supplicant, the driver thinks that PSM is on, but power
consumption indicates that it is not actually on (using about 1.5W of power).
When it's in this state, I have to manually use iw to turn PSM off and then on
again to get actual power-savings (power dropping to about 1.1W).

  --david