WiFi打开慢

上一节我们分析了driver以上的Wi-Fi打开流程，这一节我们拿一个问题练练手实战一下。

概述：
Wi-Fi打开在界面上看是一个很简答的动作，但实际上这是一个非常复杂的过程，设计到AIDL、HIDL、netlink、socket、cgf80211等多种通信机制，也包含了软件、硬件的启动过程，在整个流程当中，使用了各种线程同步、锁等原子操作，如果某一个状态或者动作卡住，将会影响整个启动流程。

问题背景：
1.wifi开关打开比对比机器慢；

问题分析：

在了解了Wi-Fi打开流程之后（还记得上一节wifi打开流程的梳理吧，如果忘记了在复盘一下，看看wifi打开各个阶段都会打印一些什么信息），我们基于wifi log初步解析下问题原因：

//测试机花费1.49s

//1.49s
01-12 16:57:12.508 1000 2317 5859 I WifiService: setWifiEnabled package=com.android.settings uid=1000 enable=true isPrivileged=true
//启动wpa_supplicnat 1.34
01-12 16:57:13.840 root 1 1 I init : … started service ‘wpa_supplicant’ has pid 30392
01-12 16:57:13.921 wifi 30392 30392 I wpa_supplicant: Successfully initialized wpa_supplicant
01-12 16:57:14.001 1000 2317 2317 I MiuiWifiHalHandler: received wifi state change: 3
01-12 16:57:14.002 1000 2317 5859 I WifiService: startScan uid=1000

//对比机花费0.31s

//0.31s
01-12 16:57:12.449 1000 2703 4914 I WifiService: setWifiEnabled package=com.android.settings uid=1000 enable=true isPrivileged=true
01-12 16:57:12.528 wifi 9929 9929 I wpa_supplicant: Successfully initialized wpa_supplicant
01-12 16:57:12.577 1000 2703 3204 D WifiClientModeImpl[94738046:wlan0]: entering ConnectableState: ifaceName = wlan0

01-12 16:57:12.579 1000 2703 2703 I MiuiWifiHalHandler: received wifi state change: 3
01-12 16:57:12.580 1000 2703 9723 I WifiService: startScan uid=1000

基于以上的日志可以看到测试机确认花费时间久一点，接下来结合代码梳理整体流程，并且在关键的部位上打上关键的日志，wifi打开最关键的一部分如下截图：

小编在这里几个关键部分添加了自己的debug日志，再来看一下debug日志的打印：

//测试机

// wifi开始开启
02-01 09:47:34.533 1000 2176 7533 I WifiService: setWifiEnabled package=com.android.settings uid=1000 enable=true isPrivileged=true
02-01 09:47:34.535 1000 2176 3722 E WifiClientModeManager: anjs debug start wifi cmd_start
02-01 09:47:34.543 1000 2176 3722 E HalDevMgr: anjs getChipIds=[0]
02-01 09:47:34.546 1000 2176 3722 I WifiVendorHal: Vendor Hal started successfully
02-01 09:47:34.547 1000 2176 3722 D HalDevMgr: anjs createIface: createIfaceType=0, requiredChipCapabilities=0, requestorWs=WorkSource{1000 com.android.settings}
//创建网口
02-01 09:47:35.446 1000 2176 3722 D HalDevMgr: createIfaceIfPossible: added cacheEntry={name=wlan0, type=0, destroyedListeners.size()=1, RequestorWs=WorkSource{1000 com.android.settings}, creationTime=211152}
02-01 09:47:35.448 1000 2176 3722 D WifiNl80211Manager: Setting up interface for client mode: wlan0
02-01 09:47:35.566 1000 2176 3722 E WifiNative: anjs Successfully switched to connectivity mode on iface=Iface:{Name=wlan0,Id=4,Type=STA_CONNECTIVITY}
// wifi打开
02-01 09:47:35.592 1000 2176 2176 I MiuiWifiHalHandler: received wifi state change: 3

基于以上日志来看，耗时主要是发生在createStaIface上边，这里主要是一些驱动的操作，代码梳理放到下文，我们先看驱动的打印：

