<html><head><meta http-equiv="Content-Type" content="text/html; charset=utf-8"></head><body style="word-wrap: break-word; -webkit-nbsp-mode: space; line-break: after-white-space;" class=""><div class=""><br class=""></div>Do you think that the overhead of the logging framework is impacting performance of things like SSH/SCP and SIMCOM async? Kind of related to the issue I raised about the infinite loop caused by debug logging on the web console and ssh (when those are already receiving log monitor output) - logging the logging.<div class=""><br class=""></div><div class="">It seems using ESP_EARLY would avoid this? Or a cleanup to move such logging to verbose level, other stuff at debug level, and a restriction on web client and ssh to never log monitor above debug level?</div><div class=""><br class=""></div><div class="">Regards, Mark.<br class=""><div><br class=""><blockquote type="cite" class=""><div class="">On 13 Jun 2020, at 9:30 PM, Michael Balzer <<a href="mailto:dexter@expeedo.de" class="">dexter@expeedo.de</a>> wrote:</div><br class="Apple-interchange-newline"><div class="">
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8" class="">
<div class="">
I've added a simple workaround for this issue to our esp-idf fork: <a href="https://github.com/openvehicles/esp-idf/commit/9024cd38ecbc78a46ed16b79d63f57812e72b123" class="">https://github.com/openvehicles/esp-idf/commit/9024cd38ecbc78a46ed16b79d63f57812e72b123</a><br class="">
<br class="">
The workaround checks if logging is done from the timer context, if
so reduces the semaphore wait time to zero, thus avoiding blocking.<br class="">
<br class="">
That should eliminate any timer consistency issues arising from
logging in timer callbacks. The disadvantage is a higher chance of
such log messages getting dropped.<br class="">
<br class="">
Regards,<br class="">
Michael<br class="">
<br class="">
<br class="">
<div class="moz-cite-prefix">Am 05.11.19 um 21:45 schrieb Michael
Balzer:<br class="">
</div>
<blockquote type="cite" cite="mid:6eac2ac1-4835-7a73-51f3-af003a43eae6@expeedo.de" class="">
<meta http-equiv="content-type" content="text/html; charset=UTF-8" class="">
Everyone,<br class="">
<br class="">
I've pushed the long due refactoring of the file logging into a
dedicated task. This removes most of the delays involved in file
logging, as the fsync() and log cycling now is done in the logging
task and no longer blocks overall log message processing.<br class="">
<br class="">
I stumbled upon a bad thing (tm) though we need to resolve with
logging: the esp-idf logging generally involves a semaphore wait
of max 10 ms (!). I wasn't aware of this because I didn't look
into the source before, there also is no warning about this in the
esp-idf documentation (<a href="https://docs.espressif.com/projects/esp-idf/en/latest/api-reference/system/log.html" moz-do-not-send="true" class="">https://docs.espressif.com/projects/esp-idf/en/latest/api-reference/system/log.html</a>),
so I guess I'm not the only one being taken by surprise here.<br class="">
<br class="">
<blockquote class=""><tt class="">// Maximum time to wait for the mutex in a logging
statement.</tt><br class="">
<tt class="">#define <b class="">MAX_MUTEX_WAIT_MS 10</b></tt><br class="">
<tt class="">#define MAX_MUTEX_WAIT_TICKS ((MAX_MUTEX_WAIT_MS +
portTICK_PERIOD_MS - 1) / portTICK_PERIOD_MS)</tt><br class="">
<tt class="">…</tt><br class="">
<tt class="">void IRAM_ATTR <b class="">esp_log_write</b>(esp_log_level_t level,</tt><br class="">
<tt class=""> const char* tag,</tt><br class="">
<tt class=""> const char* format, ...)</tt><br class="">
<tt class="">{</tt><br class="">
<tt class=""> if (!s_log_mutex) {</tt><br class="">
<tt class=""> s_log_mutex = xSemaphoreCreateMutex();</tt><br class="">
<tt class=""> }</tt><br class="">
<tt class=""> if (<b class="">xSemaphoreTake(s_log_mutex, MAX_MUTEX_WAIT_TICKS</b>)
== pdFALSE) {</tt><br class="">
<tt class=""> return;</tt><br class="">
<tt class=""> }</tt><br class="">
<tt class="">…</tt><br class="">
</blockquote>
<br class="">
That semaphore is needed to secure the log level tag cache against
parallel access, so it also affects log messages of currently
disabled tags and/or levels.<br class="">
<br class="">
This means we <b class="">must not</b> use the standard logging from timer
callbacks, at no verbosity level. But we do, partially caused by
my own code serving as a bad example I assume -- sorry.<br class="">
<br class="">
But I've not only found direct log calls in most vehicle timer
callbacks, there also are some hidden ones from calling the
framework, for example marking a notification as read can produce
a log output from Cleanup() if tracing is enabled.<br class="">
<br class="">
We need to change this short to mid term. This may be the cause of
those strange timer overflow issues we've seen occasionally. It
also means every debug or verbose log output currently in the code
involves potentially multiple semaphore waits, that's for example
the case for all hex dumps logged by the SIMCOM module.<br class="">
<br class="">
Our primary option is to remove all log calls from all low level
framework functions and timer callbacks.<br class="">
<br class="">
A simple & quick workaround could be to extend the ESP_LOGx
macros to check if they are executed in the timer task context, if
so suppress the message or call the ESP_EARLY log function
instead. That will hide these log messages from the logging
framework though, if using the _EARLY_ variant they only will be
sent to the USB port.<br class="">
<br class="">
For a better solution I thought about adding a dedicated queue
& task for the initial log submission as well. That will need
quite some rework to the esp-idf (no changes for this in the
current master) but would allow to continue logging as we do now.
Cons: queue submission involves some overhead & RAM, printf
format expansion needs to be done before the tag/level check,
messages may need to be dropped if the task starves or RAM gets
tight, log output to consoles will depend on a task as well.<br class="">
<br class="">
Opinions / better ideas?<br class="">
<br class="">
Regards,<br class="">
Michael<br class="">
<pre class="moz-signature" cols="160">--
Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal
Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
</pre>
<br class="">
<fieldset class="mimeAttachmentHeader"></fieldset>
<pre class="moz-quote-pre" wrap="">_______________________________________________
OvmsDev mailing list
<a class="moz-txt-link-abbreviated" href="mailto:OvmsDev@lists.openvehicles.com">OvmsDev@lists.openvehicles.com</a>
<a class="moz-txt-link-freetext" href="http://lists.openvehicles.com/mailman/listinfo/ovmsdev">http://lists.openvehicles.com/mailman/listinfo/ovmsdev</a>
</pre>
</blockquote>
<br class="">
<pre class="moz-signature" cols="160">--
Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal
Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
</pre>
</div>
_______________________________________________<br class="">OvmsDev mailing list<br class=""><a href="mailto:OvmsDev@lists.openvehicles.com" class="">OvmsDev@lists.openvehicles.com</a><br class="">http://lists.openvehicles.com/mailman/listinfo/ovmsdev<br class=""></div></blockquote></div><br class=""></div></body></html>