From b98f8e39fa3faaff8ff63ae3823cca33e884748e Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Tue, 8 Mar 2022 09:34:30 +0100 Subject: [PATCH] logging: Adapt logging to use new cbprintf feature Adapt logging to always use static packaging. Runtime packaging is used only when configuration requires that. Static packaging significantly speeds up logging when there are string arguments. Update log_stack test to new stack usage. Signed-off-by: Krzysztof Chruscinski --- include/logging/log_msg2.h | 21 +++++------- subsys/logging/log_msg2.c | 31 +++++++++++++++--- tests/subsys/logging/log_msg2/src/main.c | 33 +++++-------------- tests/subsys/logging/log_stack/src/main.c | 40 +++++++++++------------ 4 files changed, 62 insertions(+), 63 deletions(-) diff --git a/include/logging/log_msg2.h b/include/logging/log_msg2.h index 4a5597a7ad4..f5b7b008aa3 100644 --- a/include/logging/log_msg2.h +++ b/include/logging/log_msg2.h @@ -195,19 +195,19 @@ enum z_log_msg2_mode { #define Z_LOG_MSG2_STACK_CREATE(_cstr_cnt, _domain_id, _source, _level, _data, _dlen, ...) \ do { \ int _plen; \ + uint32_t flags = CBPRINTF_PACKAGE_FIRST_RO_STR_CNT(_cstr_cnt) | \ + CBPRINTF_PACKAGE_ADD_RW_STR_POS; \ if (GET_ARG_N(1, __VA_ARGS__) == NULL) { \ _plen = 0; \ } else { \ - CBPRINTF_STATIC_PACKAGE(NULL, 0, _plen, Z_LOG_MSG2_ALIGN_OFFSET, \ - CBPRINTF_PACKAGE_FIRST_RO_STR_CNT(_cstr_cnt), \ + CBPRINTF_STATIC_PACKAGE(NULL, 0, _plen, Z_LOG_MSG2_ALIGN_OFFSET, flags, \ __VA_ARGS__); \ } \ struct log_msg2 *_msg; \ Z_LOG_MSG2_ON_STACK_ALLOC(_msg, Z_LOG_MSG2_LEN(_plen, 0)); \ if (_plen) { \ CBPRINTF_STATIC_PACKAGE(_msg->data, _plen, \ - _plen, Z_LOG_MSG2_ALIGN_OFFSET, \ - CBPRINTF_PACKAGE_FIRST_RO_STR_CNT(_cstr_cnt), \ + _plen, Z_LOG_MSG2_ALIGN_OFFSET, flags, \ __VA_ARGS__);\ } \ struct log_msg2_desc _desc = \ @@ -346,15 +346,10 @@ do {\ _level, _data, _dlen, ...) \ do { \ Z_LOG_MSG2_STR_VAR(_fmt, ##__VA_ARGS__); \ - if (CBPRINTF_MUST_RUNTIME_PACKAGE(CBPRINTF_PACKAGE_FIRST_RO_STR_CNT(_cstr_cnt), \ - __VA_ARGS__)) { \ - LOG_MSG2_DBG("create runtime message\n");\ - z_log_msg2_runtime_create(_domain_id, (void *)_source, \ - _level, (uint8_t *)_data, _dlen,\ - CBPRINTF_PACKAGE_FIRST_RO_STR_CNT(_cstr_cnt), \ - Z_LOG_FMT_ARGS(_fmt, ##__VA_ARGS__));\ - _mode = Z_LOG_MSG2_MODE_RUNTIME; \ - } else if (IS_ENABLED(CONFIG_LOG_SPEED) && _try_0cpy && ((_dlen) == 0)) {\ + bool has_rw_str = CBPRINTF_MUST_RUNTIME_PACKAGE( \ + CBPRINTF_PACKAGE_FIRST_RO_STR_CNT(_cstr_cnt), \ + __VA_ARGS__); \ + if (IS_ENABLED(CONFIG_LOG_SPEED) && _try_0cpy && ((_dlen) == 0) && !has_rw_str) {\ LOG_MSG2_DBG("create zero-copy message\n");\ Z_LOG_MSG2_SIMPLE_CREATE(_cstr_cnt, _domain_id, _source, \ _level, Z_LOG_FMT_ARGS(_fmt, ##__VA_ARGS__)); \ diff --git a/subsys/logging/log_msg2.c b/subsys/logging/log_msg2.c index 1ff257d4b77..0eed269a989 100644 --- a/subsys/logging/log_msg2.c +++ b/subsys/logging/log_msg2.c @@ -47,14 +47,35 @@ void z_impl_z_log_msg2_static_create(const void *source, return; } - uint32_t msg_wlen = log_msg2_get_total_wlen(desc); - struct log_msg2 *msg = z_log_msg2_alloc(msg_wlen); + struct log_msg2_desc out_desc = desc; + int inlen = desc.package_len; + struct log_msg2 *msg; - if (msg) { - memcpy(msg->data, package, desc.package_len); + if (inlen > 0) { + uint32_t flags = CBPRINTF_PACKAGE_COPY_RW_STR; + uint16_t strl[4]; + int len; + + len = cbprintf_package_copy(package, inlen, + NULL, 0, flags, + strl, ARRAY_SIZE(strl)); + + /* Update package length with calculated value (which may be extended + * when strings are copied into the package. + */ + out_desc.package_len = len; + msg = z_log_msg2_alloc(log_msg2_get_total_wlen(out_desc)); + if (msg) { + len = cbprintf_package_copy(package, inlen, + msg->data, out_desc.package_len, + flags, strl, ARRAY_SIZE(strl)); + __ASSERT_NO_MSG(len >= 0); + } + } else { + msg = z_log_msg2_alloc(log_msg2_get_total_wlen(out_desc)); } - z_log_msg2_finalize(msg, source, desc, data); + z_log_msg2_finalize(msg, source, out_desc, data); } #ifdef CONFIG_USERSPACE diff --git a/tests/subsys/logging/log_msg2/src/main.c b/tests/subsys/logging/log_msg2/src/main.c index 6324d9496fd..62ed2e7a63e 100644 --- a/tests/subsys/logging/log_msg2/src/main.c +++ b/tests/subsys/logging/log_msg2/src/main.c @@ -19,15 +19,6 @@ #include #include -#if defined(CONFIG_ARCH_POSIX) -/* On some platforms all strings are considered RW, that impacts size of the - * package. - */ -#define TEST_LOG_MSG2_RW_STRINGS 1 -#else -#define TEST_LOG_MSG2_RW_STRINGS 0 -#endif - #if CONFIG_NO_OPTIMIZATIONS #define EXP_MODE(name) Z_LOG_MSG2_MODE_RUNTIME #else @@ -372,9 +363,6 @@ void test_mode_size_plain_string(void) */ exp_len = sizeof(struct log_msg2_hdr) + /* package */2 * sizeof(const char *); - if (mode == Z_LOG_MSG2_MODE_RUNTIME && TEST_LOG_MSG2_RW_STRINGS) { - exp_len += 2 + strlen("test str"); - } exp_len = ROUND_UP(exp_len, Z_LOG_MSG2_ALIGNMENT) / sizeof(int); get_msg_validate_length(exp_len); @@ -434,9 +422,6 @@ void test_mode_size_plain_str_data(void) */ exp_len = sizeof(struct log_msg2_hdr) + sizeof(data) + /* package */2 * sizeof(char *); - if (mode == Z_LOG_MSG2_MODE_RUNTIME && TEST_LOG_MSG2_RW_STRINGS) { - exp_len += 2 + strlen("test str"); - } exp_len = ROUND_UP(exp_len, Z_LOG_MSG2_ALIGNMENT) / sizeof(int); get_msg_validate_length(exp_len); } @@ -488,32 +473,30 @@ void test_mode_size_str_with_2strings(void) uint32_t exp_len; int mode; static const char *prefix = "prefix"; + char sufix[] = "sufix"; Z_LOG_MSG2_CREATE3(1, mode, 1 /* accept one string pointer*/, domain, source, level, - NULL, 0, TEST_STR, prefix, "sufix"); - zassert_equal(mode, EXP_MODE(RUNTIME), + NULL, 0, TEST_STR, prefix, sufix); + zassert_equal(mode, EXP_MODE(FROM_STACK), "Unexpected creation mode"); Z_LOG_MSG2_CREATE3(0, mode, 1 /* accept one string pointer*/, domain, source, level, - NULL, 0, TEST_STR, prefix, "sufix"); - zassert_equal(mode, EXP_MODE(RUNTIME), + NULL, 0, TEST_STR, prefix, sufix); + zassert_equal(mode, EXP_MODE(FROM_STACK), "Unexpected creation mode"); /* Calculate expected message length. Message consists of: * - header - * - package: header + fmt pointer + 2 pointers (on some platforms - * strings are included in the package) + * - package: header + fmt pointer + 2 pointers + * - index location of read only string * * Message size is rounded up to the required alignment. */ exp_len = sizeof(struct log_msg2_hdr) + - /* package */4 * sizeof(const char *); - if (TEST_LOG_MSG2_RW_STRINGS) { - exp_len += strlen("sufix") + 2; /* null + header */ - } + /* package */4 * sizeof(const char *) + 2 + strlen(sufix); exp_len = ROUND_UP(exp_len, Z_LOG_MSG2_ALIGNMENT) / sizeof(int); diff --git a/tests/subsys/logging/log_stack/src/main.c b/tests/subsys/logging/log_stack/src/main.c index d8dcc7ea3a8..0823b285bb2 100644 --- a/tests/subsys/logging/log_stack/src/main.c +++ b/tests/subsys/logging/log_stack/src/main.c @@ -61,9 +61,9 @@ ZTEST_SUITE(test_log_stack, NULL, NULL, NULL, NULL, after); #if defined(CONFIG_CPU_CORTEX_M0) #if !defined(CONFIG_LOG_MODE_IMMEDIATE) && !defined(CONFIG_NO_OPTIMIZATIONS) -#define SIMPLE_USAGE 64 -#define HEXDUMP_USAGE 88 -#define MORE_ARGS_USAGE 80 +#define SIMPLE_USAGE 96 +#define HEXDUMP_USAGE 96 +#define MORE_ARGS_USAGE 112 #elif defined(CONFIG_LOG_MODE_IMMEDIATE) && !defined(CONFIG_NO_OPTIMIZATIONS) #define SIMPLE_USAGE 412 #define HEXDUMP_USAGE 412 @@ -81,9 +81,9 @@ ZTEST_SUITE(test_log_stack, NULL, NULL, NULL, NULL, after); #elif defined(CONFIG_CPU_CORTEX_M3) #if !defined(CONFIG_LOG_MODE_IMMEDIATE) && !defined(CONFIG_NO_OPTIMIZATIONS) -#define SIMPLE_USAGE 40 -#define HEXDUMP_USAGE 72 -#define MORE_ARGS_USAGE 56 +#define SIMPLE_USAGE 88 +#define HEXDUMP_USAGE 88 +#define MORE_ARGS_USAGE 104 #elif defined(CONFIG_LOG_MODE_IMMEDIATE) && !defined(CONFIG_NO_OPTIMIZATIONS) #define SIMPLE_USAGE 388 #define HEXDUMP_USAGE 388 @@ -121,9 +121,9 @@ ZTEST_SUITE(test_log_stack, NULL, NULL, NULL, NULL, after); #elif defined(CONFIG_X86_64) #if !defined(CONFIG_LOG_MODE_IMMEDIATE) && !defined(CONFIG_NO_OPTIMIZATIONS) -#define SIMPLE_USAGE 32 -#define HEXDUMP_USAGE 304 -#define MORE_ARGS_USAGE 64 +#define SIMPLE_USAGE 80 +#define HEXDUMP_USAGE 80 +#define MORE_ARGS_USAGE 112 #elif defined(CONFIG_LOG_MODE_IMMEDIATE) && !defined(CONFIG_NO_OPTIMIZATIONS) #define SIMPLE_USAGE 1088 #define HEXDUMP_USAGE 1088 @@ -161,9 +161,9 @@ ZTEST_SUITE(test_log_stack, NULL, NULL, NULL, NULL, after); #elif defined(CONFIG_RISCV) && !defined(CONFIG_64BIT) && defined(CONFIG_SMP) #if !defined(CONFIG_LOG_MODE_IMMEDIATE) && !defined(CONFIG_NO_OPTIMIZATIONS) -#define SIMPLE_USAGE 24 +#define SIMPLE_USAGE 44 #define HEXDUMP_USAGE 60 -#define MORE_ARGS_USAGE 40 +#define MORE_ARGS_USAGE 60 #elif defined(CONFIG_LOG_MODE_IMMEDIATE) && !defined(CONFIG_NO_OPTIMIZATIONS) #define SIMPLE_USAGE 456 #define HEXDUMP_USAGE 456 @@ -181,13 +181,13 @@ ZTEST_SUITE(test_log_stack, NULL, NULL, NULL, NULL, after); #elif defined(CONFIG_RISCV) && defined(CONFIG_64BIT) && defined(CONFIG_SMP) #if !defined(CONFIG_LOG_MODE_IMMEDIATE) && !defined(CONFIG_NO_OPTIMIZATIONS) -#define SIMPLE_USAGE 80 -#define HEXDUMP_USAGE 96 -#define MORE_ARGS_USAGE 112 +#define SIMPLE_USAGE 112 +#define HEXDUMP_USAGE 112 +#define MORE_ARGS_USAGE 144 #elif defined(CONFIG_LOG_MODE_IMMEDIATE) && !defined(CONFIG_NO_OPTIMIZATIONS) -#define SIMPLE_USAGE 688 -#define HEXDUMP_USAGE 688 -#define MORE_ARGS_USAGE 720 +#define SIMPLE_USAGE 704 +#define HEXDUMP_USAGE 768 +#define MORE_ARGS_USAGE 736 #elif !defined(CONFIG_LOG_MODE_IMMEDIATE) && defined(CONFIG_NO_OPTIMIZATIONS) #define SIMPLE_USAGE 272 #define HEXDUMP_USAGE 272 @@ -201,9 +201,9 @@ ZTEST_SUITE(test_log_stack, NULL, NULL, NULL, NULL, after); #elif defined(CONFIG_RISCV) && defined(CONFIG_64BIT) #if !defined(CONFIG_LOG_MODE_IMMEDIATE) && !defined(CONFIG_NO_OPTIMIZATIONS) -#define SIMPLE_USAGE 104 -#define HEXDUMP_USAGE 144 -#define MORE_ARGS_USAGE 136 +#define SIMPLE_USAGE 152 +#define HEXDUMP_USAGE 152 +#define MORE_ARGS_USAGE 184 #elif defined(CONFIG_LOG_MODE_IMMEDIATE) && !defined(CONFIG_NO_OPTIMIZATIONS) #define SIMPLE_USAGE 704 #define HEXDUMP_USAGE 704