Re: logging subsys questions / concerns

Carles Cufi

Re-sending since apparently this email never reached its destination.


From: Chruściński, Krzysztof <Krzysztof.Chruscinski@...>
Sent: 29 November 2018 07:54
To: Cufi, Carles <Carles.Cufi@...>; Boie, Andrew P <andrew.p.boie@...>; zephyr-devel <zephyr-devel@...>; Rzeszutko, Jakub <Jakub.Rzeszutko@...>
Subject: RE: logging subsys questions / concerns


Hi Andrew,


Thanks for valid feedback. I’ve put my comments below.





-----Original Message-----
From: Cufi, Carles
Sent: Wednesday, November 28, 2018 9:40 PM
To: Boie, Andrew P <andrew.p.boie@...>; zephyr-devel <zephyr-devel@...>; Chruściński, Krzysztof <Krzysztof.Chruscinski@...>; Rzeszutko, Jakub <Jakub.Rzeszutko@...>
Subject: RE: logging subsys questions / concerns


Hi Andrew,


Thanks for all the feedback.

As agreed on Slack I am copying Krzysztof and Jakub here so that they see your comments and then, if applicable, we can create one or more issues alongside the ones that Paul has already opened.






> -----Original Message-----

> From: devel@... <devel@...> On

> Behalf Of Boie, Andrew P

> Sent: 28 November 2018 21:01

> To: zephyr-devel <zephyr-devel@...>

> Subject: [Zephyr-devel] logging subsys questions / concerns


> I've been looking at the logging subsystem code and I wanted to bring

> up some topics.


> 1) The default priority of the logging thread is -2. This is a very

> high non preemptive priority. I don't understand why the logging

> background thread doesn't run at the lowest preemptible priority on

> the system, like the idle thread. If people are running out of buffer

> space then they need to make their buffers bigger or switch to synchronous logging.

Krch:  Intention was to set it to the lowest possible value - K_LOWEST_APPLICATION_THREAD_PRIO. Now I’ve noticed that it’s -2 only when CONFIG_PREEMPT_ENABLED is set. So it can be updated or fixed to K_LOWEST_APPLICATION_THREAD_PRIO in the code.


> 2) The panic mode handling is not correct. It gets called from

> _NanoFatalErrorHandler, which flushes the log and then sets the

> panic_mode global *permanently* to true. This is not a good policy.

> NanoFatalErrorHandler getting called does not necessarily mean that

> the system has completely crashed, it's quite possible that the damage

> is limited to one thread dying, with the rest of the threads (and the

> overall system) still running just fine. I think we need to move the

> invocation of LOG_PANIC until *much* later, when we decide we need to

> hang the system instead of just aborting the faulting thread.

Krch: please suggest the better place. Note that ideally it should be as early as possible when non-recoverable error is hit since by doing that we reduce the risk of losing any logs (as before panic we keep using msg pool so there is a chance of overflow).


> 3) It does not appear that there is any support for invoking LOG()

> macros from user mode, which severely limits its usability. Until

> there is an answer to this, conversations about default mapping

> printk() to the log subsystem really scare me. Is LOG intended to be

> used by end user applications or just internally to the kernel?

Krch: currenly it is not supported, should be addded


> 4) The synchronization between threads invoking log points, and the

> background logging thread, do not make sense to me, and seem to be a

> way of dealing with making the log thread default to a very high non-

> preemptible priority, which I already complained about.



> CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD should be completely removed.

> Introduce a k_sem with initial count 0 and max count UINT_MAX. Log

> points have the caller give the semaphore every time something is

> added to the log buffer, and have the background thread simply do a

> blocking k_sem_take(). So much simpler, and we rely on the scheduler

> to do its job instead of this weird setup where the log thread is high

> priority but sleeps for hard-coded intervals.

Krch: Speed was the purpose of not using semaphores and sticking to simple counter. Currently, it takes ~250 cycles (nrf52 - ~4us @64MHz) to log an average log message (up to 2 arguments). k_sem_give would add 1,5us so logging time would increase 4us->5,5us. Is that acceptable? I don’t know. What do we gain? Solution is cleaner. Is it worth ~35% performance degradation?


> 5) What does it mean if CONFIG_LOG_INPLACE_PROCESS=n, but

> CONFIG_LOG_PROCESS_THREAD=n? Can we simplify our Kconfigs?

Krch: It is possible to use deferred mode and not use the thread. Most likely that would be the case when multithreading is disabled.





Join to automatically receive all group messages.