02-01 09:47:34.569 wifi 4125 4125 I [binder][0xf8fb517b][01:47:34.550797] qca6750: [4125:I:HDD] wlan_hdd_state_ctrl_param_write: Wifi Turning On from UI
02-01 09:47:34.569 wifi 4125 4125 I [binder][0xf8fb51ee][01:47:34.550803] qca6750: [4125:I:HDD] wlan_hdd_state_ctrl_param_write: is_driver_loaded 1 is_driver_recovering 0
02-01 09:47:34.569 wifi 4125 4125 I [binder][0xf8fb52c3][01:47:34.550814] qca6750: [4125:I:HDD] wlan_hdd_validate_modules_state: Modules not enabled, Present status: 2
09:47:34.553720 [kworke][0xf8fb9fea][01:47:34.551843]qca6750: [266:D:HDD] hdd_wlan_start_modules: enter
09:47:35.423050 [kworke][0xf9fa8310][01:47:35.421858]qca6750: [266:D:HDD] Wlan transitioned (now ENABLED)
09:47:35.423052 [kworke][0xf9fa8350][01:47:35.421862]qca6750: [266:D:HDD] hdd_wlan_start_modules: exit

驱动启动耗时1s多。

代码梳理：

1.framework层对于createStaIface都是调调调

packages/modules/Wifi/service/java/com/android/server/wifi/hal/WifiChipHidlImpl.java
158 public WifiStaIface createStaIface() {
159 String methodStr = “createStaIface”;
160 return validateAndCall(methodStr, null,
161 () -> createStaIfaceInternal(methodStr));
162 }

689 private WifiStaIface createStaIfaceInternal(String methodStr) {
690 Mutable ifaceResp = new Mutable<>();
691 try {
692 mWifiChip.createStaIface((status, iface) -> {
693 if (isOk(status, methodStr)) {
694 ifaceResp.value = new WifiStaIface(iface, mContext, mSsidTranslator);
695 }
696 });
697 } catch (RemoteException e) {
698 handleRemoteException(e, methodStr);
699 }
700 return ifaceResp.value;
701 }

2.这里使用了AIDL机制，create virtualInterface接口

hardware/interfaces/wifi/aidl/default/wifi_chip.cpp
1172 std::pair<std::shared_ptr, ndk::ScopedAStatus> WifiChip::createStaIfaceInternal() {
1173 if (!canCurrentModeSupportConcurrencyTypeWithCurrentTypes(IfaceConcurrencyType::STA)) {
1174 return {nullptr, createWifiStatus(WifiStatusCode::ERROR_NOT_AVAILABLE)};
1175 }
1176 std::string ifname = allocateStaIfaceName();
1177 legacy_hal::wifi_error legacy_status = legacy_hal_.lock()->createVirtualInterface(
1178 ifname, aidl_struct_util::convertAidlIfaceTypeToLegacy(IfaceType::STA));
1179 if (legacy_status != legacy_hal::WIFI_SUCCESS) {
1180 LOG(ERROR) << "Failed to add interface: " << ifname << " "
1181 << legacyErrorToString(legacy_status);
1182 return {nullptr, createWifiStatusFromLegacyError(legacy_status)};
1183 }
1184 std::shared_ptr iface = WifiStaIface::create(ifname, legacy_hal_, iface_util_);
1185 sta_ifaces_.push_back(iface);
1186 for (const auto& callback : event_cb_handler_.getCallbacks()) {
1187 if (!callback->onIfaceAdded(IfaceType::STA, ifname).isOk()) {
1188 LOG(ERROR) << “Failed to invoke onIfaceAdded callback”;
1189 }
1190 }
1191 setActiveWlanIfaceNameProperty(getFirstActiveWlanIfaceName());
1192 return {iface, ndk::ScopedAStatus::ok()};
1193 }

hardware/interfaces/wifi/aidl/default/wifi_legacy_hal.cpp
1700 wifi_error WifiLegacyHal::createVirtualInterface(const std::string& ifname,
1701 wifi_interface_type iftype) {
1702 // Create the interface if it doesn’t exist. If interface already exist,
1703 // Vendor Hal should return WIFI_SUCCESS.
1704 wifi_error status = global_func_table_.wifi_virtual_interface_create(global_handle_,
1705 ifname.c_str(), iftype);
1706 return handleVirtualInterfaceCreateOrDeleteStatus(ifname, status);
1707 }

