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@expeedo.de <mailto:dexter@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@expeedo.de <mailto:dexter@expeedo.de>> wrote:
I've added a simple workaround for this issue to our esp-idf fork: https://github.com/openvehicles/esp-idf/commit/9024cd38ecbc78a46ed16b79d63f5...
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/l...), 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@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@lists.openvehicles.com <mailto:OvmsDev@lists.openvehicles.com> http://lists.openvehicles.com/mailman/listinfo/ovmsdev
_______________________________________________ OvmsDev mailing list OvmsDev@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@lists.openvehicles.com <mailto:OvmsDev@lists.openvehicles.com> http://lists.openvehicles.com/mailman/listinfo/ovmsdev
_______________________________________________ OvmsDev mailing list OvmsDev@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