I've found a strange issue with console logging and/or especially CAN tracing: If CAN tracing is enabled and a command that sends CAN frames and runs longer than about a second (?) (i.e. "co can1 scan"), the trace output first becomes garbled, the command will need much longer than usual to finish, and after returning to the prompt, the hex and single char output of the trace is split into separate outputs, coming one per second (running for a while), intermixing with the shell prompt. Also trace output gets garbled especially on a parallel telnet session. I suspect that's due to the UART queue becoming full, and the console logger doing xQueueSendToBack() with 1000 ms timeouts. Every hex dump byte is logged by a separate call to MyCommandApp.Log(). If the queue is full, every single call gets delayed for a second …adding up to block the console for as many seconds as there are calls…? (unverified theory)
As proposed, I will change the script code to use BufferedShell and also change how console_logger() is done so I can remove the problematic OvmsConsole::Log() function. Then puts() will work again, too. -- Steve
Is this related? I.e. should the CAN trace output be done using ESP_LOG instead of MyCommandApp.Log()? If so I can take care of that… Regards, Michael -- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
Michael, The right fix is to change the CAN tracing to gather its output into a buffer so complete lines get logged. The ESP_LOG macros get redirected through our logging system as well, but (currently) only to the async console rather than all consoles. Is logging of CAN traces to telnet/SSH sessions desired? How about other logging? There may also be some ways to improve handling of full-queue conditions to degrade more gracefully. -- Steve On Fri, 29 Dec 2017, Michael Balzer wrote:
I've found a strange issue with console logging and/or especially CAN tracing:
If CAN tracing is enabled and a and that sends CAN frames and runs longer than about a second (?) (i.e. "co can1 scan"), the trace output first becomes garbled, the command will need much longer than usual to finish, and after returning to the prompt, the hex and single char output of the trace is split into separate outputs, coming one per second (running for a while), intermixing with the shell prompt. Also trace output gets garbled especially on a parallel telnet session.
I suspect that's due to the UART queue becoming full, and the console logger doing xQueueSendToBack() with 1000 ms timeouts.
Every hex dump byte is logged by a separate call to MyCommandApp.Log(). If the queue is full, every single call gets delayed for a second ...adding up to block the console for as many seconds as there are calls...? (unverified theory)
As proposed, I will change the script code to use BufferedShell and also change how console_logger() is done so I can remove the problematic OvmsConsole::Log() function. Then puts() will work again, too. -- Steve
Is this related? I.e. should the CAN trace output be done using ESP_LOG instead of MyCommandApp.Log()?
If so I can take care of that...
Regards, Michael
-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
Stephen, I'll change the CAN tracing tomorrow. Log output on the async console is sufficient for now. Maybe if we get SD cards running, we can write the log also into a file. Regards, Michael Am 29.12.2017 um 23:04 schrieb Stephen Casner:
Michael,
The right fix is to change the CAN tracing to gather its output into a buffer so complete lines get logged.
The ESP_LOG macros get redirected through our logging system as well, but (currently) only to the async console rather than all consoles. Is logging of CAN traces to telnet/SSH sessions desired? How about other logging?
There may also be some ways to improve handling of full-queue conditions to degrade more gracefully.
-- Steve
On Fri, 29 Dec 2017, Michael Balzer wrote:
I've found a strange issue with console logging and/or especially CAN tracing:
If CAN tracing is enabled and a and that sends CAN frames and runs longer than about a second (?) (i.e. "co can1 scan"), the trace output first becomes garbled, the command will need much longer than usual to finish, and after returning to the prompt, the hex and single char output of the trace is split into separate outputs, coming one per second (running for a while), intermixing with the shell prompt. Also trace output gets garbled especially on a parallel telnet session.
I suspect that's due to the UART queue becoming full, and the console logger doing xQueueSendToBack() with 1000 ms timeouts.
Every hex dump byte is logged by a separate call to MyCommandApp.Log(). If the queue is full, every single call gets delayed for a second ...adding up to block the console for as many seconds as there are calls...? (unverified theory)
As proposed, I will change the script code to use BufferedShell and also change how console_logger() is done so I can remove the problematic OvmsConsole::Log() function. Then puts() will work again, too. -- Steve Is this related? I.e. should the CAN trace output be done using ESP_LOG instead of MyCommandApp.Log()?
If so I can take care of that...
Regards, Michael
-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev
-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
Stephen, can you take a look at my mitigation of the queue blocking issue? https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/commit/b08e... If a console currently executes a command, I lower the log queueing wait time to 0. Other consoles continue normal log processing, so I can for example issue commands on the telnet console and watch their log output on the async. Regards, Michael Am 29.12.2017 um 23:04 schrieb Stephen Casner:
Michael,
The right fix is to change the CAN tracing to gather its output into a buffer so complete lines get logged.
The ESP_LOG macros get redirected through our logging system as well, but (currently) only to the async console rather than all consoles. Is logging of CAN traces to telnet/SSH sessions desired? How about other logging?
There may also be some ways to improve handling of full-queue conditions to degrade more gracefully.
-- Steve
On Fri, 29 Dec 2017, Michael Balzer wrote:
I've found a strange issue with console logging and/or especially CAN tracing:
If CAN tracing is enabled and a and that sends CAN frames and runs longer than about a second (?) (i.e. "co can1 scan"), the trace output first becomes garbled, the command will need much longer than usual to finish, and after returning to the prompt, the hex and single char output of the trace is split into separate outputs, coming one per second (running for a while), intermixing with the shell prompt. Also trace output gets garbled especially on a parallel telnet session.
I suspect that's due to the UART queue becoming full, and the console logger doing xQueueSendToBack() with 1000 ms timeouts.
Every hex dump byte is logged by a separate call to MyCommandApp.Log(). If the queue is full, every single call gets delayed for a second ...adding up to block the console for as many seconds as there are calls...? (unverified theory)
As proposed, I will change the script code to use BufferedShell and also change how console_logger() is done so I can remove the problematic OvmsConsole::Log() function. Then puts() will work again, too. -- Steve Is this related? I.e. should the CAN trace output be done using ESP_LOG instead of MyCommandApp.Log()?
If so I can take care of that...
Regards, Michael
-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev
-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
Michael, No, I would prefer to remove this "busy" mechanism that you added because it does not serve any useful purpose. During the time that "busy" would be false the probability of the queue becoming full is very low because the amount of processing in the command parser itself is small, so it makes no difference whether the wait time is 0 or 1000. Therefore we might as well set the wait time to zero always. Choosing to set the wait time to zero (during a command or not) means that we choose to discard log messages rather than delaying the processes that are generating them. It is fine with me if we want to make that policy change. Then I think we should have a counter for lost log messages and print a warning message about that loss when control returns to the command parser. I did that as part of the new support for commands that take input from the console; while in that mode, log messages are moved to a separate queue, and when that queue fills the oldest messages are discarded. -- Steve On Sat, 30 Dec 2017, Michael Balzer wrote:
Stephen,
can you take a look at my mitigation of the queue blocking issue?
https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/commit/b08e...
If a console currently executes a command, I lower the log queueing wait time to 0. Other consoles continue normal log processing, so I can for example issue commands on the telnet console and watch their log output on the async.
Regards, Michael
Am 29.12.2017 um 23:04 schrieb Stephen Casner:
Michael,
The right fix is to change the CAN tracing to gather its output into a buffer so complete lines get logged.
The ESP_LOG macros get redirected through our logging system as well, but (currently) only to the async console rather than all consoles. Is logging of CAN traces to telnet/SSH sessions desired? How about other logging?
There may also be some ways to improve handling of full-queue conditions to degrade more gracefully.
-- Steve
On Fri, 29 Dec 2017, Michael Balzer wrote:
I've found a strange issue with console logging and/or especially CAN tracing:
If CAN tracing is enabled and a and that sends CAN frames and runs longer than about a second (?) (i.e. "co can1 scan"), the trace output first becomes garbled, the command will need much longer than usual to finish, and after returning to the prompt, the hex and single char output of the trace is split into separate outputs, coming one per second (running for a while), intermixing with the shell prompt. Also trace output gets garbled especially on a parallel telnet session.
I suspect that's due to the UART queue becoming full, and the console logger doing xQueueSendToBack() with 1000 ms timeouts.
Every hex dump byte is logged by a separate call to MyCommandApp.Log(). If the queue is full, every single call gets delayed for a second ...adding up to block the console for as many seconds as there are calls...? (unverified theory)
As proposed, I will change the script code to use BufferedShell and also change how console_logger() is done so I can remove the problematic OvmsConsole::Log() function. Then puts() will work again, too. -- Steve Is this related? I.e. should the CAN trace output be done using ESP_LOG instead of MyCommandApp.Log()?
If so I can take care of that...
Regards, Michael
-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/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.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev
Stephen, I agree overall, just one note: If we set the wait time to zero, log messages will also get lost if too many are sent to be processed for just a short period of time. I.e. not the situation of a CAN trace, where there's no other way than discarding messages, but some single background operation that simply produces a chunk of messages too fast for the async console. As an example, if the Twizy detects a battery status change, it will trigger 15 notifications at once. So with wait time zero, some of the log output always will be lost. But on the other hand, delaying the logging process is always bad, and we just don't have the RAM to buffer more messages, so I'd also be fine with that policy change. Regards, Michael Am 31.12.2017 um 09:52 schrieb Stephen Casner:
Michael,
No, I would prefer to remove this "busy" mechanism that you added because it does not serve any useful purpose. During the time that "busy" would be false the probability of the queue becoming full is very low because the amount of processing in the command parser itself is small, so it makes no difference whether the wait time is 0 or 1000. Therefore we might as well set the wait time to zero always.
Choosing to set the wait time to zero (during a command or not) means that we choose to discard log messages rather than delaying the processes that are generating them. It is fine with me if we want to make that policy change. Then I think we should have a counter for lost log messages and print a warning message about that loss when control returns to the command parser. I did that as part of the new support for commands that take input from the console; while in that mode, log messages are moved to a separate queue, and when that queue fills the oldest messages are discarded.
-- Steve
On Sat, 30 Dec 2017, Michael Balzer wrote:
Stephen,
can you take a look at my mitigation of the queue blocking issue?
https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/commit/b08e...
If a console currently executes a command, I lower the log queueing wait time to 0. Other consoles continue normal log processing, so I can for example issue commands on the telnet console and watch their log output on the async.
Regards, Michael
Am 29.12.2017 um 23:04 schrieb Stephen Casner:
Michael,
The right fix is to change the CAN tracing to gather its output into a buffer so complete lines get logged.
The ESP_LOG macros get redirected through our logging system as well, but (currently) only to the async console rather than all consoles. Is logging of CAN traces to telnet/SSH sessions desired? How about other logging?
There may also be some ways to improve handling of full-queue conditions to degrade more gracefully.
-- Steve
On Fri, 29 Dec 2017, Michael Balzer wrote:
I've found a strange issue with console logging and/or especially CAN tracing:
If CAN tracing is enabled and a and that sends CAN frames and runs longer than about a second (?) (i.e. "co can1 scan"), the trace output first becomes garbled, the command will need much longer than usual to finish, and after returning to the prompt, the hex and single char output of the trace is split into separate outputs, coming one per second (running for a while), intermixing with the shell prompt. Also trace output gets garbled especially on a parallel telnet session.
I suspect that's due to the UART queue becoming full, and the console logger doing xQueueSendToBack() with 1000 ms timeouts.
Every hex dump byte is logged by a separate call to MyCommandApp.Log(). If the queue is full, every single call gets delayed for a second ...adding up to block the console for as many seconds as there are calls...? (unverified theory)
As proposed, I will change the script code to use BufferedShell and also change how console_logger() is done so I can remove the problematic OvmsConsole::Log() function. Then puts() will work again, too. -- Steve Is this related? I.e. should the CAN trace output be done using ESP_LOG instead of MyCommandApp.Log()?
If so I can take care of that...
Regards, Michael
-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/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.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev
_______________________________________________ OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev
-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
Michael, The queue size is currently 30, which should handle the 15 notifications from Twizy. We can make that number larger as appropriate. -- Steve On Sun, 31 Dec 2017, Michael Balzer wrote:
Stephen,
I agree overall, just one note:
If we set the wait time to zero, log messages will also get lost if too many are sent to be processed for just a short period of time. I.e. not the situation of a CAN trace, where there's no other way than discarding messages, but some single background operation that simply produces a chunk of messages too fast for the async console. As an example, if the Twizy detects a battery status change, it will trigger 15 notifications at once. So with wait time zero, some of the log output always will be lost.
But on the other hand, delaying the logging process is always bad, and we just don't have the RAM to buffer more messages, so I'd also be fine with that policy change.
Regards, Michael
Am 31.12.2017 um 09:52 schrieb Stephen Casner:
Michael,
No, I would prefer to remove this "busy" mechanism that you added because it does not serve any useful purpose. During the time that "busy" would be false the probability of the queue becoming full is very low because the amount of processing in the command parser itself is small, so it makes no difference whether the wait time is 0 or 1000. Therefore we might as well set the wait time to zero always.
Choosing to set the wait time to zero (during a command or not) means that we choose to discard log messages rather than delaying the processes that are generating them. It is fine with me if we want to make that policy change. Then I think we should have a counter for lost log messages and print a warning message about that loss when control returns to the command parser. I did that as part of the new support for commands that take input from the console; while in that mode, log messages are moved to a separate queue, and when that queue fills the oldest messages are discarded.
-- Steve
On Sat, 30 Dec 2017, Michael Balzer wrote:
Stephen,
can you take a look at my mitigation of the queue blocking issue?
https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/commit/b08e...
If a console currently executes a command, I lower the log queueing wait time to 0. Other consoles continue normal log processing, so I can for example issue commands on the telnet console and watch their log output on the async.
Regards, Michael
Am 29.12.2017 um 23:04 schrieb Stephen Casner:
Michael,
The right fix is to change the CAN tracing to gather its output into a buffer so complete lines get logged.
The ESP_LOG macros get redirected through our logging system as well, but (currently) only to the async console rather than all consoles. Is logging of CAN traces to telnet/SSH sessions desired? How about other logging?
There may also be some ways to improve handling of full-queue conditions to degrade more gracefully.
-- Steve
On Fri, 29 Dec 2017, Michael Balzer wrote:
I've found a strange issue with console logging and/or especially CAN tracing:
If CAN tracing is enabled and a and that sends CAN frames and runs longer than about a second (?) (i.e. "co can1 scan"), the trace output first becomes garbled, the command will need much longer than usual to finish, and after returning to the prompt, the hex and single char output of the trace is split into separate outputs, coming one per second (running for a while), intermixing with the shell prompt. Also trace output gets garbled especially on a parallel telnet session.
I suspect that's due to the UART queue becoming full, and the console logger doing xQueueSendToBack() with 1000 ms timeouts.
Every hex dump byte is logged by a separate call to MyCommandApp.Log(). If the queue is full, every single call gets delayed for a second ...adding up to block the console for as many seconds as there are calls...? (unverified theory)
As proposed, I will change the script code to use BufferedShell and also change how console_logger() is done so I can remove the problematic OvmsConsole::Log() function. Then puts() will work again, too. -- Steve Is this related? I.e. should the CAN trace output be done using ESP_LOG instead of MyCommandApp.Log()?
If so I can take care of that...
Regards, Michael
-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/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.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev
_______________________________________________ OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/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.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev
Stephen, your new log handling works nicely: OVMS > co can1 scan 1-10 Scan #1-10... Done. V (189794) can: tx can1 id 601 len 8: 40 00 10 00 00 00 00 00 | @....... V (189844) can: tx can1 id 601 len 8: 80 00 10 00 00 00 04 05 | ........ V (189854) can: tx can1 id 601 len 8: 40 00 10 00 00 00 00 00 | @....... V (189904) can: tx can1 id 601 len 8: 80 00 10 00 00 00 04 05 | ........ V (189914) can: tx can1 id 601 len 8: 40 00 10 00 00 00 00 00 | @....... V (189964) can: tx can1 id 601 len 8: 80 00 10 00 00 00 04 05 | ........ V (189964) can: tx can1 id 602 len 8: 40 00 10 00 00 00 00 00 | @....... V (190014) can: tx can1 id 602 len 8: 80 00 10 00 00 00 04 05 | ........ V (190024) can: tx can1 id 602 len 8: 40 00 10 00 00 00 00 00 | @....... V (190074) can: tx can1 id 602 len 8: 80 00 10 00 00 00 04 05 | ........ V (190084) can: tx can1 id 602 len 8: 40 00 10 00 00 00 00 00 | @....... V (190134) can: tx can1 id 602 len 8: 80 00 10 00 00 00 04 05 | ........ V (190134) can: tx can1 id 603 len 8: 40 00 10 00 00 00 00 00 | @....... V (190184) can: tx can1 id 603 len 8: 80 00 10 00 00 00 04 05 | ........ V (190194) can: tx can1 id 603 len 8: 40 00 10 00 00 00 00 00 | @....... V (190244) can: tx can1 id 603 len 8: 80 00 10 00 00 00 04 05 | ........ V (190254) can: tx can1 id 603 len 8: 40 00 10 00 00 00 00 00 | @....... V (190304) can: tx can1 id 603 len 8: 80 00 10 00 00 00 04 05 | ........ V (190304) can: tx can1 id 604 len 8: 40 00 10 00 00 00 00 00 | @....... V (190354) can: tx can1 id 604 len 8: 80 00 10 00 00 00 04 05 | ........ V (190364) can: tx can1 id 604 len 8: 40 00 10 00 00 00 00 00 | @....... V (190414) can: tx can1 id 604 len 8: 80 00 10 00 00 00 04 05 | ........ V (190424) can: tx can1 id 604 len 8: 40 00 10 00 00 00 00 00 | @....... V (190474) can: tx can1 id 604 len 8: 80 00 10 00 00 00 04 05 | ........ V (190474) can: tx can1 id 605 len 8: 40 00 10 00 00 00 00 00 | @....... V (190524) can: tx can1 id 605 len 8: 80 00 10 00 00 00 04 05 | ........ V (190534) can: tx can1 id 605 len 8: 40 00 10 00 00 00 00 00 | @....... V (190584) can: tx can1 id 605 len 8: 80 00 10 00 00 00 04 05 | ........ V (190594) can: tx can1 id 605 len 8: 40 00 10 00 00 00 00 00 | @....... V (190644) can: tx can1 id 605 len 8: 80 00 10 00 00 00 04 05 | ........ [30 log messages lost] OVMS > Regards, Michael Am 31.12.2017 um 18:11 schrieb Stephen Casner:
Michael,
The queue size is currently 30, which should handle the 15 notifications from Twizy. We can make that number larger as appropriate.
-- Steve
On Sun, 31 Dec 2017, Michael Balzer wrote:
Stephen,
I agree overall, just one note:
If we set the wait time to zero, log messages will also get lost if too many are sent to be processed for just a short period of time. I.e. not the situation of a CAN trace, where there's no other way than discarding messages, but some single background operation that simply produces a chunk of messages too fast for the async console. As an example, if the Twizy detects a battery status change, it will trigger 15 notifications at once. So with wait time zero, some of the log output always will be lost.
But on the other hand, delaying the logging process is always bad, and we just don't have the RAM to buffer more messages, so I'd also be fine with that policy change.
Regards, Michael
Am 31.12.2017 um 09:52 schrieb Stephen Casner:
Michael,
No, I would prefer to remove this "busy" mechanism that you added because it does not serve any useful purpose. During the time that "busy" would be false the probability of the queue becoming full is very low because the amount of processing in the command parser itself is small, so it makes no difference whether the wait time is 0 or 1000. Therefore we might as well set the wait time to zero always.
Choosing to set the wait time to zero (during a command or not) means that we choose to discard log messages rather than delaying the processes that are generating them. It is fine with me if we want to make that policy change. Then I think we should have a counter for lost log messages and print a warning message about that loss when control returns to the command parser. I did that as part of the new support for commands that take input from the console; while in that mode, log messages are moved to a separate queue, and when that queue fills the oldest messages are discarded.
-- Steve
On Sat, 30 Dec 2017, Michael Balzer wrote:
Stephen,
can you take a look at my mitigation of the queue blocking issue?
https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/commit/b08e...
If a console currently executes a command, I lower the log queueing wait time to 0. Other consoles continue normal log processing, so I can for example issue commands on the telnet console and watch their log output on the async.
Regards, Michael
Am 29.12.2017 um 23:04 schrieb Stephen Casner:
Michael,
The right fix is to change the CAN tracing to gather its output into a buffer so complete lines get logged.
The ESP_LOG macros get redirected through our logging system as well, but (currently) only to the async console rather than all consoles. Is logging of CAN traces to telnet/SSH sessions desired? How about other logging?
There may also be some ways to improve handling of full-queue conditions to degrade more gracefully.
-- Steve
On Fri, 29 Dec 2017, Michael Balzer wrote:
I've found a strange issue with console logging and/or especially CAN tracing:
If CAN tracing is enabled and a and that sends CAN frames and runs longer than about a second (?) (i.e. "co can1 scan"), the trace output first becomes garbled, the command will need much longer than usual to finish, and after returning to the prompt, the hex and single char output of the trace is split into separate outputs, coming one per second (running for a while), intermixing with the shell prompt. Also trace output gets garbled especially on a parallel telnet session.
I suspect that's due to the UART queue becoming full, and the console logger doing xQueueSendToBack() with 1000 ms timeouts.
Every hex dump byte is logged by a separate call to MyCommandApp.Log(). If the queue is full, every single call gets delayed for a second ...adding up to block the console for as many seconds as there are calls...? (unverified theory)
> As proposed, I will change the script code to use BufferedShell and > also change how console_logger() is done so I can remove the > problematic OvmsConsole::Log() function. Then puts() will work again, > too. > -- Steve Is this related? I.e. should the CAN trace output be done using ESP_LOG instead of MyCommandApp.Log()?
If so I can take care of that...
Regards, Michael
-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/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.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev
_______________________________________________ OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/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.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev
_______________________________________________ OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev
-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
This is so nice! Thanks, Stephen! Geir
1. jan. 2018 kl. 13:12 skrev Michael Balzer <dexter@expeedo.de>:
Stephen,
your new log handling works nicely:
OVMS > co can1 scan 1-10 Scan #1-10... Done. V (189794) can: tx can1 id 601 len 8: 40 00 10 00 00 00 00 00 | @....... V (189844) can: tx can1 id 601 len 8: 80 00 10 00 00 00 04 05 | ........ V (189854) can: tx can1 id 601 len 8: 40 00 10 00 00 00 00 00 | @....... V (189904) can: tx can1 id 601 len 8: 80 00 10 00 00 00 04 05 | ........ V (189914) can: tx can1 id 601 len 8: 40 00 10 00 00 00 00 00 | @....... V (189964) can: tx can1 id 601 len 8: 80 00 10 00 00 00 04 05 | ........ V (189964) can: tx can1 id 602 len 8: 40 00 10 00 00 00 00 00 | @....... V (190014) can: tx can1 id 602 len 8: 80 00 10 00 00 00 04 05 | ........ V (190024) can: tx can1 id 602 len 8: 40 00 10 00 00 00 00 00 | @....... V (190074) can: tx can1 id 602 len 8: 80 00 10 00 00 00 04 05 | ........ V (190084) can: tx can1 id 602 len 8: 40 00 10 00 00 00 00 00 | @....... V (190134) can: tx can1 id 602 len 8: 80 00 10 00 00 00 04 05 | ........ V (190134) can: tx can1 id 603 len 8: 40 00 10 00 00 00 00 00 | @....... V (190184) can: tx can1 id 603 len 8: 80 00 10 00 00 00 04 05 | ........ V (190194) can: tx can1 id 603 len 8: 40 00 10 00 00 00 00 00 | @....... V (190244) can: tx can1 id 603 len 8: 80 00 10 00 00 00 04 05 | ........ V (190254) can: tx can1 id 603 len 8: 40 00 10 00 00 00 00 00 | @....... V (190304) can: tx can1 id 603 len 8: 80 00 10 00 00 00 04 05 | ........ V (190304) can: tx can1 id 604 len 8: 40 00 10 00 00 00 00 00 | @....... V (190354) can: tx can1 id 604 len 8: 80 00 10 00 00 00 04 05 | ........ V (190364) can: tx can1 id 604 len 8: 40 00 10 00 00 00 00 00 | @....... V (190414) can: tx can1 id 604 len 8: 80 00 10 00 00 00 04 05 | ........ V (190424) can: tx can1 id 604 len 8: 40 00 10 00 00 00 00 00 | @....... V (190474) can: tx can1 id 604 len 8: 80 00 10 00 00 00 04 05 | ........ V (190474) can: tx can1 id 605 len 8: 40 00 10 00 00 00 00 00 | @....... V (190524) can: tx can1 id 605 len 8: 80 00 10 00 00 00 04 05 | ........ V (190534) can: tx can1 id 605 len 8: 40 00 10 00 00 00 00 00 | @....... V (190584) can: tx can1 id 605 len 8: 80 00 10 00 00 00 04 05 | ........ V (190594) can: tx can1 id 605 len 8: 40 00 10 00 00 00 00 00 | @....... V (190644) can: tx can1 id 605 len 8: 80 00 10 00 00 00 04 05 | ........ [30 log messages lost] OVMS >
Regards, Michael
Am 31.12.2017 um 18:11 schrieb Stephen Casner:
Michael,
The queue size is currently 30, which should handle the 15 notifications from Twizy. We can make that number larger as appropriate.
-- Steve
On Sun, 31 Dec 2017, Michael Balzer wrote:
Stephen,
I agree overall, just one note:
If we set the wait time to zero, log messages will also get lost if too many are sent to be processed for just a short period of time. I.e. not the situation of a CAN trace, where there's no other way than discarding messages, but some single background operation that simply produces a chunk of messages too fast for the async console. As an example, if the Twizy detects a battery status change, it will trigger 15 notifications at once. So with wait time zero, some of the log output always will be lost.
But on the other hand, delaying the logging process is always bad, and we just don't have the RAM to buffer more messages, so I'd also be fine with that policy change.
Regards, Michael
Am 31.12.2017 um 09:52 schrieb Stephen Casner:
Michael,
No, I would prefer to remove this "busy" mechanism that you added because it does not serve any useful purpose. During the time that "busy" would be false the probability of the queue becoming full is very low because the amount of processing in the command parser itself is small, so it makes no difference whether the wait time is 0 or 1000. Therefore we might as well set the wait time to zero always.
Choosing to set the wait time to zero (during a command or not) means that we choose to discard log messages rather than delaying the processes that are generating them. It is fine with me if we want to make that policy change. Then I think we should have a counter for lost log messages and print a warning message about that loss when control returns to the command parser. I did that as part of the new support for commands that take input from the console; while in that mode, log messages are moved to a separate queue, and when that queue fills the oldest messages are discarded.
-- Steve
On Sat, 30 Dec 2017, Michael Balzer wrote:
Stephen,
can you take a look at my mitigation of the queue blocking issue?
https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/commit/b08e...
If a console currently executes a command, I lower the log queueing wait time to 0. Other consoles continue normal log processing, so I can for example issue commands on the telnet console and watch their log output on the async.
Regards, Michael
Am 29.12.2017 um 23:04 schrieb Stephen Casner:
Michael,
The right fix is to change the CAN tracing to gather its output into a buffer so complete lines get logged.
The ESP_LOG macros get redirected through our logging system as well, but (currently) only to the async console rather than all consoles. Is logging of CAN traces to telnet/SSH sessions desired? How about other logging?
There may also be some ways to improve handling of full-queue conditions to degrade more gracefully.
-- Steve
On Fri, 29 Dec 2017, Michael Balzer wrote:
> I've found a strange issue with console logging and/or especially > CAN tracing: > > If CAN tracing is enabled and a and that sends CAN frames and runs > longer than about a second (?) (i.e. "co can1 scan"), the trace > output first becomes garbled, the command will need much longer than > usual to finish, and after returning to the prompt, the hex and > single char output of the trace is split into separate outputs, > coming one per second (running for a while), intermixing with the > shell prompt. Also trace output gets garbled especially on a > parallel telnet session. > > I suspect that's due to the UART queue becoming full, and the > console logger doing xQueueSendToBack() with 1000 ms timeouts. > > Every hex dump byte is logged by a separate call to > MyCommandApp.Log(). If the queue is full, every single call gets > delayed for a second ...adding up to block the console for as many > seconds as there are calls...? (unverified theory) > >> As proposed, I will change the script code to use BufferedShell and >> also change how console_logger() is done so I can remove the >> problematic OvmsConsole::Log() function. Then puts() will work again, >> too. >> -- Steve > Is this related? I.e. should the CAN trace output be done using > ESP_LOG instead of MyCommandApp.Log()? > > If so I can take care of that... > > Regards, > Michael > > -- > Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal > Fon 02333 / 833 5735 * Handy 0176 / 206 989 26 _______________________________________________ OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/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.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev
_______________________________________________ OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/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.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev
_______________________________________________ OvmsDev mailing list OvmsDev@lists.teslaclub.hk http://lists.teslaclub.hk/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.teslaclub.hk http://lists.teslaclub.hk/mailman/listinfo/ovmsdev
participants (3)
-
Geir Øyvind Vælidalo -
Michael Balzer -
Stephen Casner