Logger process trigger #8704

nordic-krch · 2018-07-03T09:36:16Z

Two features are introduced:

option to wake up thread which is responsible for log processing. Thread can be waken up when number of buffered messages exceeds configurable threshold. Thread id is provided during log initialization and can be null if feature is not used - threshold set to 0.
added optional internal logger thread. If enabled, logger thread is created, thread is initializing the logger and process messages. If there is no pending messages thread goes to sleep for configurable period. Thread might be waken up using periodically or using threshold. Stack size set to 768 bytes (stack analysis shown that 576 bytes were used on nrf52).

Logger sample updated to showcase new features.

nordic-krch · 2018-07-03T09:38:22Z

cc: @jukkar

codecov-io · 2018-07-03T09:59:00Z

Codecov Report

Merging #8704 into master will decrease coverage by 0.01%.
The diff coverage is 27.27%.

@@            Coverage Diff             @@
##           master    #8704      +/-   ##
==========================================
- Coverage    52.3%   52.28%   -0.02%     
==========================================
  Files         196      196              
  Lines       24778    24788      +10     
  Branches     5152     5152              
==========================================
+ Hits        12959    12961       +2     
- Misses       9740     9748       +8     
  Partials     2079     2079

Impacted Files	Coverage Δ
subsys/logging/log_core.c	`69.07% <27.27%> (-3.46%)`	⬇️

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 afad09d...cb8c89b. Read the comment docs.

jukkar · 2018-07-03T13:03:32Z

subsys/logging/log_core.c

I think sleeping here is not good. We should have a way to be notified here that there are messages waiting to be processed, k_poll() could be used here for example.

There is notifying option: number of buffered messages are tracked and when exceeds the threshold task is waken up. Sleeping is added for case when logs are not arriving continuously and some could stuck for long period. I added threshold to avoid calling k_wakeup() on every log entry because that degrades performance of the logger.

Do you mean that this thread is put to sleep and then waken up by some other thread?

Having a k_sleep() here means that basically you are polling the logger. I think this is not really good to do it like this. Better would be that when things exceed some threshold, the logging APIs will trigger a pollable event, which causes this reading thread to be waken up and process the data. After processing this data, the thread starts to wait another events. This is a bit more code than plain sleep, but is better architecturally.

yes, PR contains 2 commits, first commit (9495059) adds ability to wake up a thread when threshold is exceeded. Second commit (adding internal thread) is using this feature but additionally adds sleep period in the thread. Sleeping is added to ensure that buffered logs are processed (and presented to the developer) even when logs stopped arriving. Let say that threshold is set to 20 and you have 19 logs in a buffer and next log will not come for dozens of seconds. You may get confused in that situation if you except to see given log (e.g. you got connected, but log does not print "connected").

Sleep period is configurable (maybe i should add option where sleep period 0 sets forever sleeping).

jukkar · 2018-07-04T12:01:21Z

BTW, do we really need to have "subsys:" in the commit subject? I think this is redundant as "logging" is your subsystem so there is no need to add 8 characters more to commit subject, that give no real information.

nordic-krch · 2018-07-05T07:28:16Z

@jukkar removed subsys: part from commit messages.

nashif · 2018-07-09T01:03:12Z

subsys/logging/Kconfig

the name of the option does not match the help or the prompt, i.e. this is for number of buffered logs, but no mention of that in the name of the config. Also, what is THR? if thread, please spell it out.

THR was supposed to mean threshold. I've extended it to threshold to avoid confusion and modified prompt to "Amount of buffered logs which triggers processing thread."

nashif · 2018-07-09T02:03:27Z

subsys/logging/log_core.c

call this 'log_process_thread', then it appears as such when we list threads by name (using stringify)

pizi-nordic · 2018-07-09T14:47:39Z

subsys/logging/log_core.c

We definitely have to separate logger initialization from thread-based processing initialization.
The logger must be be able to log data very early (ideally just after entering C code), while threads could start after system is fully initialized.

Ideally we should end with a call to log_init() in Zephyr startup code and (much) later application might decide how it is going to process gathered data (in the idle, dedicated thread or somewhere else).

good point, I've extracted setting thread to external function. log_init() is without parameters and initializes fifo and does not touch thread part. I checked that it will play nicely with #8742

pizi-nordic · 2018-07-11T12:52:58Z

doc/subsystems/logging/logger.rst

Could we add an option which will set priority of internal thread?

added configurable priority and stack size.

pizi-nordic · 2018-07-11T12:55:08Z

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

Could we have a log_flush() or something else which will block current thread until log queue is empty?

I've added log_buffered_cnt() to log_ctrl.h api which returns number of currently pending log messages. It is later on used in the example to pend on log flush

pizi-nordic · 2018-07-11T12:56:28Z

subsys/logging/Kconfig

I suggest 2 different options:

LOG_PROCESS_THREAD: Allow for log processing thread, enables other LOG_PROCESS_THREAD_* options.
LOG_PROCESS_THREAD_INTERNAL: Enables internal thread for log processing.

pizi-nordic · 2018-07-11T12:57:28Z

subsys/logging/log_core.c

