<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
</head>
<body>
Mark,<br>
<br>
I changed the ssh/web protocol level logging three weeks ago in
response to your issue:<br>
<br>
<a
href="https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/issues/375">https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/issues/375</a><br>
<br>
The accompanying commit to our idf fork was just to fix the
potential logs from timer context.<br>
<br>
I have tested full verbose logging via web & ssh after these two
fixes and haven't had any lock-ups or slowness. Can you describe how
to reproduce that effect?<br>
<br>
Regards,<br>
Michael<br>
<br>
<br>
<div class="moz-cite-prefix">Am 03.07.20 um 09:34 schrieb Mark
Webb-Johnson:<br>
</div>
<blockquote type="cite"
cite="mid:6D7BF69D-2557-4CCE-9756-613658660AB3@webb-johnson.net">
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
<blockquote type="cite" class="">
<div class="">On excluding verbose level logging from web &
ssh channels: I think that's a severe & (now) unnecessary
restriction. I've been using both for verbose debugging and
consider this to be useful & convenient.</div>
</blockquote>
<div class=""><br class="">
</div>
I don’t mean not sending out verbose log messages (from other
parts of the system) for ssh/web sessions. I mean removing the
verbose logging that they issue internally. The problem is that if
verbose logging is enabled over and ssh session, then the verbose
log output from the ssh code causes an infinite loop. I think
console_ssh was changed some time ago to use EARLY logging (just
to console), but not sure about other parts of the system.
<div class=""><br class="">
</div>
<div class="">It seems that if you connect remotely (ssh, web,
etc) and ‘log level verbose’, things lock-up or get so slow as
to be unusable.<br class="">
<div class=""><br class="">
</div>
<div class="">Regards, Mark.<br class="">
<div><br class="">
<blockquote type="cite" class="">
<div class="">On 16 Jun 2020, at 2:04 AM, Michael Balzer
<<a href="mailto:dexter@expeedo.de" class=""
moz-do-not-send="true">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=""> The overhead of a direct log call is the
call, the semaphore acquisition, the tag level check
& the min-heap handling. That should normally be
small. The semaphore has a nominal max wait of 1 tick
= 10 ms, but the actual delay will normally be in the
µs range.<br class="">
<br class="">
So I don't think that's causing performance issues if
not used excessively or within critical sections.<br
class="">
<br class="">
There is much more overhead though if our
OvmsCommand::HexDump() utility is used, as is the case
in the SIMCOM driver. HexDump() needs to allocate
memory and format the buffer (possibly multiple
blocks), regardless of the tag level. The actual tag
level check isn't exported from the idf log module, so
can currently not be done in advance. We could change
that, but there are few HexDump() calls now, most of
them just for error reports.<br class="">
<br class="">
On excluding verbose level logging from web & ssh
channels: I think that's a severe & (now)
unnecessary restriction. I've been using both for
verbose debugging and consider this to be useful &
convenient.<br class="">
<br class="">
Regards,<br class="">
Michael<br class="">
<br class="">
<br class="">
<div class="moz-cite-prefix">Am 15.06.20 um 07:55
schrieb Mark Webb-Johnson:<br class="">
</div>
<blockquote type="cite"
cite="mid:AC2DA22E-F65F-4D75-AA65-5C12C829B0A4@webb-johnson.net"
class="">
<meta http-equiv="Content-Type" content="text/html;
charset=UTF-8" 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 class=""><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=""
moz-do-not-send="true">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="" moz-do-not-send="true">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" moz-do-not-send="true">OvmsDev@lists.openvehicles.com</a>
<a class="moz-txt-link-freetext" href="http://lists.openvehicles.com/mailman/listinfo/ovmsdev" moz-do-not-send="true">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="" moz-do-not-send="true">OvmsDev@lists.openvehicles.com</a><br
class="">
<a class="moz-txt-link-freetext"
href="http://lists.openvehicles.com/mailman/listinfo/ovmsdev"
moz-do-not-send="true">http://lists.openvehicles.com/mailman/listinfo/ovmsdev</a><br
class="">
</div>
</blockquote>
</div>
<br class="">
</div>
<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" moz-do-not-send="true">OvmsDev@lists.openvehicles.com</a>
<a class="moz-txt-link-freetext" href="http://lists.openvehicles.com/mailman/listinfo/ovmsdev" moz-do-not-send="true">http://lists.openvehicles.com/mailman/listinfo/ovmsdev</a>
</pre>
</blockquote>
<br class="">
<pre class="moz-signature" cols="72">--
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=""
moz-do-not-send="true">OvmsDev@lists.openvehicles.com</a><br
class="">
<a class="moz-txt-link-freetext" href="http://lists.openvehicles.com/mailman/listinfo/ovmsdev">http://lists.openvehicles.com/mailman/listinfo/ovmsdev</a><br
class="">
</div>
</blockquote>
</div>
<br class="">
</div>
</div>
<br>
<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>
<pre class="moz-signature" cols="72">--
Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal
Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
</pre>
</body>
</html>