From abd1947c43cc49cae2caa4cef248f83ee3fd9c54 Mon Sep 17 00:00:00 2001 From: Alan Chen Date: Fri, 30 Aug 2019 12:07:03 -0700 Subject: [PATCH] qcacld-3.0: Add timing profiling log for runtime PM operations Add timing profiling log for runtime PM operations such that we can know how much time each operation is taking. Change-Id: Iad2aca8e8bb2f0dadc14d24e3a5c2b03938df9df CRs-Fixed: 2518935 --- .../pmo/core/src/wlan_pmo_suspend_resume.c | 23 +++++++++++++++++-- core/hdd/inc/wlan_hdd_main.h | 3 +++ core/hdd/src/wlan_hdd_driver_ops.c | 16 ++++++++++++- 3 files changed, 39 insertions(+), 3 deletions(-) diff --git a/components/pmo/core/src/wlan_pmo_suspend_resume.c b/components/pmo/core/src/wlan_pmo_suspend_resume.c index 5ec1ce2fc80e..f4ae85980763 100644 --- a/components/pmo/core/src/wlan_pmo_suspend_resume.c +++ b/components/pmo/core/src/wlan_pmo_suspend_resume.c @@ -903,6 +903,7 @@ QDF_STATUS pmo_core_psoc_bus_suspend_req(struct wlan_objmgr_psoc *psoc, struct pmo_psoc_priv_obj *psoc_ctx; QDF_STATUS status; bool wow_mode_selected = false; + qdf_time_t begin, end; pmo_enter(); if (!psoc) { @@ -928,10 +929,13 @@ QDF_STATUS pmo_core_psoc_bus_suspend_req(struct wlan_objmgr_psoc *psoc, wow_mode_selected = pmo_core_is_wow_enabled(psoc_ctx); pmo_debug("wow mode selected %d", wow_mode_selected); + begin = qdf_get_system_timestamp(); if (wow_mode_selected) status = pmo_core_enable_wow_in_fw(psoc, psoc_ctx, wow_params); else status = pmo_core_psoc_suspend_target(psoc, 0); + end = qdf_get_system_timestamp(); + pmo_debug("fw took total time %lu ms to enable wow", end - begin); pmo_psoc_put_ref(psoc); out: @@ -951,6 +955,7 @@ QDF_STATUS pmo_core_psoc_bus_runtime_suspend(struct wlan_objmgr_psoc *psoc, QDF_STATUS status; int ret; struct pmo_wow_enable_params wow_params = {0}; + qdf_time_t begin, end; pmo_enter(); @@ -1016,7 +1021,12 @@ QDF_STATUS pmo_core_psoc_bus_runtime_suspend(struct wlan_objmgr_psoc *psoc, } if (pld_cb) { + begin = qdf_get_system_timestamp(); ret = pld_cb(); + end = qdf_get_system_timestamp(); + pmo_debug("runtime pci bus suspend took total time %lu ms", + end - begin); + if (ret) { status = qdf_status_from_os_return(ret); goto resume_hif; @@ -1063,11 +1073,13 @@ out: QDF_STATUS pmo_core_psoc_bus_runtime_resume(struct wlan_objmgr_psoc *psoc, pmo_pld_auto_resume_cb pld_cb) { + int ret; void *hif_ctx; void *dp_soc; void *txrx_pdev; void *htc_ctx; QDF_STATUS status; + qdf_time_t begin, end; pmo_enter(); @@ -1095,9 +1107,12 @@ QDF_STATUS pmo_core_psoc_bus_runtime_resume(struct wlan_objmgr_psoc *psoc, } hif_pre_runtime_resume(hif_ctx); - if (pld_cb) { - if (pld_cb()) { + begin = qdf_get_system_timestamp(); + ret = pld_cb(); + end = qdf_get_system_timestamp(); + pmo_debug("pci bus resume took total time %lu ms", end - begin); + if (ret) { status = QDF_STATUS_E_FAILURE; goto fail; } @@ -1270,6 +1285,7 @@ QDF_STATUS pmo_core_psoc_bus_resume_req(struct wlan_objmgr_psoc *psoc, struct pmo_psoc_priv_obj *psoc_ctx; bool wow_mode; QDF_STATUS status; + qdf_time_t begin, end; pmo_enter(); if (!psoc) { @@ -1296,10 +1312,13 @@ QDF_STATUS pmo_core_psoc_bus_resume_req(struct wlan_objmgr_psoc *psoc, goto out; } + begin = qdf_get_system_timestamp(); if (wow_mode) status = pmo_core_psoc_disable_wow_in_fw(psoc, psoc_ctx); else status = pmo_core_psoc_resume_target(psoc, psoc_ctx); + end = qdf_get_system_timestamp(); + pmo_debug("fw took total time %lu ms to disable wow", end - begin); pmo_psoc_put_ref(psoc); diff --git a/core/hdd/inc/wlan_hdd_main.h b/core/hdd/inc/wlan_hdd_main.h index b2a5137faaa3..5ea4501c95be 100644 --- a/core/hdd/inc/wlan_hdd_main.h +++ b/core/hdd/inc/wlan_hdd_main.h @@ -1959,6 +1959,9 @@ struct hdd_context { unsigned long derived_intf_addr_mask; struct sar_limit_cmd_params *sar_cmd_params; + + qdf_time_t runtime_resume_start_time_stamp; + qdf_time_t runtime_suspend_done_time_stamp; }; /** diff --git a/core/hdd/src/wlan_hdd_driver_ops.c b/core/hdd/src/wlan_hdd_driver_ops.c index 59785d744dd0..a88f27c718bf 100644 --- a/core/hdd/src/wlan_hdd_driver_ops.c +++ b/core/hdd/src/wlan_hdd_driver_ops.c @@ -1299,6 +1299,7 @@ static int wlan_hdd_runtime_suspend(struct device *dev) int err; QDF_STATUS status; struct hdd_context *hdd_ctx; + qdf_time_t delta; hdd_debug("Starting runtime suspend"); @@ -1322,7 +1323,14 @@ static int wlan_hdd_runtime_suspend(struct device *dev) hdd_pld_runtime_suspend_cb); err = qdf_status_to_os_return(status); - hdd_debug("Runtime suspend done result: %d", err); + hdd_ctx->runtime_suspend_done_time_stamp = qdf_get_system_timestamp(); + delta = hdd_ctx->runtime_suspend_done_time_stamp - + hdd_ctx->runtime_resume_start_time_stamp; + + if (hdd_ctx->runtime_suspend_done_time_stamp > + hdd_ctx->runtime_resume_start_time_stamp) + hdd_debug("Runtime suspend done result: %d total cxpc up time %lu ms", + err, delta); return err; } @@ -1356,8 +1364,14 @@ static int wlan_hdd_runtime_resume(struct device *dev) { struct hdd_context *hdd_ctx = cds_get_context(QDF_MODULE_ID_HDD); QDF_STATUS status; + qdf_time_t delta; hdd_debug("Starting runtime resume"); + hdd_ctx->runtime_resume_start_time_stamp = qdf_get_system_timestamp(); + delta = hdd_ctx->runtime_resume_start_time_stamp - + hdd_ctx->runtime_suspend_done_time_stamp; + hdd_debug("Starting runtime resume total cxpc down time %lu ms", + delta); if (wlan_hdd_validate_context(hdd_ctx)) return 0;