[RFC][DNM] logging: subsystem major redesign #7992

nordic-krch · 2018-05-29T11:08:48Z

Adding new implementation of logging subsystem. New features
includes: support for multiple backends, improving performance
by deferring log processing to the known context, adding
timestamps and logs filtering options (compile time, runtime,
module level, instance level). Console backend added as the
example backend.

Implementation according to the design proposal made by @pizi-nordic in #6186 with one exception: in the proposal messages are stored in the ring buffer but in the implementation they are stored as linked list. Ring buffer requires fixed size where linked list does not.

Logger features:

deferred logging - when log is called a message is created and added to the list. Message contains: string pointer, arguments, timestamp, source id and level. In the idle stage, logs are taken from the list and distributed to all active backends which requested given log. Single log message takes ~4us.
run time and compile time filtering. When compiled in, logs can be enabled/disabled in run time.
independent compile time logging for modules
instance level logging (e.g. LOG_INST_ERR(p_inst, "message %d", data))
flexible timestamping - external function provided during initialization
support for multiple backends (up to 9 backends).
independent set of filters for each backend (e.g. up to debug level to uart, errors + warnings and info from bluetooth to flash)
design ready for multi-domain logging
panic support - in panic mode backends are reconfigured to blocking mode (or shut down) and logs are processed synchronously where called
dedicated macros for dumping data - recommended (efficient) solution for dumping data (e.g. LOG_HEXDUMP_DBG(p_data, length)
printk support - when printk is called, string is formatted and output string is put into log message. It is less efficient than standard logging but gives standard printk-like functionality.

Logger subsystem consists of following entities:

log_core - functions for allocating log messages and adding them to the list (log api calls), log processing, log filters reconfiguration
log_msg - function for managing messages pool (creating, releasing) and manipulating data in the message
log_list - simple one direction linked list - should be replaced by generic component in the future
log_output - formatting string from log message. Formatting includes adding prefixes like timestamp (optionally formatted to hh:mm:ss:ms,us format), severity level name, source name, coloring

Logger API's:

log.h - API with log macros (e.g. LOG_ERR(...)) intended to be used by the modules source code (never by headers!)
log_ctrl.h - API for controling logger core: initialization, processing, configuration of runtime filters, going into panic mode. It is intended to be used by the application
log_backend.h - Backend interface. Used by backend implementations
log_msg.h - managing messages and manipulating message content. Used by core and intended to be used by backend implementations
log_instance.h - macros used for implementing instance level logging, included by module header.
log_output.h - converting log message to string output. Intended to be used by backend implementations which presents log in readable format.

PR contains:

logging subsystem implementation
default logger backend (log_backend_console)
example which shows main features of the logger

Please add RFC and DNP labels.

Signed-off-by: Krzysztof Chruściński [email protected]

Adding new implementation of logging subsystem. New features includes: support for multiple backends, improving performance by deferring log processing to the known context, adding timestamps and logs filtering options (compile time, runtime, module level, instance level). Console backend added as the example backend. Signed-off-by: Krzysztof Chruściński <[email protected]>

nordic-krch · 2018-05-29T11:11:47Z

cc: @pizi-nordic

pizi-nordic · 2018-05-29T11:12:51Z

CC: @nashif @carlescufi

carlescufi · 2018-05-29T11:14:51Z

samples/subsys/logging/logger/src/main.c

+static u32_t timestamp_get()
+{
+#ifdef CONFIG_SOC_FAMILY_NRF
+	return NRF_RTC1->COUNTER;


why? k_cycle_get_32() works on Nordic devices as well

It does but it is very slow (see _timer_cycle_get_32 in nrf_rtc_timer.c). It temporary, wanted to use it to achieve expected performance. Hopefully, nordic implementation of cycle_get will get improved.

carlescufi · 2018-05-29T11:15:09Z

samples/subsys/logging/logger/src/main.c

+static u32_t timestamp_freq()
+{
+#ifdef CONFIG_SOC_FAMILY_NRF
+	return 32768 / (NRF_RTC1->PRESCALER + 1);


same, why special cases for Nordic in a common file?

carlescufi · 2018-05-29T11:17:48Z

tests/subsys/logging/log_list/README.txt

@@ -0,0 +1,44 @@
+Title: Log list


You should use .rst for documentation

I removed the file. Imo, there is not much value added by keeping this file. Added it because logger-hook had it but i see that most of the tests do not have this file.

carlescufi · 2018-05-29T11:18:44Z

tests/subsys/logging/log_list/README.txt

+This project outputs to the console.  It can be built and executed
+on QEMU as follows:
+
+    make run


This is out of date, there should be CMake here. Also please use .. zephyr-app-commands:: for this

carlescufi · 2018-05-29T11:18:57Z

tests/subsys/logging/log_list/README.txt

+
+--------------------------------------------------------------------------------
+
+Troubleshooting:


Same, this needs rewriting

carlescufi · 2018-05-29T11:19:19Z

tests/subsys/logging/log_msg/README.txt

@@ -0,0 +1,52 @@
+Title: Log message test


see comments above for the README file format

carlescufi · 2018-05-29T11:19:33Z

tests/subsys/logging/log_msg/src/log_msg_test.c

+void test_main(void)
+{
+	ztest_test_suite(test_log_message,
+//			ztest_unit_test(test_log_std_msg),


why is this disabled?

Accident, re-enabled.

carlescufi · 2018-05-29T11:21:57Z

@nordic-krch thanks for this PR! I tried running this on an nRF52832 devkit with samples/hello_world but I get no output at all on the UART, is this expected?

codecov-io · 2018-05-29T11:50:22Z

Codecov Report

Merging #7992 into master will increase coverage by 21.96%.
The diff coverage is n/a.

@@            Coverage Diff             @@
##           master   #7992       +/-   ##
==========================================
+ Coverage   55.03%     77%   +21.96%     
==========================================
  Files         481      10      -471     
  Lines       53936     274    -53662     
  Branches    10474      30    -10444     
==========================================
- Hits        29686     211    -29475     
+ Misses      19981      43    -19938     
+ Partials     4269      20     -4249

Impacted Files	Coverage Δ
tests/ztest/src/ztest.c	`52.85% <0%> (-9.43%)`	⬇️
tests/ztest/include/ztest_assert.h	`22.22% <0%> (-7.19%)`	⬇️
ext/lib/crypto/tinycrypt/source/hmac.c
tests/kernel/stack/stack_api/src/main.c
tests/net/socket/udp/src/main.c
tests/kernel/obj_tracing/src/philosopher.c
tests/kernel/mutex/mutex/src/main.c
ext/lib/crypto/mbedtls/library/ssl_tls.c
...ernel/sched/schedule_api/src/test_sched_priority.c
subsys/net/ip/icmpv4.c
... and 462 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 5405f68...9e83d6e. Read the comment docs.

carlescufi · 2018-05-29T11:50:52Z

@nordic-krch I tested the samples/subsys/logging/logger and it works fine for me! looks like you are based on a fairly old version of Zephyr, I think you should rebase to the latest master. Also I get no colors, is there something I need to do to get those? (using minicom)
EDIT: minicom issue, works now

nashif · 2018-05-29T13:26:08Z

/home/nashif/Work/github/zephyr/subsys/logging/log_output.c: In function ‘raw_string_print’:
/home/nashif/Work/github/zephyr/subsys/logging/log_output.c:264:50: warning: passing argument 3 of ‘log_msg_hexdump_data_get’ from incompatible pointer type [-Wincompatible-pointer-types]
   log_msg_hexdump_data_get(p_msg, p_ctx->p_data, &length, offset);
                                                  ^
In file included from /home/nashif/Work/github/zephyr/include/logging/log_output.h:9:0,
                 from /home/nashif/Work/github/zephyr/subsys/logging/log_output.c:7:
/home/nashif/Work/github/zephyr/include/logging/log_msg.h:318:6: note: expected ‘u32_t * {aka unsigned int *}’ but argument is of type ‘size_t * {aka long unsigned int *}’
 void log_msg_hexdump_data_get(struct log_msg *p_msg,
      ^~~~~~~~~~~~~~~~~~~~~~~~

nashif

log_backend is windows formatted, i.e it has lots of ^M

nashif · 2018-05-29T13:23:25Z

include/linker/common-ram.ld

@@ -14,7 +14,12 @@
 	{
 		SHELL_INIT_SECTIONS()
 	} GROUP_DATA_LINK_IN(RAMABLE_REGION, ROMABLE_REGION)
-
+


you have some whitespace noise here.

nashif · 2018-05-29T13:23:38Z

include/linker/common-ram.ld

+	{
+		LOG_RAM_SECTIONS()
+	} GROUP_DATA_LINK_IN(RAMABLE_REGION, ROMABLE_REGION)
+


andyross

Not remotely done reading all of this. Haven't looked at micro-level complaints in the source at all.

I love the compressed log stream and the backend-agnostic API. I'm impressed by the linker and preprocessor magic.

Found at least two things that I think I hate, though. Am I missing something as to how these work?

andyross · 2018-05-29T16:22:43Z

include/logging/log.h

+ *
+ */
+#ifndef LOG_LEVEL
+#define LOG_SRC_LEVEL CONFIG_LOG_DEFAULT_LEVEL


Maybe call this "LOCAL" log level or something. "SRC" is a little confusing -- all logging comes from "source code".

Also: not a fan of "define this before including the file" preprocessor APIs. With a little care you can do something like IS_ENABLED() to test vs. symbols that may or may not be defined.

I liked your suggestion to use something like IS_ENABLED() macro. Then we get rid of the requirement that local log level must be defined before including log.h.

'Source' meant module or instance (source of the log). I see that this is confusing. Maybe I will come with better name.

andyross · 2018-05-29T16:26:12Z

include/logging/log.h

+ * @param ... A string optionally containing printk valid conversion specifier,
+ * followed by as many values as specifiers.
+ */
+#define LOG_ERR(...)    LOG_INTERNAL_MODULE(LOG_LEVEL_ERR, __VA_ARGS__)


So... digging through all the levels of this API...

I think this is going to defeat the GCC built-in printf format string validation, right? The compiler never sees the format literal as a string passed to a function with atribute((format(printf...))), because it goes into a separate linker section.

If so, that's a pretty critical loss of functionality. That warning saves a ton of bugs that would otherwise never be noticed.

Added empty, inline function log_printf_arg_checker() to be called in LOG_INTERNAL macro. This function has printf attribute. Compiler checking works with no performance penalty.

andyross · 2018-05-29T16:27:12Z

subsys/logging/log_core.c

+
+void log_1(const char *p_str,
+	   u32_t arg0,
+	   struct log_msg_ids src_level)


Wait, wait, wait. Wait. No, seriously, wait...

You have a staggeringly huge framework constructed of extraordinarily clever preprocessor code. It automatically detects the varargs structure of the logging used at runtime in order to correctly pack the right number of arguments into the highly compressed stream, so that the code just does the right thing without having to write out all the variants by hand. It probably does other stuff I haven't figured out yet.

But all that work just lands here in a bunch of hand-coded marshalling functions that need to duplicate all the work via separately-compiled (and thus big!) runtime code?

Why wasn't this whole mess just one C varargs function (with a little wrapper to put the format string into the right section, etc...) to begin with? Smaller, probably faster, MUCH simpler (seriously: it would cut hundreds on hundreds of lines out of the patch!).

I just don't get why you had to go through all the cpp and boilerplate hell just to get here.

The goal was to have best performance possible. Vargs will add some additional cycles. I reused approach we had in logger in nRF5 SDK. Back then I was evaluating the cost of using vargs. I will try to get the numbers as the input for discussion.

I've tried to change log macro to build an array of arguments and pass that array to generic log_n() function. Log message is created with single function, etc. It takes 74 cycles more (296 vs. 222) to log typical message (string + 1 argument) on nrf52 (cortex m4, 64mhz). That's 30% worse. In my opinion, it's a significant penalty and I would stay with current solution.

carlescufi · 2018-05-29T16:34:44Z

include/logging/log.h

+ * It's meant to report severe errors, such as those from which it's
+ * not possible to recover.
+ *
+ * @param p_inst Pointer to the log filter associated with the instance.


Can you please remove all the p_ and all other Hungarian notation prefixes? Zephyr doesn't use those and it collides with the rest of the code.

nordic-krch requested review from andrewboie, andyross and dbkinder as code owners May 29, 2018 11:08

SavinayDharmappa self-requested a review May 29, 2018 11:09

carlescufi requested review from nashif and jhedberg May 29, 2018 11:10

carlescufi requested a review from mbolivar May 29, 2018 11:13

carlescufi reviewed May 29, 2018

View reviewed changes

tests/subsys/logging/log_msg/README.txt

@@ -0,0 +1,52 @@

Title: Log message test

Copy link

Member

carlescufi May 29, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

see comments above for the README file format

carlescufi reviewed May 29, 2018

View reviewed changes

carlescufi changed the title ~~logging: subsystem major redesign~~ [RFC][DNM] logging: subsystem major redesign May 29, 2018

carlescufi added RFC Request For Comments: want input from the community DNM This PR should not be merged (Do Not Merge) area: Logging labels May 29, 2018

nordic-krch closed this May 29, 2018

nordic-krch deleted the logging_subsys branch May 29, 2018 13:24

nashif reviewed May 29, 2018

View reviewed changes

andyross reviewed May 29, 2018

View reviewed changes

carlescufi reviewed May 29, 2018

View reviewed changes

nordic-krch mentioned this pull request May 30, 2018

logging: subsystem major redesign #8023

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[RFC][DNM] logging: subsystem major redesign #7992

[RFC][DNM] logging: subsystem major redesign #7992

nordic-krch commented May 29, 2018 •

edited

Loading

nordic-krch commented May 29, 2018

pizi-nordic commented May 29, 2018

carlescufi May 29, 2018

nordic-krch May 29, 2018

carlescufi May 29, 2018

carlescufi May 29, 2018

nordic-krch Jun 1, 2018

carlescufi May 29, 2018

carlescufi May 29, 2018

carlescufi May 29, 2018

carlescufi May 29, 2018

nordic-krch Jun 1, 2018

carlescufi commented May 29, 2018 •

edited

Loading

codecov-io commented May 29, 2018

carlescufi commented May 29, 2018 •

edited

Loading

nashif commented May 29, 2018

nashif left a comment

nashif May 29, 2018

nordic-krch Jun 1, 2018

nashif May 29, 2018

nordic-krch Jun 1, 2018

andyross left a comment

andyross May 29, 2018

nordic-krch May 30, 2018

andyross May 29, 2018

nordic-krch Jun 1, 2018

andyross May 29, 2018

nordic-krch May 30, 2018

nordic-krch Jun 1, 2018

carlescufi May 29, 2018

nordic-krch Jun 1, 2018


		--------------------------------------------------------------------------------

		Troubleshooting:

[RFC][DNM] logging: subsystem major redesign #7992

[RFC][DNM] logging: subsystem major redesign #7992

Conversation

nordic-krch commented May 29, 2018 • edited Loading

nordic-krch commented May 29, 2018

pizi-nordic commented May 29, 2018

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

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

carlescufi commented May 29, 2018 • edited Loading

codecov-io commented May 29, 2018

Codecov Report

carlescufi commented May 29, 2018 • edited Loading

nashif commented May 29, 2018

nashif 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

andyross 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

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

nordic-krch commented May 29, 2018 •

edited

Loading

carlescufi commented May 29, 2018 •

edited

Loading

carlescufi commented May 29, 2018 •

edited

Loading