logging: Prevent multiple arguments evaluation (take 2) #42686

nordic-krch · 2022-02-10T10:27:27Z

This is another attempt to fix #42050. First attempt (#42165) was reverted (#42609) due to #42608. Test was failing because of increased stack usage after changes in logging. Increased stack usage has been seen in CONFIG_NO_OPTIMIZATIONS=y case.

In this take, logging macro path has been changed so that runtime packaging (the one without preprocessor magic and multiple arguments evaluation) is used always when CONFIG_NO_OPTIMIZATIONS=y or CONFIG_LOG_MODE_IMMEDIATE=y. In both cases static packaging is not needed since static packaging is used to get best performance and with those two options enabled it is not a case. Since preprocessor magic is used only when optimization is enabled, compiler handles it correctly, resolving all static values without bloating stack usage.

Additionally, added a test (tests/subsys/logging/log_stack) for checking stack usage when logging is used. Test has been used to characterize stack usage for various architectures (it varies a lot) in 4 configurations:

deferred mode
deferred mode (no optimization)
immediate mode
immediate mode (no optimization)

Test should detect any unexpected stack usage increases in logging area.

Fixes #42050.
Fixed #43016.

nashif · 2022-02-10T12:51:52Z

@nordic-krch we also had issues with the previous attempt on XCC, @dcpleung can provide the details.

dcpleung · 2022-02-10T18:35:31Z

Actually, @MaureenHelm found the issue first.

The issue is that XCC complains: #pragma GCC diagnostic not allowed inside functions. If you #ifdef them, XCC complains about _auto_type being unknown since this was introduced in GCC 4.9, but XCC is based on GCC 4.2.

nordic-krch · 2022-02-11T07:28:53Z

The issue is that XCC complains: #pragma GCC diagnostic not allowed inside functions. If you #ifdef them, XCC complains about _auto_type being unknown since this was introduced in GCC 4.9, but XCC is based on GCC 4.2.

Added guard similar to one in cbprintf. For GCC < 4.9 and clang < 3.8 runtime packaging is used always and preprocessor cuts path with __auto_type and _Generic.

include/logging/log_msg2.h

SebastianBoe · 2022-02-15T09:53:49Z

include/logging/log_msg2.h

+#ifndef CONFIG_LOG2_ALWAYS_RUNTIME
+#if !defined(__cplusplus) && \
+	!(((__GNUC__ * 10000 + __GNUC_MINOR__ * 100 + __GNUC_PATCHLEVEL__) >= 40900) || \
+	((__clang_major__ * 10000 + __clang_minor__ * 100 + __clang_patchlevel__) >= 30800))


Maybe put this in a #define ?

#if condition_for_supporting_autotype
#define AUTO_TYPE_IS_SUPPORTED
#endif

Would make the rest of the logic simpler, and potentially be useful if someone else wanted to know if autotype is supported.

are there any way we could detect if this is supported before build time ?

