From 08f0d93cbbeac7c26edcd25ca835296458397e60 Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Mon, 17 Dec 2018 10:43:58 +0100 Subject: [PATCH] shell: Improve handling of log messages If burst of log messages was passed to the shell log backend, it was likely that messages were lost because shell had no means to control arrivals of log messages. Added log message enqueueing timeout to the shell instance to allow blocking logger thread if short-term arrival rate exceeded shell capabilities. Added kconfig option for setting log message queue size and timeout in RTT and UART instances. Added section in shell documentation which explains interaction between the logger and shell instance acting as a logger backend. Signed-off-by: Krzysztof Chruscinski --- doc/subsystems/shell/shell.rst | 17 +++++++++++++++++ include/shell/shell.h | 17 +++++++++++------ include/shell/shell_log_backend.h | 19 ++++++++++++------- subsys/shell/Kconfig.backends | 14 ++++++++++++++ .../Kconfig.template.shell_log_queue_size | 10 ++++++++++ .../Kconfig.template.shell_log_queue_timeout | 10 ++++++++++ subsys/shell/shell_dummy.c | 2 +- subsys/shell/shell_log_backend.c | 10 ++++++---- subsys/shell/shell_rtt.c | 4 +++- subsys/shell/shell_uart.c | 4 +++- 10 files changed, 87 insertions(+), 20 deletions(-) create mode 100644 subsys/shell/Kconfig.template.shell_log_queue_size create mode 100644 subsys/shell/Kconfig.template.shell_log_queue_timeout diff --git a/doc/subsystems/shell/shell.rst b/doc/subsystems/shell/shell.rst index be626583cc5..d1e21565f6a 100644 --- a/doc/subsystems/shell/shell.rst +++ b/doc/subsystems/shell/shell.rst @@ -435,4 +435,21 @@ the shell will only print the subcommands registered for this command: params ping +Shell as the logger backend +*************************** +Shell instance can act as the :ref:`logger` backend. Shell ensures that log +messages are correctly multiplexed with shell output. Log messages from logger +thread are enqueued and processed in the shell thread. Logger thread will block +for configurable amount of time if queue is full, blocking logger thread context +for that time. Oldest log message is removed from the queue after timeout and +new message is enqueued. Use the ``shell stats show`` command to retrieve +number of log messages dropped by the shell instance. Log queue size and timeout +are :c:macro:`SHELL_DEFINE` arguments. + +.. warning:: + Enqueuing timeout must be set carefully when multiple backends are used + in the system. The shell instance could have a slow transport or could + block, for example, by a UART with hardware flow control. If timeout is + set too high, the logger thread could be blocked and impact other logger + backends. diff --git a/include/shell/shell.h b/include/shell/shell.h index d0c0dd5baf4..77769910545 100644 --- a/include/shell/shell.h +++ b/include/shell/shell.h @@ -452,18 +452,23 @@ extern void shell_print_stream(const void *user_ctx, const char *data, * * @param[in] _name Instance name. * @param[in] _prompt Shell prompt string. - * @param[in] transport_iface Pointer to the transport interface. - * @param[in] log_queue_size Logger processing queue size. + * @param[in] _transport_iface Pointer to the transport interface. + * @param[in] _log_queue_size Logger processing queue size. + * @param[in] _log_timeout Logger thread timeout in milliseconds on full + * log queue. If queue is full logger thread is + * blocked for given amount of time before log + * message is dropped. * @param[in] _shell_flag Shell output newline sequence. */ -#define SHELL_DEFINE(_name, _prompt, transport_iface, \ - log_queue_size, _shell_flag) \ +#define SHELL_DEFINE(_name, _prompt, _transport_iface, \ + _log_queue_size, _log_timeout, _shell_flag) \ static const struct shell _name; \ static struct shell_ctx UTIL_CAT(_name, _ctx); \ static char _name##prompt[CONFIG_SHELL_PROMPT_LENGTH + 1] = _prompt; \ static u8_t _name##_out_buffer[CONFIG_SHELL_PRINTF_BUFF_SIZE]; \ SHELL_LOG_BACKEND_DEFINE(_name, _name##_out_buffer, \ - CONFIG_SHELL_PRINTF_BUFF_SIZE); \ + CONFIG_SHELL_PRINTF_BUFF_SIZE, \ + _log_queue_size, _log_timeout); \ SHELL_HISTORY_DEFINE(_name, 128, 8);/*todo*/ \ SHELL_FPRINTF_DEFINE(_name##_fprintf, &_name, _name##_out_buffer, \ CONFIG_SHELL_PRINTF_BUFF_SIZE, \ @@ -474,7 +479,7 @@ extern void shell_print_stream(const void *user_ctx, const char *data, static struct k_thread _name##_thread; \ static const struct shell _name = { \ .prompt = _name##prompt, \ - .iface = transport_iface, \ + .iface = _transport_iface, \ .ctx = &UTIL_CAT(_name, _ctx), \ .history = SHELL_HISTORY_PTR(_name), \ .shell_flag = _shell_flag, \ diff --git a/include/shell/shell_log_backend.h b/include/shell/shell_log_backend.h index 5b35090630c..6be97d96a19 100644 --- a/include/shell/shell_log_backend.h +++ b/include/shell/shell_log_backend.h @@ -37,6 +37,7 @@ struct shell_log_backend { struct k_msgq *msgq; const struct log_output *log_output; struct shell_log_backend_control_block *control_block; + u32_t timeout; }; /** @brief Prototype of function outputing processed data. */ @@ -45,9 +46,12 @@ int shell_log_backend_output_func(u8_t *data, size_t length, void *ctx); /** @def SHELL_LOG_BACKEND_DEFINE * @brief Macro for creating instance of shell log backend. * - * @param _name Shell name. - * @param _buf Output buffer. - * @param _size Output buffer size. + * @param _name Shell name. + * @param _buf Output buffer. + * @param _size Output buffer size. + * @param _queue_size Log message queue size. + * @param _timeout Timeout in milliseconds for pending on queue full. + * Message is dropped on timeout. */ /** @def SHELL_LOG_BACKEND_PTR * @brief Macro for retrieving pointer to the instance of shell log backend. @@ -55,10 +59,10 @@ int shell_log_backend_output_func(u8_t *data, size_t length, void *ctx); * @param _name Shell name. */ #if CONFIG_LOG -#define SHELL_LOG_BACKEND_DEFINE(_name, _buf, _size) \ +#define SHELL_LOG_BACKEND_DEFINE(_name, _buf, _size, _queue_size, _timeout) \ LOG_BACKEND_DEFINE(_name##_backend, log_backend_shell_api, false); \ K_MSGQ_DEFINE(_name##_msgq, sizeof(void *), \ - CONFIG_SHELL_MAX_LOG_MSG_BUFFERED, sizeof(void *)); \ + _queue_size, sizeof(void *)); \ LOG_OUTPUT_DEFINE(_name##_log_output, shell_log_backend_output_func, \ _buf, _size); \ static struct shell_log_backend_control_block _name##_control_block; \ @@ -66,12 +70,13 @@ int shell_log_backend_output_func(u8_t *data, size_t length, void *ctx); .backend = &_name##_backend, \ .msgq = &_name##_msgq, \ .log_output = &_name##_log_output, \ - .control_block = &_name##_control_block \ + .control_block = &_name##_control_block, \ + .timeout = _timeout \ } #define SHELL_LOG_BACKEND_PTR(_name) (&_name##_log_backend) #else /* CONFIG_LOG */ -#define SHELL_LOG_BACKEND_DEFINE(_name, _buf, _size) /* empty */ +#define SHELL_LOG_BACKEND_DEFINE(_name, _buf, _size, _queue_size, _timeout) #define SHELL_LOG_BACKEND_PTR(_name) NULL #endif /* CONFIG_LOG */ diff --git a/subsys/shell/Kconfig.backends b/subsys/shell/Kconfig.backends index de8e3d2ba87..2702b620d5b 100644 --- a/subsys/shell/Kconfig.backends +++ b/subsys/shell/Kconfig.backends @@ -65,6 +65,13 @@ config SHELL_BACKEND_SERIAL_RX_POLL_PERIOD help Determines how often UART is polled for RX byte. +module = SHELL_BACKEND_SERIAL +default-timeout = 100 +source "subsys/shell/Kconfig.template.shell_log_queue_timeout" + +default-size = 10 +source "subsys/shell/Kconfig.template.shell_log_queue_size" + choice prompt "Initial log level limit" default SHELL_BACKEND_SERIAL_LOG_LEVEL_DEFAULT @@ -115,6 +122,13 @@ config SHELL_RTT_RX_POLL_PERIOD help Determines how often RTT is polled for RX byte. +module = SHELL_BACKEND_RTT +default-timeout = 100 +source "subsys/shell/Kconfig.template.shell_log_queue_timeout" + +default-size = 10 +source "subsys/shell/Kconfig.template.shell_log_queue_size" + choice prompt "Initial log level limit" default SHELL_RTT_INIT_LOG_LEVEL_DEFAULT diff --git a/subsys/shell/Kconfig.template.shell_log_queue_size b/subsys/shell/Kconfig.template.shell_log_queue_size new file mode 100644 index 00000000000..95adf7bd452 --- /dev/null +++ b/subsys/shell/Kconfig.template.shell_log_queue_size @@ -0,0 +1,10 @@ +config $(module)_LOG_MESSAGE_QUEUE_SIZE + int "Log message queue size" + default $(default-size) + help + Amount of messages that can enqueued in order to be processed by shell + thread. Too small queue may lead to logger thread being blocked + (see $(module)_LOG_MESSAGE_QUEUE_TIMEOUT). Too big queue on relatively + slow shell transport may lead to situation where logs are dropped + because all log messages are enqueued. + diff --git a/subsys/shell/Kconfig.template.shell_log_queue_timeout b/subsys/shell/Kconfig.template.shell_log_queue_timeout new file mode 100644 index 00000000000..69e09cb459a --- /dev/null +++ b/subsys/shell/Kconfig.template.shell_log_queue_timeout @@ -0,0 +1,10 @@ +config $(module)_LOG_MESSAGE_QUEUE_TIMEOUT + int "Log message drop timeout (in milliseconds)" + default $(default-timeout) + range -1 10000 + help + If queue with pending log messages is full, oldest log message is + dropped if queue is still full after requested time (-1 is forever). + Logger thread is blocked for that period, thus long timeout impacts + other logger backends and must be used with care. + diff --git a/subsys/shell/shell_dummy.c b/subsys/shell/shell_dummy.c index d6d01b4eeed..1424d95dc83 100644 --- a/subsys/shell/shell_dummy.c +++ b/subsys/shell/shell_dummy.c @@ -8,7 +8,7 @@ #include SHELL_DUMMY_DEFINE(shell_transport_dummy); -SHELL_DEFINE(shell_dummy, "~$ ", &shell_transport_dummy, 10, +SHELL_DEFINE(shell_dummy, "~$ ", &shell_transport_dummy, 1, 0, SHELL_FLAG_OLF_CRLF); static int init(const struct shell_transport *transport, diff --git a/subsys/shell/shell_log_backend.c b/subsys/shell/shell_log_backend.c index 8423852c667..69ca0300572 100644 --- a/subsys/shell/shell_log_backend.c +++ b/subsys/shell/shell_log_backend.c @@ -49,11 +49,13 @@ static void msg_to_fifo(const struct shell *shell, { int err; - err = k_msgq_put(shell->log_backend->msgq, &msg, K_NO_WAIT); + err = k_msgq_put(shell->log_backend->msgq, &msg, + shell->log_backend->timeout); switch (err) { case 0: break; + case -EAGAIN: case -ENOMSG: { struct log_msg *old_msg; @@ -71,9 +73,9 @@ static void msg_to_fifo(const struct shell *shell, err = k_msgq_put(shell->log_backend->msgq, &msg, K_NO_WAIT); if (err) { - /* Rather unusual sitaution as we just freed one element - * and there is no other context that puts into the - * mesq. */ + /* Unexpected case as we just freed one element and + * there is no other context that puts into the msgq. + */ __ASSERT_NO_MSG(0); } break; diff --git a/subsys/shell/shell_rtt.c b/subsys/shell/shell_rtt.c index 7be2eb3bc3f..1a371757481 100644 --- a/subsys/shell/shell_rtt.c +++ b/subsys/shell/shell_rtt.c @@ -10,7 +10,9 @@ #include SHELL_RTT_DEFINE(shell_transport_rtt); -SHELL_DEFINE(shell_rtt, "rtt:~$ ", &shell_transport_rtt, 10, +SHELL_DEFINE(shell_rtt, "rtt:~$ ", &shell_transport_rtt, + CONFIG_SHELL_BACKEND_RTT_LOG_MESSAGE_QUEUE_SIZE, + CONFIG_SHELL_BACKEND_RTT_LOG_MESSAGE_QUEUE_TIMEOUT, SHELL_FLAG_OLF_CRLF); LOG_MODULE_REGISTER(shell_rtt, CONFIG_SHELL_RTT_LOG_LEVEL); diff --git a/subsys/shell/shell_uart.c b/subsys/shell/shell_uart.c index 4e8840267ed..15e5f806966 100644 --- a/subsys/shell/shell_uart.c +++ b/subsys/shell/shell_uart.c @@ -21,7 +21,9 @@ LOG_MODULE_REGISTER(shell_uart); SHELL_UART_DEFINE(shell_transport_uart, CONFIG_SHELL_BACKEND_SERIAL_TX_RING_BUFFER_SIZE, CONFIG_SHELL_BACKEND_SERIAL_RX_RING_BUFFER_SIZE); -SHELL_DEFINE(shell_uart, "uart:~$ ", &shell_transport_uart, 10, +SHELL_DEFINE(shell_uart, "uart:~$ ", &shell_transport_uart, + CONFIG_SHELL_BACKEND_SERIAL_LOG_MESSAGE_QUEUE_SIZE, + CONFIG_SHELL_BACKEND_SERIAL_LOG_MESSAGE_QUEUE_TIMEOUT, SHELL_FLAG_OLF_CRLF); #ifdef CONFIG_SHELL_BACKEND_SERIAL_INTERRUPT_DRIVEN