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 <[email protected]>

Author: MarekPorwisz

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
 **********************
 

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

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,13 +985,25 @@ 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);
 
 		if (err >= 0) {
 			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;
 

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.