Suspend takes 4 sec +

[Victor Tuson Palau]

Suspends takes about 4 sec while resume is instant.

>click on power menu and click on suspend
>system suspends
>power button click to resume

[Ming Lei (tom-leiming)]

Looks no such problem when testing suspend with 'pm-suspend' utility, see below log:

[ 1082.043991] PM: Syncing filesystems ... done.
[ 1082.049538] PM: Preparing system for mem sleep
[ 1082.049607] Tegra emc suspend: enabled bridge.emc
[ 1082.049619] Tegra cpufreq suspend: setting frequency to 475000 kHz
[ 1082.051762] Freezing user space processes ... (elapsed 0.01 seconds) done.
[ 1082.071804] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
[ 1082.091686] PM: Entering mem sleep
[ 1082.091719] reg-dummy reg-dummy: preparing suspend
[ 1082.091743] serial8250 serial8250: preparing suspend
[ 1082.091767] platform grouper_misc: preparing suspend
[ 1082.091783] tegra-i2c tegra-i2c.4: preparing suspend
[ 1082.091800] tegra-i2c tegra-i2c.3: preparing suspend
[ 1082.091816] tegra-i2c tegra-i2c.2: preparing suspend
[ 1082.091832] tegra-i2c tegra-i2c.1: preparing suspend
[ 1082.091848] tegra-i2c tegra-i2c.0: preparing suspend
[ 1082.091864] spi_tegra spi_tegra.3: preparing suspend
[ 1082.091880] spi_tegra spi_tegra.0: preparing suspend
[ 1082.091897] tegra-otg tegra-otg: preparing suspend
[ 1082.091913] tegra-ehci tegra-ehci.1: preparing suspend
[ 1082.091930] platform fiq_debugger.0: preparing suspend
[ 1082.091946] tegra_uart tegra_uart.1: preparing suspend
[ 1082.091962] tegra_uart tegra_uart.2: preparing suspend
[ 1082.091978] tegra_uart tegra_uart.3: preparing suspend
[ 1082.091994] tegra_uart tegra_uart.4: preparing suspend
[ 1082.092010] arm-pmu arm-pmu.0: preparing suspend
[ 1082.092026] platform tegra_rtc: preparing suspend
[ 1082.092043] fsl-tegra-udc fsl-tegra-udc: preparing suspend
[ 1082.092060] tegra_smmu tegra_smmu: preparing suspend
[ 1082.092077] tegra_wdt tegra_wdt: preparing suspend
[ 1082.092093] tegra_camera tegra_camera: preparing suspend
[ 1082.092110] tegra-se tegra-se: preparing suspend
[ 1082.092126] tegra30-ahub tegra30-ahub: preparing suspend
[ 1082.092143] tegra30-dam tegra30-dam.0: preparing suspend
[ 1082.092160] tegra30-dam tegra30-dam.1: preparing suspend
[ 1082.092176] tegra30-dam tegra30-dam.2: preparing suspend
[ 1082.092192] tegra30-i2s tegra30-i2s.1: preparing suspend
[ 1082.092209] tegra30-i2s tegra30-i2s.3: preparing suspend
[ 1082.092225] tegra30-i2s tegra30-i2s.4: preparing suspend
[ 1082.092242] tegra30-spdif tegra30-spdif: preparing suspend
[ 1082.092259] spdif-dit spdif-dit.0: preparing suspend
[ 1082.092276] spdif-dit spdif-dit.1: preparing suspend
[ 1082.092292] bcm4330_rfkill bcm4330_rfkill: preparing suspend
[ 1082.092309] tegra-pcm-audio tegra-pcm-audio: preparing suspend
[ 1082.092327] tegra-snd-rt5640 tegra-snd-rt5640.0: preparing suspend
[ 1082.092345] leds-gpio leds-gpio: preparing suspend
[ 1082.092361] platform tegra30-hda: preparing suspend
[ 1082.092377] ram_console ram_console: preparing suspend
[ 1082.092393] sdhci-tegra sdhci-tegra.3: preparing suspend
[ 1082.092410] sdhci-tegra sdhci-tegra.2: preparing suspend
[ 1082.092427] bcmdhd_wlan bcmdhd_wlan.1: preparing suspend
[ 1082.092445] gpio-keys gpio-keys.0: preparing suspend, may wakeup
[ 1082.092463] host1x host1x: preparing suspend
[ 1082.092479] tegra-nvmap tegra-nvmap: preparing suspend
[ 1082.092496] tegra_pwm teg...

