[Ovmsdev] Console logging / CAN tracing
Geir Øyvind Vælidalo
geir at validalo.net
Mon Jan 1 20:20:16 HKT 2018
This is so nice! Thanks, Stephen!
Geir
> 1. jan. 2018 kl. 13:12 skrev Michael Balzer <dexter at 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/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 at 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 at lists.teslaclub.hk
>>>>> http://lists.teslaclub.hk/mailman/listinfo/ovmsdev
>>>>>
>>>>>
>>>> _______________________________________________
>>>> OvmsDev mailing list
>>>> OvmsDev at 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 at lists.teslaclub.hk
>>> http://lists.teslaclub.hk/mailman/listinfo/ovmsdev
>>>
>>>
>> _______________________________________________
>> OvmsDev mailing list
>> OvmsDev at 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 at lists.teslaclub.hk
> http://lists.teslaclub.hk/mailman/listinfo/ovmsdev
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openvehicles.com/pipermail/ovmsdev/attachments/20180101/afa55002/attachment.htm>
More information about the OvmsDev
mailing list