<html>
  <head>
    <meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
  </head>
  <body>
    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>
    <br>
    So I don't think that's causing performance issues if not used
    excessively or within critical sections.<br>
    <br>
    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>
    <br>
    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>
    <br>
    Regards,<br>
    Michael<br>
    <br>
    <br>
    <div class="moz-cite-prefix">Am 15.06.20 um 07:55 schrieb Mark
      Webb-Johnson:<br>
    </div>
    <blockquote type="cite"
      cite="mid:AC2DA22E-F65F-4D75-AA65-5C12C829B0A4@webb-johnson.net">
      <meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
      <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=""
                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">http://lists.openvehicles.com/mailman/listinfo/ovmsdev</a><br
                class="">
            </div>
          </blockquote>
        </div>
        <br class="">
      </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>