From ecd058779c787287d9d8d9c0cf92c1f001f0eadc Mon Sep 17 00:00:00 2001 From: Marek Porwisz Date: Thu, 13 Nov 2025 11:22:38 +0100 Subject: [PATCH] rpc: Add possibility to measure command execution time Added measuring the command execution time. The time is printed as an INFO log level after the command is complete. Signed-off-by: Marek Porwisz --- nrf_rpc/CHANGELOG.rst | 10 ++++++++++ nrf_rpc/Kconfig | 7 +++++++ nrf_rpc/nrf_rpc.c | 13 +++++++++++++ nrf_rpc/template/nrf_rpc_os_tmpl.h | 6 ++++++ 4 files changed, 36 insertions(+) diff --git a/nrf_rpc/CHANGELOG.rst b/nrf_rpc/CHANGELOG.rst index ac68946eea..f15e5bbaf1 100644 --- a/nrf_rpc/CHANGELOG.rst +++ b/nrf_rpc/CHANGELOG.rst @@ -9,6 +9,16 @@ Changelog All the notable changes to this project are documented on this page. +nRF Connect SDK v3.1.99 +*********************** + +Added +===== + +* Added the possibility to measure command execution time. + You can enable this feature with the :kconfig:option:`CONFIG_NRF_RPC_COMMAND_TIME_MEASURE` Kconfig option. + You must also implement the :c:func:`nrf_rpc_os_timestamp_get_now` function, which returns the current timestamp expressed in milliseconds. + nRF Connect SDK v3.1.0 ********************** diff --git a/nrf_rpc/Kconfig b/nrf_rpc/Kconfig index 780d080368..b04123856f 100644 --- a/nrf_rpc/Kconfig +++ b/nrf_rpc/Kconfig @@ -70,4 +70,11 @@ config NRF_RPC_THREAD_POOL_SIZE the remote side. If there is no available threads then remote side will wait. +config NRF_RPC_COMMAND_TIME_MEASURE + bool "Measure command execution time" + help + Measure the time between sending the command and receiving the response + and log the value. Time measured includes the transmission and reception + time. Log level for the time measurement is CONFIG_NRF_RPC_LOG_LEVEL_INF. + endif # NRF_RPC diff --git a/nrf_rpc/nrf_rpc.c b/nrf_rpc/nrf_rpc.c index 7189eaa740..4759748a0d 100644 --- a/nrf_rpc/nrf_rpc.c +++ b/nrf_rpc/nrf_rpc.c @@ -944,6 +944,7 @@ int nrf_rpc_cmd_common(const struct nrf_rpc_group *group, uint32_t cmd, const uint8_t **rsp_packet = NULL; size_t *rsp_len = NULL; struct nrf_rpc_cmd_ctx *cmd_ctx; + uint64_t processing_time; NRF_RPC_ASSERT(group != NULL); NRF_RPC_ASSERT((cmd & 0xFF) != NRF_RPC_ID_UNKNOWN); @@ -984,6 +985,9 @@ int nrf_rpc_cmd_common(const struct nrf_rpc_group *group, uint32_t cmd, NRF_RPC_DBG("Sending command 0x%02X from group 0x%02X", cmd, group->data->src_group_id); + if(IS_ENABLED(CONFIG_NRF_RPC_COMMAND_TIME_MEASURE)) { + processing_time = nrf_rpc_os_timestamp_get_now(); + } err = send(group, full_packet, len + NRF_RPC_HEADER_SIZE); @@ -991,6 +995,15 @@ int nrf_rpc_cmd_common(const struct nrf_rpc_group *group, uint32_t cmd, err = wait_for_response(group, cmd_ctx, rsp_packet, rsp_len); } + if(IS_ENABLED(CONFIG_NRF_RPC_COMMAND_TIME_MEASURE)) { + processing_time = nrf_rpc_os_timestamp_get_now() - processing_time; + NRF_RPC_INF("Command 0x%02X from group 0x%02X execution time %llums", cmd, + group->data->src_group_id, processing_time); + } + else { + (void)processing_time; + } + cmd_ctx->handler = old_handler; cmd_ctx->handler_data = old_handler_data; diff --git a/nrf_rpc/template/nrf_rpc_os_tmpl.h b/nrf_rpc/template/nrf_rpc_os_tmpl.h index ba6ee67896..85dc389f8c 100644 --- a/nrf_rpc/template/nrf_rpc_os_tmpl.h +++ b/nrf_rpc/template/nrf_rpc_os_tmpl.h @@ -169,6 +169,12 @@ void* nrf_rpc_os_tls_get(void); */ void nrf_rpc_os_tls_set(void *data); +/** @brief Get the current timestamp value. + * + * @return Current timestamp in milliseconds. + */ +uint64_t nrf_rpc_os_timestamp_get_now(void); + /** @brief Reserve one context from command context pool. * * If there is no available context then this function waits for it.