Is that empty line needed?

pizi-nordic · 2018-07-11T12:58:46Z

subsys/logging/Kconfig

There sould be a note, that this option affects only internal thread.

dbkinder

+1 for doc changes as written.

pizi-nordic · 2018-07-12T11:41:31Z

doc/subsystems/logging/logger.rst

IMHO it might be worth to mention, that this also affects internal thread if it is enabled.
"... threshold dedicated thread (see :cpp:func:log_thread_set) or the internal one"

pizi-nordic · 2018-07-12T11:43:45Z

doc/subsystems/logging/logger.rst

Last sentence is unclear to me.
What about something like this: "In that case logger thread is initialized and log messages are processed implicitly."?

pizi-nordic · 2018-07-12T11:44:46Z

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

Why this k_sleep() is needed?

it can be removed once #8842 goes in. It's about allowing log to initialize since log thread is on low priority and initialization is there.

@nashif: Could you please merge #8842?
@nordic-krch: Could you please rebase this after #8842 will be merged?

pizi-nordic · 2018-07-12T11:46:02Z

subsys/logging/log_core.c

Should we allow to replace logger internal thread?

It is exposed in case user does not use internal thread. I can add assert there to check if proc_tid before setting is null.

Added configurable threshold of number of buffered log messages on which log wakes up thread which processes buffered logs. Thread ID is provided during logger initialization. Feature is optional and can be disabled by setting CONFIG_LOG_PROCESS_TRIGGER_THR to 0. Signed-off-by: Krzysztof Chruscinski <[email protected]>

When enabled, logger is creating own thread which processes buffered logs. When no logs to process, thread sleeps for configurable period. Thread can be waken up if number of buffered log messages exceeds configured threshold. Logging sample aligned to use new feature. Signed-off-by: Krzysztof Chruscinski <[email protected]>

Documenting new logger features: waking up processing thread and internal logger processing thread. Signed-off-by: Krzysztof Chruscinski <[email protected]>

carlescufi requested review from andyross, nashif and pizi-nordic July 3, 2018 09:37

carlescufi added area: Logging Enhancement Changes/Updates/Additions to existing features labels Jul 3, 2018

carlescufi added this to the v1.13.0 milestone Jul 3, 2018

jukkar reviewed Jul 3, 2018

View reviewed changes

nordic-krch force-pushed the logger_process_trigger branch from dddcec8 to bb47d7f Compare July 4, 2018 05:19

nordic-krch force-pushed the logger_process_trigger branch from bb47d7f to e5a51c7 Compare July 5, 2018 07:26

nashif requested changes Jul 9, 2018

View reviewed changes

nordic-krch force-pushed the logger_process_trigger branch 3 times, most recently from fbd2c05 to 2cd625f Compare July 9, 2018 06:50

nashif approved these changes Jul 9, 2018

View reviewed changes

pizi-nordic suggested changes Jul 9, 2018

View reviewed changes

nordic-krch force-pushed the logger_process_trigger branch from 2cd625f to 5301b80 Compare July 10, 2018 07:47

nordic-krch requested a review from dbkinder as a code owner July 10, 2018 07:47

nordic-krch mentioned this pull request Jul 10, 2018

logging: Add implicit initialization when logger used before init #8742

Closed

pizi-nordic reviewed Jul 11, 2018

View reviewed changes

dbkinder approved these changes Jul 11, 2018

View reviewed changes

nordic-krch force-pushed the logger_process_trigger branch 3 times, most recently from 8fb4b54 to ed54a35 Compare July 12, 2018 08:13

pizi-nordic reviewed Jul 12, 2018

View reviewed changes

nordic-krch force-pushed the logger_process_trigger branch from ed54a35 to 49633b8 Compare July 12, 2018 12:26

nordic-krch added 2 commits July 16, 2018 08:35

doc: subsys: logging: internal thread and thread wake up

cb8c89b

Documenting new logger features: waking up processing thread and internal logger processing thread. Signed-off-by: Krzysztof Chruscinski <[email protected]>

nordic-krch force-pushed the logger_process_trigger branch from 49633b8 to cb8c89b Compare July 16, 2018 06:45

pizi-nordic approved these changes Jul 16, 2018

View reviewed changes

nashif merged commit 46db70a into zephyrproject-rtos:master Jul 16, 2018

nordic-krch mentioned this pull request Jul 17, 2018

Network logging overhaul #8816

Merged

Logger process trigger #8704

Logger process trigger #8704

Uh oh!

Conversation

nordic-krch commented Jul 3, 2018

Uh oh!

nordic-krch commented Jul 3, 2018

Uh oh!

codecov-io commented Jul 3, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jukkar commented Jul 4, 2018

Uh oh!

nordic-krch commented Jul 5, 2018

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

pizi-nordic Jul 9, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

dbkinder left a comment

Choose a reason for hiding this comment

Uh oh!

pizi-nordic Jul 12, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

codecov-io commented Jul 3, 2018 •

edited

Loading

pizi-nordic Jul 9, 2018 •

edited

Loading

pizi-nordic Jul 12, 2018 •

edited

Loading