For example checking compiler version in CMake or testing the compiler (I'm not aware of any compiler flags related to this feature, so this will most likely not be possible).

not sure about compile time, but i rephrased this define to fixed #42686 (comment) same time.

placed comment here: #42686 (comment)

comments to comments easily gets lost in history threads.

SebastianBoe · 2022-02-15T09:58:37Z

include/logging/log_msg2.h

+ */
+#define Z_LOG_LOCAL_ARG_NAME(idx, arg) COND_CODE_0(idx, (arg), (_v##idx))
+
+/* Create local variable from input variable (expect first (fmt) argument). */


Suggested change

/* Create local variable from input variable (expect first (fmt) argument). */

/* Create local variable from input variable (except for the first (fmt) argument). */

SebastianBoe · 2022-02-15T09:59:59Z

include/logging/log_msg2.h

+	COND_CODE_0(idx, (), (auto Z_LOG_LOCAL_ARG_NAME(idx, arg) = (arg) + 0))
+#else
+#define Z_LOG_LOCAL_ARG_CREATE(idx, arg) \
+	COND_CODE_0(idx, (), (__auto_type Z_LOG_LOCAL_ARG_NAME(idx, arg) = (arg) + 0))


Can we have a define that evaluates to either auto or __auto_type so this is simplified ?

Done, Setting Z_AUTO_TYPE define to auto in cpp and __auto_type if c (and supported).

SebastianBoe · 2022-02-15T10:02:19Z

include/logging/log_msg2.h

+
+/* First level of processing creates stack variables to be passed for further processing.
+ * This is done to prevent multiple evaluations of input arguments (in case argument
+ * evaluation has consequences, e.g. it is a function call).


Suggested change

* evaluation has consequences, e.g. it is a function call).

* evaluation has side effects, e.g. it is a non-pure function call).

SebastianBoe · 2022-02-15T10:11:59Z

tests/subsys/logging/log_stack/src/test.inc

@@ -0,0 +1,288 @@
+/*


Suffix should be .h, not .inc.

This makes it easier for tools and humans to understand what kind of file it is.

there is a pattern, first started in tests/unit/util to name if test.inc and this is forth test that do that. I would keep it as is for consistency.

fair enough

SebastianBoe · 2022-02-17T14:36:08Z

include/logging/log_msg2.h

+	((__clang_major__ * 10000 + __clang_minor__ * 100 + __clang_patchlevel__) >= 30800)
+#define Z_AUTO_TYPE __auto_type
+#else
+#error "Compiler lacks support for __auto_type. Enable CONFIG_LOG2_ALWAYS_RUNTIME."


should be

#ifndef CONFIG_LOG2_ALWAYS_RUNTIME
#error
#endif

right?

I see that below in this file we are checking if this define is set, so I assume it is not always unset.

my bad. fixed.

"move fast and break things" ;)

looks like a good job overall, at least the parts I was able
to understand.

tejlmand

Please use the features of CMake instead of hacks like including test.inc in to main files that are named just for the sole purposes of having them compiled with different compilers.

tejlmand · 2022-02-21T12:32:05Z

tests/subsys/logging/log_stack/CMakeLists.txt

+target_sources_ifdef(CONFIG_CPLUSPLUS app PRIVATE src/maincxx.cxx)
+
+target_sources_ifndef(CONFIG_CPLUSPLUS app PRIVATE src/main.c)


actually, because maincxx.cxx and main.c are identical and including the same file, so a much better approach is to request CMake to compile main.c using the C++ compiler, like this:

Suggested change

target_sources_ifdef(CONFIG_CPLUSPLUS app PRIVATE src/maincxx.cxx)

target_sources_ifndef(CONFIG_CPLUSPLUS app PRIVATE src/main.c)

target_sources(app PRIVATE src/main.c)

if(CONFIG_CPLUSPLUS)

# Feel free to add a good comment here.

set_source_files_properties(src/main.c PROPERTIES LANGUAGE CXX)

endif()

and then remove maincxx.cxx as well as test.inc.
Have just a single main.c file.

Cleaning of other places using test.inc can be done in seperate PR.

tejlmand · 2022-02-21T12:41:44Z

include/logging/log_msg2.h

+#define Z_AUTO_TYPE __auto_type
+#else
+#ifndef CONFIG_LOG2_ALWAYS_RUNTIME
+#error "Compiler lacks support for __auto_type. Enable CONFIG_LOG2_ALWAYS_RUNTIME."


Could we check configure time:
#42686 (comment)

For example checking compiler version in CMake

This can be done with: https://cmake.org/cmake/help/latest/variable/CMAKE_LANG_COMPILER_VERSION.html which is supported for gcc and llvm.
That way we may detect this BEFORE compilation.

that way we can inform user earlier that there is a configuration issue that must be fixed.

Always use runtime packaging in immediate mode. Removing attempt to package on stack if possible. It would be done only to speed up logging but that is not a requirement in immediate mode where packaging time is fractional compared to backend processing. Using runtime packaging also reduces stack usage in the context which calls log message. Signed-off-by: Krzysztof Chruscinski <[email protected]>

nordic-krch · 2022-02-22T10:37:04Z

@SebastianBoe @dcpleung approvals have been withdrawn, rebased and applied @tejlmand comments. Please take another look.

tejlmand

Looks good, only comment left is we should reduce the fatal error to a warning.

tejlmand · 2022-02-22T12:01:38Z

subsys/logging/CMakeLists.txt

+  if (NOT CONFIG_LOG2_ALWAYS_RUNTIME)
+    if(CMAKE_C_COMPILER_ID STREQUAL "Clang")
+      if(CMAKE_C_COMPILER_VERSION VERSION_LESS "3.8.0")
+        message(FATAL_ERROR "Compiler version requires CONFIG_LOG2_ALWAYS_RUNTIME to be set")


I think we should downgrade this to WARNING.

Suggested change

message(FATAL_ERROR "Compiler version requires CONFIG_LOG2_ALWAYS_RUNTIME to be set")

message(WARNING "Compiler version requires CONFIG_LOG2_ALWAYS_RUNTIME to be set")

Reason, a fatal error will prevent users from running menuconfig and fix the problem, ref #9573

In principle FATAL_ERROR would be optimal here, but as users should be able to fix this using menuconfig, we have to go for less optimal solution.

tejlmand · 2022-02-22T12:01:50Z

subsys/logging/CMakeLists.txt

+    endif()
+    if(CMAKE_C_COMPILER_ID STREQUAL "GNU")
+      if(CMAKE_C_COMPILER_VERSION VERSION_LESS "4.9.0")
+        message(FATAL_ERROR "Compiler version requires CONFIG_LOG2_ALWAYS_RUNTIME to be set")


I think we should downgrade this to WARNING.

Suggested change

message(FATAL_ERROR "Compiler version requires CONFIG_LOG2_ALWAYS_RUNTIME to be set")

message(WARNING "Compiler version requires CONFIG_LOG2_ALWAYS_RUNTIME to be set")

Reason, a fatal error will prevent users from running menuconfig and fix the problem, ref #9573

Logging v2 is utilizing complex preprocessing operations to prepare message at compile time. Multiple operations are peformed on log message arguments. However, it is expected that argument will be evaluated only once (e.g. it can be a call to a function with side effects). Adding additional layer which creates copies of user arguments on stack and passes them to further processing. Updated test for log_msg2 which is using internal macro which got renamed. Signed-off-by: Krzysztof Chruscinski <[email protected]>

Added test which checks that log argument is evaluated only once when log message is created. Signed-off-by: Krzysztof Chruscinski <[email protected]>

When immediate logging is used and optimization is off then bigger stack is needed for thread analyzer. Adjusting the value. Signed-off-by: Krzysztof Chruscinski <[email protected]>

Added test which estimates stack usage of few types of logging messages in various modes, with and without optimization. Test was used to determine usage for various architectures and is expected to be used to detect stack usage increase since it fails when stack usage in given configuration goes beyond the hardcoded limit. Signed-off-by: Krzysztof Chruscinski <[email protected]>

Add information about logging stack usage. Signed-off-by: Krzysztof Chruscinski <[email protected]>

tejlmand

lgtm

nordic-krch requested a review from nashif as a code owner February 10, 2022 10:27

nordic-krch requested a review from dcpleung February 10, 2022 10:27

github-actions bot added area: API Changes to public APIs area: Documentation area: Logging area: Tests Issues related to a particular existing or missing test labels Feb 10, 2022

nordic-krch added the bug The issue is a bug, or the PR is fixing a bug label Feb 10, 2022

nordic-krch force-pushed the fix/log_multieval3 branch from d2b707b to f71fce0 Compare February 11, 2022 07:22

nordic-krch force-pushed the fix/log_multieval3 branch from f71fce0 to 0d314bf Compare February 11, 2022 07:33

MaureenHelm self-requested a review February 11, 2022 13:25

dcpleung approved these changes Feb 11, 2022

View reviewed changes

zephyrbot added area: Build System area: Debugging labels Feb 14, 2022

zephyrbot requested review from carlescufi, chen-png, gmarull, mbolivar-nordic, SebastianBoe, tejlmand and utzig February 14, 2022 14:32

zephyrbot assigned nordic-krch Feb 14, 2022

SebastianBoe reviewed Feb 15, 2022

View reviewed changes

include/logging/log_msg2.h Outdated Show resolved Hide resolved

SebastianBoe reviewed Feb 15, 2022

View reviewed changes

nordic-krch force-pushed the fix/log_multieval3 branch from 54fe62f to 046c109 Compare February 17, 2022 14:28

SebastianBoe reviewed Feb 17, 2022

View reviewed changes

nordic-krch force-pushed the fix/log_multieval3 branch from 046c109 to 41123c4 Compare February 17, 2022 14:50

SebastianBoe previously approved these changes Feb 17, 2022

View reviewed changes

dcpleung previously approved these changes Feb 17, 2022

View reviewed changes

tejlmand requested changes Feb 21, 2022

View reviewed changes

tejlmand reviewed Feb 21, 2022

View reviewed changes

nordic-krch mentioned this pull request Feb 21, 2022

Self inc/dec works incorrectly with logging API. #43016

Closed

nordic-krch dismissed stale reviews from dcpleung and SebastianBoe via 2df7853 February 22, 2022 08:26

nordic-krch force-pushed the fix/log_multieval3 branch 3 times, most recently from 9f57b20 to c7ed4f7 Compare February 22, 2022 10:10

carlescufi added the Hotfix Fix for issues blocking development, i.e. CI issues, tests failing in CI, etc. label Feb 22, 2022

SebastianBoe previously approved these changes Feb 22, 2022

View reviewed changes

tejlmand requested changes Feb 22, 2022

View reviewed changes

nordic-krch added 5 commits February 22, 2022 13:45

tests: logging: log_api: Add test for argument evaluation

6d11ad6

Added test which checks that log argument is evaluated only once when log message is created. Signed-off-by: Krzysztof Chruscinski <[email protected]>

debug: thread_analyzer: Use bigger stack in certain configurations

defb023

When immediate logging is used and optimization is off then bigger stack is needed for thread analyzer. Adjusting the value. Signed-off-by: Krzysztof Chruscinski <[email protected]>

doc: logging: Add section about stack usage

abac3bc

Add information about logging stack usage. Signed-off-by: Krzysztof Chruscinski <[email protected]>

nordic-krch dismissed SebastianBoe’s stale review via abac3bc February 22, 2022 12:45

nordic-krch force-pushed the fix/log_multieval3 branch from c7ed4f7 to abac3bc Compare February 22, 2022 12:45

tejlmand approved these changes Feb 22, 2022

View reviewed changes

carlescufi approved these changes Feb 22, 2022

View reviewed changes

carlescufi merged commit ec963aa into zephyrproject-rtos:main Feb 22, 2022

nordic-krch mentioned this pull request Feb 22, 2022

tests: lib: cbprintf_package: Rework C++ test #43071

Closed

cgturner1 mentioned this pull request Feb 22, 2022

XCC build failures for all intel_adsp tests/platforms #43087

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

logging: Prevent multiple arguments evaluation (take 2) #42686

logging: Prevent multiple arguments evaluation (take 2) #42686

nordic-krch commented Feb 10, 2022 •

edited

Loading

nashif commented Feb 10, 2022

dcpleung commented Feb 10, 2022

nordic-krch commented Feb 11, 2022

SebastianBoe Feb 15, 2022 •

edited

Loading

tejlmand Feb 17, 2022

nordic-krch Feb 17, 2022

tejlmand Feb 21, 2022

SebastianBoe Feb 15, 2022

SebastianBoe Feb 15, 2022

nordic-krch Feb 17, 2022

SebastianBoe Feb 15, 2022 •

edited

Loading

SebastianBoe Feb 15, 2022

nordic-krch Feb 17, 2022

SebastianBoe Feb 17, 2022

SebastianBoe Feb 17, 2022

nordic-krch Feb 17, 2022

SebastianBoe Feb 17, 2022

tejlmand left a comment

tejlmand Feb 21, 2022

tejlmand Feb 21, 2022 •

edited

Loading

tejlmand Feb 21, 2022

nordic-krch commented Feb 22, 2022

tejlmand left a comment

tejlmand Feb 22, 2022

nordic-krch Feb 22, 2022

tejlmand Feb 22, 2022

nordic-krch Feb 22, 2022

tejlmand left a comment

	/* Create local variable from input variable (expect first (fmt) argument). */
	/* Create local variable from input variable (except for the first (fmt) argument). */

	* evaluation has consequences, e.g. it is a function call).
	* evaluation has side effects, e.g. it is a non-pure function call).

		target_sources_ifdef(CONFIG_CPLUSPLUS app PRIVATE src/maincxx.cxx)

		target_sources_ifndef(CONFIG_CPLUSPLUS app PRIVATE src/main.c)

