[Ovmsdev] File logging task
Michael Balzer
dexter at expeedo.de
Sat Jul 4 15:15:11 HKT 2020
Mark,
I changed the ssh/web protocol level logging three weeks ago in response
to your issue:
https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/issues/375
The accompanying commit to our idf fork was just to fix the potential
logs from timer context.
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?
Regards,
Michael
Am 03.07.20 um 09:34 schrieb Mark Webb-Johnson:
>> 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.
>
> 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.
>
> 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.
>
> Regards, Mark.
>
>> On 16 Jun 2020, at 2:04 AM, Michael Balzer <dexter at expeedo.de
>> <mailto:dexter at expeedo.de>> wrote:
>>
>> 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.
>>
>> So I don't think that's causing performance issues if not used
>> excessively or within critical sections.
>>
>> 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.
>>
>> 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.
>>
>> Regards,
>> Michael
>>
>>
>> Am 15.06.20 um 07:55 schrieb Mark Webb-Johnson:
>>>
>>> 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.
>>>
>>> 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?
>>>
>>> Regards, Mark.
>>>
>>>> On 13 Jun 2020, at 9:30 PM, Michael Balzer <dexter at expeedo.de
>>>> <mailto:dexter at expeedo.de>> wrote:
>>>>
>>>> I've added a simple workaround for this issue to our esp-idf fork:
>>>> https://github.com/openvehicles/esp-idf/commit/9024cd38ecbc78a46ed16b79d63f57812e72b123
>>>>
>>>> The workaround checks if logging is done from the timer context, if
>>>> so reduces the semaphore wait time to zero, thus avoiding blocking.
>>>>
>>>> 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.
>>>>
>>>> Regards,
>>>> Michael
>>>>
>>>>
>>>> Am 05.11.19 um 21:45 schrieb Michael Balzer:
>>>>> Everyone,
>>>>>
>>>>> 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.
>>>>>
>>>>> 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
>>>>> (https://docs.espressif.com/projects/esp-idf/en/latest/api-reference/system/log.html),
>>>>> so I guess I'm not the only one being taken by surprise here.
>>>>>
>>>>> // Maximum time to wait for the mutex in a logging statement.
>>>>> #define *MAX_MUTEX_WAIT_MS 10*
>>>>> #define MAX_MUTEX_WAIT_TICKS ((MAX_MUTEX_WAIT_MS +
>>>>> portTICK_PERIOD_MS - 1) / portTICK_PERIOD_MS)
>>>>> …
>>>>> void IRAM_ATTR *esp_log_write*(esp_log_level_t level,
>>>>> const char* tag,
>>>>> const char* format, ...)
>>>>> {
>>>>> if (!s_log_mutex) {
>>>>> s_log_mutex = xSemaphoreCreateMutex();
>>>>> }
>>>>> if (*xSemaphoreTake(s_log_mutex, MAX_MUTEX_WAIT_TICKS*) ==
>>>>> pdFALSE) {
>>>>> return;
>>>>> }
>>>>> …
>>>>>
>>>>>
>>>>> 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.
>>>>>
>>>>> This means we *must not* 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.
>>>>>
>>>>> 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.
>>>>>
>>>>> 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.
>>>>>
>>>>> Our primary option is to remove all log calls from all low level
>>>>> framework functions and timer callbacks.
>>>>>
>>>>> 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.
>>>>>
>>>>> 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.
>>>>>
>>>>> Opinions / better ideas?
>>>>>
>>>>> Regards,
>>>>> Michael
>>>>> --
>>>>> Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal
>>>>> Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
>>>>>
>>>>> _______________________________________________
>>>>> OvmsDev mailing list
>>>>> OvmsDev at lists.openvehicles.com
>>>>> http://lists.openvehicles.com/mailman/listinfo/ovmsdev
>>>>
>>>> --
>>>> Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal
>>>> Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
>>>> _______________________________________________
>>>> OvmsDev mailing list
>>>> OvmsDev at lists.openvehicles.com <mailto:OvmsDev at lists.openvehicles.com>
>>>> http://lists.openvehicles.com/mailman/listinfo/ovmsdev
>>>
>>>
>>> _______________________________________________
>>> OvmsDev mailing list
>>> OvmsDev at lists.openvehicles.com
>>> http://lists.openvehicles.com/mailman/listinfo/ovmsdev
>>
>> --
>> Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal
>> Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
>> _______________________________________________
>> OvmsDev mailing list
>> OvmsDev at lists.openvehicles.com <mailto:OvmsDev at lists.openvehicles.com>
>> http://lists.openvehicles.com/mailman/listinfo/ovmsdev
>
>
> _______________________________________________
> OvmsDev mailing list
> OvmsDev at lists.openvehicles.com
> http://lists.openvehicles.com/mailman/listinfo/ovmsdev
--
Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal
Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openvehicles.com/pipermail/ovmsdev/attachments/20200704/22eac4b1/attachment-0001.html>
More information about the OvmsDev
mailing list