[Ovmsdev] Console logging / CAN tracing
Stephen Casner
casner at acm.org
Mon Jan 1 01:11:01 HKT 2018
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
>
>
More information about the OvmsDev
mailing list