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/b08e70497158bd2473e02c8912271627c4bb71b6
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.hkhttp://lists.teslaclub.hk/mailman/listinfo/ovmsdev