1700 wifi_error WifiLegacyHal::createVirtualInterface(const std::string& ifname,
1701 wifi_interface_type iftype) {
1702 // Create the interface if it doesn’t exist. If interface already exist,
1703 // Vendor Hal should return WIFI_SUCCESS.
1704 wifi_error status = global_func_table_.wifi_virtual_interface_create(global_handle_,
1705 ifname.c_str(), iftype);
1706 return handleVirtualInterfaceCreateOrDeleteStatus(ifname, status);
1707 }

3.发送NL80211_CMD_NEW_INTERFACE消息给kernel

1328 wifi_error wifi_virtual_interface_create(wifi_handle handle,
1329 const char* ifname,
1330 wifi_interface_type iface_type)
1331 {
1332 wifi_error ret;
1333 WiFiConfigCommand *wifiConfigCommand;
1334 hal_info info = getHalInfo(handle);
1335 if (!info || info->num_interfaces < 1) {
1336 ALOGE(“%s: Error wifi_handle NULL or base wlan interface not present”, FUNCTION);
1337 return WIFI_ERROR_UNKNOWN;
1338 }
1339
1340 // Already exists and set interface mode only
1341 if (if_nametoindex(ifname) != 0) {
1342 return wifi_set_interface_mode(handle, ifname, iface_type);
1343 }
1344
1345 ALOGD(“%s: ifname=%s create”, FUNCTION, ifname);
1346
1347 wifiConfigCommand = new WiFiConfigCommand(handle, get_requestid(), 0, 0);
1348 if (wifiConfigCommand == NULL) {
1349 ALOGE(“%s: Error wifiConfigCommand NULL”, FUNCTION);
1350 return WIFI_ERROR_UNKNOWN;
1351 }
1352
1353 nl80211_iftype type;
1354 switch(iface_type) {
1355 case WIFI_INTERFACE_TYPE_STA: / IfaceType:STA /
1356 type = NL80211_IFTYPE_STATION;
1357 break;
1358 case WIFI_INTERFACE_TYPE_AP: / IfaceType:AP /
1359 type = NL80211_IFTYPE_AP;
1360 break;
1361 case WIFI_INTERFACE_TYPE_P2P: / IfaceType:P2P /
1362 type = NL80211_IFTYPE_P2P_DEVICE;
1363 break;
1364 case WIFI_INTERFACE_TYPE_NAN: / IfaceType:NAN */
1365 type = NL80211_IFTYPE_NAN;
1366 break;
1367 default:
1368 ALOGE(“%s: Wrong interface type %u”, FUNCTION, iface_type);
1369 ret = WIFI_ERROR_UNKNOWN;
1370 goto done;
1371 break;
1372 }
1373 wifiConfigCommand->create_generic(NL80211_CMD_NEW_INTERFACE);

kernel_platform/common-gki/net/wireless/nl80211.c
16501 {
16502 .cmd = NL80211_CMD_NEW_INTERFACE,
16503 .validate = GENL_DONT_VALIDATE_STRICT | GENL_DONT_VALIDATE_DUMP,
16504 .doit = nl80211_new_interface,
16505 .flags = GENL_UNS_ADMIN_PERM,
16506 .internal_flags =
16507 IFLAGS(NL80211_FLAG_NEED_WIPHY |
16508 NL80211_FLAG_NEED_RTNL |
16509 /* we take the wiphy mutex later ourselves */
16510 NL80211_FLAG_NO_WIPHY_MTX),
16511 },

4.这里用到了nl80211消息处理知识点

kernel_platform/common-gki/net/wireless/nl80211.c
4211 static int _nl80211_new_interface(struct sk_buff *skb, struct genl_info *info)
4212 {
4213 struct cfg80211_registered_device *rdev = info->user_ptr[0];
4214 struct vif_params params;
4215 struct wireless_dev *wdev;
4216 struct sk_buff *msg;
4217 int err;
4218 enum nl80211_iftype type = NL80211_IFTYPE_UNSPECIFIED;
4219
4220 memset(&params, 0, sizeof(params));
4221
4222 if (!info->attrs[NL80211_ATTR_IFNAME])
4223 return -EINVAL;
4224
4225 if (info->attrs[NL80211_ATTR_IFTYPE])
4226 type = nla_get_u32(info->attrs[NL80211_ATTR_IFTYPE]);
4227
4228 if (!rdev->ops->add_virtual_intf)
4229 return -EOPNOTSUPP;
4230
4231 if ((type == NL80211_IFTYPE_P2P_DEVICE || type == NL80211_IFTYPE_NAN ||
4232 rdev->wiphy.features & NL80211_FEATURE_MAC_ON_CREATE) &&
4233 info->attrs[NL80211_ATTR_MAC]) {
4234 nla_memcpy(params.macaddr, info->attrs[NL80211_ATTR_MAC],
4235 ETH_ALEN);
4236 if (!is_valid_ether_addr(params.macaddr))
4237 return -EADDRNOTAVAIL;
4238 }
4239
4240 if (info->attrs[NL80211_ATTR_4ADDR]) {
4241 params.use_4addr = !!nla_get_u8(info->attrs[NL80211_ATTR_4ADDR]);
4242 err = nl80211_valid_4addr(rdev, NULL, params.use_4addr, type);
4243 if (err)
4244 return err;
4245 }
4246
4247 if (!cfg80211_iftype_allowed(&rdev->wiphy, type, params.use_4addr, 0))
4248 return -EOPNOTSUPP;
4249
4250 err = nl80211_parse_mon_options(rdev, type, info, &params);
4251 if (err < 0)
4252 return err;
4253
4254 msg = nlmsg_new(NLMSG_DEFAULT_SIZE, GFP_KERNEL);
4255 if (!msg)
4256 return -ENOMEM;
4257
4258 wdev = rdev_add_virtual_intf(rdev,
4259 nla_data(info->attrs[NL80211_ATTR_IFNAME]),
4260 NET_NAME_USER, type, &params);

kernel_platform/common-gki/net/mac80211/cfg.c
4871 const struct cfg80211_ops mac80211_config_ops = {
4872 .add_virtual_intf = ieee80211_add_iface,

172 static struct wireless_dev *ieee80211_add_iface(struct wiphy *wiphy,
173 const char *name,
174 unsigned char name_assign_type,
175 enum nl80211_iftype type,
176 struct vif_params *params)
177 {
178 struct ieee80211_local *local = wiphy_priv(wiphy);
179 struct wireless_dev *wdev;
180 struct ieee80211_sub_if_data *sdata;
181 int err;
182
183 err = ieee80211_if_add(local, name, name_assign_type, &wdev, type, params);
184 if (err)
185 return ERR_PTR(err);
186
187 sdata = IEEE80211_WDEV_TO_SUB_IF(wdev);
188
189 if (type == NL80211_IFTYPE_MONITOR) {
190 err = ieee80211_set_mon_options(sdata, params);
191 if (err) {
192 ieee80211_if_remove(sdata);
193 return NULL;
194 }
195 }
196
197 return wdev;
198 }

kernel_platform/common-gki/net/mac80211/iface.c
2091 int ieee80211_if_add(struct ieee80211_local *local, const char *name,
2092 unsigned char name_assign_type,
2093 struct wireless_dev **new_wdev, enum nl80211_iftype type,
2094 struct vif_params *params)
2095 {
2096 struct net_device *ndev = NULL;
2097 struct ieee80211_sub_if_data *sdata = NULL;
2098 struct txq_info *txqi;
2099 void (*if_setup)(struct net_device *dev);
2100 int ret, i;
2101 int txqs = 1;
2102
2103 ASSERT_RTNL();
2104
2105 if (type == NL80211_IFTYPE_P2P_DEVICE || type == NL80211_IFTYPE_NAN) {
2106 struct wireless_dev *wdev;
2107
2108 sdata = kzalloc(sizeof(*sdata) + local->hw.vif_data_size,
2109 GFP_KERNEL);
2110 if (!sdata)
2111 return -ENOMEM;
2112 wdev = &sdata->wdev;
2113
2114 sdata->dev = NULL;
2115 strscpy(sdata->name, name, IFNAMSIZ);
2116 ieee80211_assign_perm_addr(local, wdev->address, type);
2117 memcpy(sdata->vif.addr, wdev->address, ETH_ALEN);
2118 ether_addr_copy(sdata->vif.bss_conf.addr, sdata->vif.addr);
2119 } else {
2120 int size = ALIGN(sizeof(*sdata) + local->hw.vif_data_size,
2121 sizeof(void *));
2122 int txq_size = 0;
2123
2124 if (local->ops->wake_tx_queue &&
2125 type != NL80211_IFTYPE_AP_VLAN &&
2126 (type != NL80211_IFTYPE_MONITOR ||
2127 (params->flags & MONITOR_FLAG_ACTIVE)))
2128 txq_size += sizeof(struct txq_info) +
2129 local->hw.txq_data_size;
2130
2131 if (local->ops->wake_tx_queue) {
2132 if_setup = ieee80211_if_setup_no_queue;
2133 } else {
2134 if_setup = ieee80211_if_setup;
2135 if (local->hw.queues >= IEEE80211_NUM_ACS)
2136 txqs = IEEE80211_NUM_ACS;
2137 }

1500 static void ieee80211_if_setup(struct net_device *dev)
1501 {
1502 ether_setup(dev);
1503 dev->priv_flags &= ~IFF_TX_SKB_SHARING;
1504 dev->netdev_ops = &ieee80211_dataif_ops;
1505 dev->needs_free_netdev = true;
1506 dev->priv_destructor = ieee80211_if_free;
1507 }

829 static const struct net_device_ops ieee80211_dataif_ops = {
830 .ndo_open = ieee80211_open,
831 .ndo_stop = ieee80211_stop,
832 .ndo_uninit = ieee80211_uninit,
833 .ndo_start_xmit = ieee80211_subif_start_xmit,
834 .ndo_set_rx_mode = ieee80211_set_multicast_list,
835 .ndo_set_mac_address = ieee80211_change_mac,
836 .ndo_select_queue = ieee80211_netdev_select_queue,
837 .ndo_get_stats64 = ieee80211_get_stats64,
838 };

vendor/qcom/opensource/wlan/qcacld-3.0/core/hdd/src/wlan_hdd_main.c
6829 static const struct net_device_ops wlan_drv_ops = {
6830 .ndo_open = hdd_open,
6831 .ndo_stop = hdd_stop,
6832 .ndo_uninit = hdd_uninit,
6833 .ndo_start_xmit = hdd_hard_start_xmit,
6834 .ndo_fix_features = hdd_fix_features,
6835 .ndo_set_features = hdd_set_features,
6836 .ndo_tx_timeout = hdd_tx_timeout,
6837 .ndo_get_stats = hdd_get_stats,
6838 #if LINUX_VERSION_CODE < KERNEL_VERSION(5, 15, 0)
6839 .ndo_do_ioctl = hdd_ioctl,
6840 #endif
6841 .ndo_set_mac_address = hdd_set_mac_address,
6842 .ndo_select_queue = hdd_select_queue,
6843 .ndo_set_rx_mode = hdd_set_multicast_list,
6844 #if LINUX_VERSION_CODE >= KERNEL_VERSION(5, 15, 0)
6845 .ndo_siocdevprivate = hdd_dev_private_ioctl,
6846 #endif
6847 #ifdef WLAN_FEATURE_OSRTP
6848 .ndo_bpf = hdd_bpf,
6849 .ndo_xsk_wakeup = hdd_xsk_wakeup,
6850 #endif
6851
6852 };

调用hdd_open,至此进入vendor driver空间

vendor/qcom/opensource/wlan/qcacld-3.0/core/hdd/src/wlan_hdd_main.c
5320 static int __hdd_open(struct net_device *dev)
14087 hdd_psoc_idle_timer_stop(hdd_ctx);
14088 if (hdd_ctx->driver_status == DRIVER_MODULES_ENABLED) {
14089 hdd_nofl_debug(“Driver modules already Enabled”);
14090 return 0;
14091 }

驱动启动流程涉及硬件的各种期间启动，驱动的各个服务启动，这里大部分是芯片厂商的内容，内部耗时的优化空间不大，还会涉及到一些系统调度的知识，debug到根本原因点比较费劲，这里小编先不阐述根本耗时点的说明，等后续知识体系为大家分享全面之后，在分享一边驱动耗时问题点定位的文章，这里先为大家提供一个更有效的修复方案：

//这里有一个计数器，试想如果可以保证这个状态跳过去，是不是wlan打开时间就可以缩短很多
13978 void hdd_psoc_idle_timer_stop(struct hdd_context *hdd_ctx)
13979 {
13980 qdf_delayed_work_stop_sync(&hdd_ctx->psoc_idle_timeout_work);
13981 hdd_allow_suspend(WIFI_POWER_EVENT_WAKELOCK_IFACE_CHANGE_TIMER);
13982 hdd_debug(“Stopped psoc idle timer”);
13983 }

13955 void hdd_psoc_idle_timer_start(struct hdd_context *hdd_ctx)
13957 uint32_t timeout_ms = hdd_ctx->config->iface_change_wait_time;
13974 qdf_delayed_work_start(&hdd_ctx->psoc_idle_timeout_work, timeout_ms);

可以看到这里有个计时器，他是可以通过驱动的ini配置文件配置的，其作用是修改driver IDLE & shutdown的时间间隔，达到在wifi频繁、快速启动的操作时，每次都要初始化一次driver完整流程的耗时方案。

iface_change_wait_time

小编在这里将默认值250调整到了10000，看一下效果：

//修改ini之后，wifi开启流程缩减到了300ms左右

02-01 09:51:05.633 1000 2176 5239 I WifiService: setWifiEnabled package=com.android.settings uid=1000 enable=true isPrivileged=true
02-01 09:51:05.653 1000 2176 3722 I WifiVendorHal: Vendor Hal started successfully
02-01 09:51:05.682 1000 2176 3722 D HalDevMgr: createIfaceIfPossible: added cacheEntry={name=wlan0, type=0, destroyedListeners.size()=1, RequestorWs=WorkSource{1000 com.android.settings}, creationTime=421388}
02-01 09:51:05.694 1000 2176 3722 I WifiNative: Successfully setup Iface:{Name=wlan0,Id=13,Type=STA_SCAN}
02-01 09:51:06.011 1000 2176 3722 E WifiNative: anjs Successfully switched to connectivity mode on iface=Iface:{Name=wlan0,Id=13,Type=STA_CONNECTIVITY}
02-01 09:51:06.056 1000 2176 2176 I MiuiWifiHalHandler: received wifi state change: 3

//驱动日志，跳过了初始化阶段（Driver modules already Enabled）

18:15:56.522809 [binder][0x6598f3b8c][10:15:56.521901]qca6750: [1519:I:HDD] wlan_hdd_state_ctrl_param_write: Wifi Turning On from UI
18:15:56.522819 [binder][0x6598f3c15][10:15:56.521908]qca6750: [1519:I:HDD] wlan_hdd_state_ctrl_param_write: is_driver_loaded 1 is_driver_recovering 0
18:15:56.522824 [binder][0x6598f3c94][10:15:56.521915]qca6750: [1519:D:HDD] hdd_psoc_idle_timer_stop: Stopped psoc idle timer
18:15:56.526360 [binder][0x6598f9dc8][10:15:56.523211]qca6750: [1519:D:HDD] hdd_psoc_idle_timer_stop: Stopped psoc idle timer
18:15:56.526365 [binder][0x6598f9ddf][10:15:56.523212]qca6750: [1519:D:HDD] Driver modules already Enabled

至此，整理问题分析以及修改方案陈述完成。大家还需要考虑一下修改这个值之后对于整机的功耗有没有影响，因为修改这个配置之后会影响wlan驱动的休眠，从而影响整机系统的休眠。

如果读到这里，你觉得有所收获，也可以关注下小编的公众号（无线技术栈），未来一起进步~
发布于 2024-02-04 12:26・IP 属地北京