Re: logging subsys questions / concerns


Boie, Andrew P
 

Hi Krzystof,

For some reason I did not get your email, Carles had to forward to me.

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.

apboie: OK cool

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

apboie: Good point, we don't want to deal with overflow in this situation. I think what we need is an API call to clear the panic mode state if _SysFatalErrorHandler() decides not to hang the system, immediately before the API call to k_thread_abort().

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

apboie: Cool. I can help with this. I'll open a bug.

I think CONFIG_LOG_PROCESS_SLEEP_MS and
CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD should be completely removed.
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?

apboie: I think the k_sleep() call in the log thread is not ideal, the system might be idle and have some bandwidth to dump logs, but instead the log thread can be sitting there in a sleep() call. In addition the log thread will be waking up all the time even when it has nothing to do.

As mentioned in my follow-up email, what I really think we need is instead of a semaphore, drop the custom list implementation and just use a k_queue. They are fast, are callable from IRQ context, and with the variant k_queue_alloc_append() API, also callable from user mode (when we cross that bridge). Producer-consumer problems like this are what k_queues are intended for.

If you can show using a k_queue would add a lot of overhead I could be convinced otherwise, but I really thing we should pursue this route as it will also make the code simpler and let the scheduler do its job. How are you measuring latencies btw?

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.

Still not quite following you, but I'll look at the code some more.

Andrew

Join devel@lists.zephyrproject.org to automatically receive all group messages.