[Ming Lei (tom-leiming)]

And the extra time should be consumed by 'powering off wifi' things, see below:

[ 275.512553] cfg80211: Calling CRDA to update world regulatory domain
[ 275.514615] wl_android_wifi_off in
[ 275.514909] Wake32 for irq=340
[ 275.514918] Disabling wake32
[ 275.514925] gpio bank wake found: wake32 for irq=67
[ 275.514931] Disabling wake32
[ 275.515098] net_ratelimit: 11 callbacks suppressed
[ 275.515111] wifi_set_power = 0
[ 275.515123] Powering off wifi
[ 275.818298] =========== WLAN placed in RESET ========
[ 275.840425] cfg80211: World regulatory domain updated:
[ 275.840526] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[ 275.840565] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[ 275.840594] cfg80211: (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
[ 275.840623] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
[ 275.840652] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[ 275.840680] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[ 275.842306] dhd_prot_ioctl : bus is down. we have nothing to do
[ 275.842364] wlan0: set cur_etheraddr failed
[ 275.854003]
[ 275.854044] Dongle Host Driver, version 5.90.195.75
[ 275.854054] Compiled in drivers/net/wireless/bcmdhd on Nov 13 2012 at 17:14:24
[ 275.854115] wl_android_wifi_on in
[ 275.854158] wifi_set_power = 1
[ 275.854189] Powering on wifi
[ 276.155260] =========== WLAN going back to live ========
[ 276.155318] sdio_reset_comm():
[ 276.167559] F1 signature read @0x18000000=0x16044330
[ 276.178352] DHD: dongle ram size is set to 294912(orig 294912)
[ 276.246068] dhdsdio_write_vars: Download, Upload and compare of NVRAM succeeded.
[ 276.373672] Wake32 for irq=340
[ 276.373728] Enabling wake32
[ 276.373772] gpio bank wake found: wake32 for irq=67
[ 276.373805] Enabling wake32
[ 276.374311] wifi_get_mac_addr
[ 276.377651] Firmware up: op_mode=1, Broadcom Dongle Host Driver mac=30:85:a9:4d:80:69
[ 277.170858] wl_android_wifi_off in
[ 277.179690] Wake32 for irq=340
[ 277.179739] Disabling wake32
[ 277.179770] gpio bank wake found: wake32 for irq=67
[ 277.179790] Disabling wake32
[ 277.182003] Powering off wifi
[ 277.487750] =========== WLAN placed in RESET ========
[ 278.337609] device: 'vcs63': device_add
[ 278.337828] PM: Adding info for No Bus:vcs63
[ 278.337895] device: 'vcsa63': device_add
[ 278.338014] PM: Adding info for No Bus:vcsa63
[ 278.985972] PM: Syncing filesystems ... done.

[Ming Lei (tom-leiming)]

The problem should be related with network-manager, and not sure why nm wants to
bring up the interface again after receiving the dbus pm suspend message.

Before suspending via menu item of 'suspend', stopping network-manager service may workaround
the problem.

[Ming Lei (tom-leiming)]

The extra interface down/up is that wifi ether address is to be restored to initialized address during sleep, see below
call path in network-manager:

real_hw_take_down/real_hw_take_up
 <-_set_hw_addr (self, priv->initial_hw_addr, "reset");
  <-real_deactivate() /*wifi*/
   <-nm_device_deactivate
    <-nm_device_take_down
     <-nm_device_state_changed
      <-nm_device_set_managed
       <-do_sleep_wake
        <-_internal_sleep
         <-_internal_sleep
          <-upower_sleeping_cb

So considered that the open/close cycle of wifi interface may take long time, maybe nm should be optimized
for the situation(don't do it if ether address isn't changed) or just remove the resetting address for n7.

[Ming Lei (tom-leiming)]

The root cause is that current broadcom wifi driver may change its mac address after downloading firmware, so
the initialized mac address is always different with the working address, which caused the network-manger
behaviour.

In theory, disabling ENABLE_INSMOD_NO_FW_LOAD may fix the problem, but cause another resume failure
problem, so still not solution for the problem now.

[Steve Langasek (vorlon)]

It looks to me like this may be something we want to investigate further from the NM side?

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.