-target_sources_ifdef(CONFIG_CPLUSPLUS app PRIVATE src/maincxx.cxx)
-target_sources_ifndef(CONFIG_CPLUSPLUS app PRIVATE src/main.c)
+target_sources(app PRIVATE src/main.c)
+if(CONFIG_CPLUSPLUS)
+  # Feel free to add a good comment here.
+  set_source_files_properties(src/main.c PROPERTIES LANGUAGE CXX)
+endif()

	message(FATAL_ERROR "Compiler version requires CONFIG_LOG2_ALWAYS_RUNTIME to be set")
	message(WARNING "Compiler version requires CONFIG_LOG2_ALWAYS_RUNTIME to be set")

logging: Prevent multiple arguments evaluation (take 2) #42686

logging: Prevent multiple arguments evaluation (take 2) #42686

Conversation

nordic-krch commented Feb 10, 2022 • edited Loading

nashif commented Feb 10, 2022

dcpleung commented Feb 10, 2022

nordic-krch commented Feb 11, 2022

SebastianBoe Feb 15, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

SebastianBoe Feb 15, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tejlmand left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tejlmand Feb 21, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nordic-krch commented Feb 22, 2022

tejlmand left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tejlmand left a comment

Choose a reason for hiding this comment

nordic-krch commented Feb 10, 2022 •

edited

Loading

SebastianBoe Feb 15, 2022 •

edited

Loading

SebastianBoe Feb 15, 2022 •

edited

Loading

tejlmand Feb 21, 2022 •

edited

Loading