Re: logging subsys questions / concerns
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
Thanks for valid feedback. I’ve put my comments below.
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-----
> 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.