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.

 

Regards,

Krzysztof

 

-----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.

 

Regards,

 

Carles

 

> -----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.

>

> I think CONFIG_LOG_PROCESS_SLEEP_MS and

> 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 devel@lists.zephyrproject.org to automatically receive all group messages.