Michael,
I've received the new drive report notifications now; these need to be
changed: please do not use text notifications to transport CSV data.
That's what "data" notifications are meant for, which are stored in
their raw form on the server for later retrieval. See e.g. the vehicle
trip & grid logs for reference on how to build the messages, or have a
look at the specific Twizy and UpMiiGo data messages.
Data notifications also are designed to transport one row at a time, so
you normally don't run into buffer size issues. A header can be supplied
as a row, but you normally add one when downloading the data from the
server, so tools don't need to filter these out. I provide headers
automatically on my server for known message types, just send me your
template and I'll include that.
Apart from that, the timing statistics now seem to work pretty well,
providing valuable insights.
Regards,
Michael
Am 14.06.24 um 08:59 schrieb Michael Geddes:
> Thankyou.
> I was more worried that we might be waiting on each other.
>
> I don't think I have quite the correct able to test on my friends Leaf
> properly, or does it use the standard cable?
>
> Anyway, let me know what I can do to.
>
> //.ichael
>
> On Fri, 14 Jun 2024 at 14:46, Michael Balzer via OvmsDev
> <ovmsdev at lists.openvehicles.com> wrote:
>
> Sorry, I know I'm behind with PRs.
>
> I'll try to find some time this weekend.
>
> Regards,
> Michael
>
>
> Am 14.06.24 um 08:31 schrieb Michael Geddes via OvmsDev:
>> Was this all good? I want to make sure I get to the bottom of
>> this whole issue asap!
>>
>> https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/pull/1018
>>
>>
>> Was there something else you needed me to work on to make sure
>> this all works for all supported cars?
>>
>> //.ichael
>>
>> On Sun, 26 May 2024 at 21:15, Michael Balzer via OvmsDev
>> <ovmsdev at lists.openvehicles.com> wrote:
>>
>> OK, I see now why it wouldn't send the notification: the V2 &
>> V3 server register for notifications up to
>> COMMAND_RESULT_NORMAL = 1024 characters.
>>
>> The report quickly becomes larger than 1024 characters, so
>> the notifications no longer get sent via the server connectors.
>>
>> You need to either reduce the size, split the report, or use
>> data notifications instead.
>>
>> On the reset value init: for my float targeting smoothing
>> helper class for the UpMiiGo, I implemented a gradual ramp up
>> from 1 to the requested sample size. You can do something
>> similar also with powers of 2. IOW, yes, initialization from
>> the first values received is perfectly OK.
>>
>> Regards,
>> Michael
>>
>>
>> Am 26.05.24 um 14:35 schrieb Michael Geddes:
>>>
>>> It _/should/_ already be sending a report on charge stop.
>>>
>>> MyEvents.RegisterEvent(TAG, "vehicle.charge.stop",
>>> std::bind(&OvmsPollers::VehicleChargeStop, this, _1, _2));
>>>
>>> Reset on charge start/vehicle on is a good idea.
>>>
>>> A question – would it be silly if the first value after a
>>> reset, rather than using 0 average to start with, if the
>>> average got set to the initial value? I’m in 2 minds about
>>> it. It would make the average more useful quicker.
>>>
>>> //.ichael
>>>
>>> On Sun, 26 May 2024, 19:39 Michael Balzer via OvmsDev,
>>> <ovmsdev at lists.openvehicles.com> wrote:
>>>
>>> As the averages quickly decline when idle, an automatic
>>> report should probably also be sent on charge stop.
>>>
>>> Also, I think you should automatically reset the timer
>>> statistics on drive & charge start.
>>>
>>> First stats from charging my UpMiiGo:
>>>
>>> Type | count | Utlztn | Time
>>> | per s | [‰] | [ms]
>>> ---------------+--------+--------+---------
>>> Poll:PRI Avg| 1.00| 0.723| 0.716
>>> Peak| | 1.282| 3.822
>>> ---------------+--------+--------+---------
>>> Poll:SRX Avg| 7.72| 1.246| 0.184
>>> Peak| | 3.128| 1.058
>>> ---------------+--------+--------+---------
>>> RxCan1[7ae] Avg| 2.48| 0.915| 0.362
>>> Peak| | 1.217| 1.661
>>> ---------------+--------+--------+---------
>>> RxCan1[7cf] Avg| 4.76| 1.928| 0.397
>>> Peak| | 2.317| 2.687
>>> ---------------+--------+--------+---------
>>> RxCan1[7ed] Avg| 3.38| 1.251| 0.327
>>> Peak| | 8.154| 12.273
>>> ---------------+--------+--------+---------
>>> RxCan1[7ee] Avg| 0.21| 0.066| 0.297
>>> Peak| | 0.225| 1.690
>>> ---------------+--------+--------+---------
>>> TxCan1[744] Avg| 1.49| 0.022| 0.011
>>> Peak| | 0.032| 0.095
>>> ---------------+--------+--------+---------
>>> TxCan1[765] Avg| 3.89| 0.134| 0.027
>>> Peak| | 0.155| 0.113
>>> ---------------+--------+--------+---------
>>> TxCan1[7e5] Avg| 2.32| 0.038| 0.013
>>> Peak| | 0.295| 0.084
>>> ---------------+--------+--------+---------
>>> TxCan1[7e6] Avg| 1 0.21| 0.002| 0.008
>>> Peak| | 0.010| 0.041
>>> ---------------+--------+--------+---------
>>> Cmd:State Avg| 0.00| 0.000| 0.007
>>> Peak| | 0.005| 0.072
>>> ===============+========+========+=========
>>> Total Avg| 27.46| 6.324| 2.349
>>>
>>>
>>> Overall healthy I'd say, but let's see how it compares.
>>>
>>> 7ed is the BMS, the peak time is probably related to the
>>> extended cell data logging -- I've enabled log intervals
>>> for both cell voltages & temperatures.
>>>
>>> Regards,
>>> Michael
>>>
>>> Am 26.05.24 um 08:42 schrieb Michael Balzer via OvmsDev:
>>>
>>> The notification works on my devices, it only has a
>>> garbled per mille character -- see attached
>>> screenshot. The same applies to the mail version:
>>>
>>>
>>> Poller timing is: on
>>>
>>> Type | count | Utlztn | Time
>>>
>>> | per s | [‰] | [ms]
>>>
>>> ---------------+--------+--------+---------
>>>
>>> Poll:PRI Avg| 0.25| 0.119| 0.382
>>>
>>> Peak| | 0.513| 0.678
>>>
>>> ---------------+--------+--------+---------
>>>
>>> RxCan1[597] Avg| 0.01| 0.004| 0.021
>>>
>>> Peak| | 0.000| 0.338
>>>
>>> ---------------+--------+--------+---------
>>>
>>> RxCan1[59b] Avg| 0.01| 0.011| 0.053
>>>
>>> Peak| | 0.000| 0.848
>>>
>>> ---------------+--------+--------+---------
>>>
>>> Cmd:State Avg| 0.01| 0.002| 0.012
>>>
>>> Peak| | 0.000| 0.120
>>>
>>> ===============+========+========+=========
>>>
>>> Total Avg| 0.28| 0.135| 0.468
>>>
>>>
>>> The encoding is a general issue. The character
>>> encoding for text messages via V2/MP is quite old &
>>> clumsy, it's got an issue with the degree celcius
>>> character as well. We previously tried to keep all
>>> text messages within the SMS safe character set
>>> (which e.g. lead to writing just "C" instead of
>>> "°C"). I'd say we should head towards UTF-8 now. If
>>> we ever refit SMS support, we can recode on the fly.
>>>
>>> Regarding not seeing the notification on your phone:
>>>
>>> a) Check your notification subtype/channel filters
>>> on the module. See
>>> https://docs.openvehicles.com/en/latest/userguide/notifications.html#suppress-notifications
>>>
>>> b) Check your notification vehicle filters on the
>>> phone (menu on notification tab): if you enabled the
>>> vehicle filter, it will add the messages of not
>>> currently selected vehicles to the list only, but
>>> not raise a system notification. (Applies to the
>>> Android App, no idea about the iOS version)
>>>
>>> Regards,
>>> Michael
>>>
>>> Am 26.05.24 um 06:32 schrieb Michael Geddes:
>>>
>>> Hi,
>>>
>>> I'm trying to finalise this now .. and one last
>>> thing is that I don't get the report coming to
>>> my mobile. I'm using the command:
>>>
>>> MyNotify.NotifyString("info", "poller.report",
>>> buf.c_str());
>>>
>>> Where the buffer string is just the same as the
>>> report output. Should I be using some other
>>> format or command?
>>>
>>> I get "alert" types (like the ioniq5 door-open
>>> alert) fine to my mobile.
>>>
>>> Michael.
>>>
>>> On Sun, 19 May 2024, 12:51 Michael Balzer via
>>> OvmsDev, <ovmsdev at lists.openvehicles.com> wrote:
>>>
>>> A builtin web UI for this seems a bit over
>>> the top. Builtin web config pages should
>>> focus on user features, this is clearly a
>>> feature only needed during/for the
>>> development/extension of a vehicle adapter.
>>> Development features in the web UI are
>>> confusing for end users.
>>>
>>> If persistent enabling/disabling is done by
>>> a simple config command (e.g. "config set
>>> can poller.trace on"), that's also doable by
>>> users.
>>>
>>> Regards,
>>> Michael
>>>
>>> Am 19.05.24 um 02:06 schrieb Michael Geddes:
>>>
>>> I was so focused on how I calculated the
>>> value that I totally missed that ‰ would
>>> be a better description. I could also
>>> use the system 'Ratio' unit... so % or ‰.
>>>
>>> I'll make space to put 'Avg' on the row.
>>> Was trying to limit the width for output
>>> on a mobile. I agree it would make it
>>> easier to understand.
>>>
>>> Totals also makes sense.
>>>
>>> Should I make this a configuration that
>>> can be set on the web-page? I'd
>>> probably use a configuration change
>>> notification so that the very bit
>>> setting is sync'd with the
>>> 'configuration' value.
>>>
>>> //.ichael
>>>
>>> On Sat, 18 May 2024, 14:05 Michael
>>> Balzer, <dexter at expeedo.de> wrote:
>>>
>>> I'm not sure whether the 'max'
>>> should be the maximum of the
>>> smoothed value.. or the maximum
>>> of the raw value.
>>>
>>>
>>> It should normally be the maximum of
>>> the raw value I think, the maximum
>>> of the smoothed value cannot tell
>>> about how bad the processing of an
>>> ID can become.
>>>
>>> The naming in the table is a bit
>>> confusing I think. (besides: I've
>>> never seen "ave" as the abbreviation
>>> for average)
>>>
>>> If I understand you correctly, "time
>>> ms per s" is the time share in per
>>> mille, so something in that
>>> direction would be more clear, and
>>> "length ms" would then be "time [ms]".
>>>
>>> The totals for all averages in the
>>> table foot would also be nice.
>>>
>>> Maybe "Ave" (or avg?) also should be
>>> placed on the left, as the "peak"
>>> label now suggests being the peak of
>>> the average.
>>>
>>> Btw, keep in mind, not all "edge"
>>> users / testers are developers (e.g.
>>> the Twizy driver I'm in contact
>>> with), collecting stats feedback for
>>> vehicles from testers should be
>>> straight forward. Maybe add a
>>> data/history record, sent
>>> automatically on every drive/charge
>>> stop when the poller tracing is on?
>>>
>>> Regards,
>>> Michael
>>>
>>> Am 18.05.24 um 02:28 schrieb Michael
>>> Geddes:
>>>
>>> You did say max/pead value. I
>>> also halved the N for both.
>>>
>>> I'm not sure whether the 'max'
>>> should be the maximum of the
>>> smoothed value.. or the maximum
>>> of the raw value.
>>>
>>> This is currently the raw-value
>>> maximum.
>>>
>>> The problem is that the middle
>>> column is the maximum of the
>>> {{sum over 10s} / (10*1000,000)
>>>
>>> I could easily change the
>>> 'period' to 1s and see how that
>>> goes.. was just trying to reduce
>>> the larger calculations.
>>>
>>> Usage: poller
>>> [pause|resume|status|times|trace]
>>>
>>>
>>> OVMS# poller time status
>>> Poller timing is: on
>>> Type | Count | Ave
>>> time | Ave length
>>> | per s | ms per
>>> s | ms
>>> -------------+----------+-----------+-----------
>>> Poll:PRI | 1.00|
>>> 0.559| 0.543
>>> peak | |
>>> 0.663| 1.528
>>> -------------+----------+-----------+-----------
>>> Poll:SRX | 0.08|
>>> 0.009| 0.038
>>> peak | |
>>> 0.068| 0.146
>>> -------------+----------+-----------+-----------
>>> CAN1 RX[778] | 0.11|
>>> 0.061| 0.280
>>> peak | |
>>> 0.458| 1.046
>>> -------------+----------+-----------+-----------
>>> CAN1 RX[7a8] | 0.04|
>>> 0.024| 0.124
>>> peak | |
>>> 0.160| 0.615
>>> -------------+----------+-----------+-----------
>>> CAN1 TX[770] | 0.05|
>>> 0.004| 0.016
>>> peak | |
>>> 0.022| 0.102
>>> -------------+----------+-----------+-----------
>>> CAN1 TX[7a0] | 0.02|
>>> 0.002| 0.011
>>> peak | |
>>> 0.010| 0.098
>>> -------------+----------+-----------+-----------
>>> CAN1 TX[7b3] | 0.01|
>>> 0.001| 0.006
>>> peak | |
>>> 0.000| 0.099
>>> -------------+----------+-----------+-----------
>>> CAN1 TX[7e2] | 0.02|
>>> 0.002| 0.011
>>> peak | |
>>> 0.010| 0.099
>>> -------------+----------+-----------+-----------
>>> CAN1 TX[7e4] | 0.08|
>>> 0.008| 0.048
>>> peak | |
>>> 0.049| 0.107
>>> -------------+----------+-----------+-----------
>>> Cmd:State | 0.00|
>>> 0.000| 0.005
>>> peak | |
>>> 0.000| 0.094
>>>
>>> On Fri, 17 May 2024 at 15:26,
>>> Michael Geddes
>>> <frog at bunyip.wheelycreek.net> wrote:
>>>
>>> This is what I have now.
>>>
>>> The one on the end is the
>>> one MIchael B was after
>>> using an N of 32. (up for
>>> discussion).
>>>
>>> The middle is the time
>>> spent in that even t per
>>> second. It accumulates
>>> times (in microseconds), and
>>> then every 10s it stores it
>>> as smoothed (N=16) value.
>>>
>>> The Count is similar (except
>>> that we store a value of
>>> '100' as 1 event so it can
>>> be still integers and has 2
>>> decimal places).
>>>
>>> Every received poll does a
>>> 64bit difference to 32bit
>>> (for the elapsed time) and
>>> 64bit comparison (for
>>> end-of-period).
>>>
>>> It also does 1x 32bit
>>> smoothing and 2x 32bit adds.
>>>
>>> Then at the end of a 10s
>>> period, it will do a 64bit
>>> add to get the next
>>> end-of-period value, as well
>>> as the 2x 32bit smoothing calcs.
>>>
>>> This is from the Ioniq 5 so
>>> not any big values yet. You
>>> can certainly see how
>>> insignificant the TX
>>> callbacks are.
>>>
>>> I'll leave it on for when
>>> the car is moving and gets
>>> some faster polling.
>>>
>>> OVMS# poll time status
>>> Poller timing is: on
>>> Type | Count |
>>> Ave time | Ave Length
>>> | per s | ms
>>> per s | ms
>>> -------------+----------+-----------+-----------
>>> Poll:PRI | 1.00|
>>> 0.540| 0.539
>>> Poll:SRX | 0.03|
>>> 0.004| 0.017
>>> CAN1 RX[778] | 0.06|
>>> 0.042| 0.175
>>> CAN1 TX[770] | 0.04|
>>> 0.002| 0.008
>>> Cmd:State | 0.01|
>>> 0.001| 0.005
>>>
>>> ----------------------8<--------------------------------
>>>
>>> Nice smoothing class (forces
>>> N as a power of 2):
>>>
>>> constexpr unsigned
>>> floorlog2(unsigned x)
>>> {
>>> return x == 1 ? 0 :
>>> 1+floorlog2(x >> 1);
>>> }
>>> /* Maintain a smoothed
>>> average using shifts for
>>> division.
>>> * T should be an integer type
>>> * N needs to be a power of 2
>>> */
>>> template <typename T,
>>> unsigned N>
>>> class average_util_t
>>> {
>>> private:
>>> T m_ave;
>>> public:
>>> average_util_t() : m_ave(0) {}
>>> static const uint8_t
>>> _BITS = floorlog2(N);
>>> void add( T val)
>>> {
>>> static_assert(N == (1 <<
>>> _BITS), "N must be a power
>>> of 2");
>>> m_ave = (((N-1) *
>>> m_ave) + val) >> _BITS;
>>> }
>>> T get() { return m_ave; }
>>> operator T() { return
>>> m_ave; }
>>> };
>>>
>>> On Thu, 16 May 2024 at
>>> 10:29, Michael Geddes
>>> <frog at bunyip.wheelycreek.net>
>>> wrote:
>>>
>>> Thanks Michael,
>>>
>>> My calculations give me
>>> ((2^32)-1) /
>>> (1000*1000*3600) = only
>>> 1.2 hours of processing
>>> time in 32bit. The
>>> initial subtraction is
>>> 64bit anyway and I can't
>>> see a further 64bit
>>> addition being a
>>> problem. I have the
>>> calculations being
>>> performed in doubles at
>>> print-out where
>>> performance is not
>>> really an issue anyway.
>>> (Though apparently doing
>>> 64 bit division is worse
>>> than floating point).
>>>
>>> In addition
>>>
>>> * I currently have this
>>> being able to be turned
>>> on and off and reset
>>> manually (only do it
>>> when required).
>>>
>>> * For the lower volume
>>> commands, the smoothed
>>> average is not going to
>>> be useful - the count is
>>> more interesting for
>>> different reasons.
>>>
>>> * The total time is
>>> quite useful. Ie a high
>>> average time doesn't
>>> matter if the count is
>>> low. The things that are
>>> affecting performance
>>> are stuff with high
>>> total time. Stuff which
>>> is happening 100 times a
>>> second needs to be a
>>> much lower average than
>>> once a second.
>>>
>>> * A measure like 'time
>>> per minute/second' and
>>> possibly count per
>>> minute/seconds as a
>>> smoothed average would
>>> potentially be more
>>> useful. (or in addition?)
>>>
>>> I think we could do
>>> _that_ in a reasonably
>>> efficient manner using a
>>> 64 bit 'last measured
>>> time', a 32 bit
>>> accumulated value and
>>> the stored 32 bit
>>> rolling average.
>>>
>>> It would boils down to
>>> some iterative (integer)
>>> sums and multiplications
>>> plus a divide by n ^
>>> (time periods passed) -
>>> which is a shift - and
>>> which can be optimised
>>> to '0' if
>>> 'time-periods-passed' is
>>> more than
>>> 32/(bits-per-n) -
>>> effectively limiting the
>>> number of iterations.
>>>
>>> The one issue I can see
>>> is that we need to
>>> calculate 'number of
>>> time-periods passed'
>>> which is a 64 bit
>>> subtraction followed by
>>> a 32 bit division (not
>>> optimisable to a simple
>>> shift).
>>>
>>> * I'm also happy to keep
>>> a rolling (32bit)
>>> average time.
>>>
>>> Even if you assume
>>> averages in the 100ms,
>>> 32bit is going to
>>> happily support an N
>>> of 64 or even 128.
>>>
>>> Am I right in
>>> thinking that the choice
>>> of N is highly dependent
>>> on frequency. For things
>>> happening 100 times per
>>> second, you might want
>>> an N like 128.. where
>>> things happening once per
>>>
>>> second, you might
>>> want an N of 4 or 8.
>>> The other things we keep
>>> track of in this manner
>>> we have a better idea of
>>> the frequency of the thing.
>>>
>>> How about we have (per
>>> record type):
>>>
>>> * total count (since
>>> last reset?) (32 bit)
>>>
>>> * smoothed average of
>>> time per instance (32 bit)
>>>
>>> * ?xx? total
>>> accumulated time since
>>> last reset (64bit) ??
>>> <-- with the below stats
>>> this is much less useful
>>>
>>> * last-measured-time
>>> (64 bit)
>>>
>>> * accumulated count
>>> since last time-period
>>> (16bit - but maybe 32bit
>>> anyway for byte alignment?)
>>>
>>> * smoothed average of
>>> count per time-period
>>> (32bit)
>>>
>>> * accumulated time
>>> since last time-period
>>> (32bit)
>>>
>>> * smoothed average of
>>> time per time-period (32bit)
>>>
>>> It's possible to keep the
>>>
>>> Is this going to be too
>>> much per record type?
>>> The number of 'records'
>>> we are keeping is quite
>>> low (so 10 to 20 maybe)
>>> - so it's not a huge
>>> memory burden.
>>>
>>> Thoughts?
>>>
>>> //.ichael
>>>
>>> On Thu, 16 May 2024 at
>>> 03:09, Michael Balzer
>>> via OvmsDev
>>> <ovmsdev at lists.openvehicles.com>
>>> wrote:
>>>
>>> esp_timer_get_time()
>>> is the right choice
>>> for precision timing.
>>>
>>> I'd say uint32 is
>>> enough though, even
>>> if counting
>>> microseconds that
>>> can hold a total of
>>> more than 71 hours
>>> of actual processing
>>> time. uint64 has a
>>> significant
>>> performance penalty,
>>> although I don't
>>> recall the overhead
>>> for simple additions.
>>>
>>> Also & more
>>> important, the
>>> average wouldn't be
>>> my main focus, but
>>> the maximum
>>> processing time seen
>>> per ID, which seems
>>> to be missing in
>>> your draft.
>>>
>>> Second thought on
>>> the average… the
>>> exact overall
>>> average really has a
>>> minor meaning, I'd
>>> rather see the
>>> current average,
>>> adapting to the
>>> current mode of
>>> operation
>>> (drive/charge/…). I
>>> suggest feeding the
>>> measurements to a
>>> low pass filter to
>>> get the smoothed
>>> average of the last
>>> n measurements. Pattern:
>>>
>>> runavg = ((N-1) *
>>> runavg + newval) / N
>>>
>>> By using a low power
>>> of 2 for N (e.g. 8
>>> or 16), you can
>>> replace the division
>>> by a simple bit
>>> shift, and have
>>> enough headroom to
>>> use 32 bit integers.
>>>
>>> Regards,
>>> Michael
>>>
>>> Am 15.05.24 um 06:51
>>> schrieb Michael
>>> Geddes via OvmsDev:
>>>
>>> Formatting
>>> aside, I have
>>> implemented what
>>> I think Michael
>>> B was
>>> suggesting. This
>>> is a sample run
>>> on the Ioniq 5
>>> (which doesn't
>>> have
>>> unsolicited RX
>>> events).
>>>
>>> This uses the
>>> call esp_timer_get_time()
>>> got get a 64bit
>>> *microseconds*
>>> since started
>>> value - and
>>> works out the
>>> time to execute
>>> that way. It's
>>> looking at
>>> absolute time
>>> and not time in
>>> the Task - so
>>> other things
>>> going on at the
>>> same time in
>>> other tasks will
>>> have an effect.
>>> (The normal tick
>>> count doesn't
>>> have nearly
>>> enough
>>> resolution to be
>>> useful - any
>>> other ideas on
>>> measurement?)
>>> I've got total
>>> accumulated time
>>> displaying in
>>> seconds and the
>>> average in
>>> milliseconds
>>> currently - but
>>> I can change
>>> that easy enough.
>>>
>>> The cumulative
>>> time is stored
>>> as uint64_t
>>> which will be
>>> plenty, as 32bit
>>> wouldn't be
>>> nearly enough.
>>>
>>> OVMS# *poller
>>> time on*
>>> Poller timing is
>>> now on
>>>
>>> OVMS# *poller
>>> time status*
>>> Poller timing is: on
>>> Poll [PRI]
>>> : n=390
>>> tot=0.2s ave=0.586ms
>>> Poll [SRX]
>>> : n=316
>>> tot=0.1s ave=0.196ms
>>> CAN1 RX[0778]
>>> : n=382
>>> tot=0.2s ave=0.615ms
>>> CAN1 RX[07a8]
>>> : n=48
>>> tot=0.0s ave=0.510ms
>>> CAN1 RX[07bb]
>>> : n=162
>>> tot=0.1s ave=0.519ms
>>> CAN1 RX[07ce]
>>> : n=33
>>> tot=0.0s ave=0.469ms
>>> CAN1 RX[07ea]
>>> : n=408
>>> tot=0.2s ave=0.467ms
>>> CAN1 RX[07ec]
>>> : n=486
>>> tot=0.2s ave=0.477ms
>>> CAN3 RX[07df]
>>> : n=769
>>> tot=0.2s ave=0.261ms
>>> CAN1 TX[0770]
>>> : n=191
>>> tot=0.0s ave=0.054ms
>>> CAN1 TX[07a0]
>>> : n=16
>>> tot=0.0s ave=0.047ms
>>> CAN1 TX[07b3]
>>> : n=31
>>> tot=0.0s ave=0.069ms
>>> CAN1 TX[07c6]
>>> : n=11
>>> tot=0.0s ave=0.044ms
>>> CAN1 TX[07e2]
>>> : n=82
>>> tot=0.0s ave=0.067ms
>>> CAN1 TX[07e4]
>>> : n=54
>>> tot=0.0s ave=0.044ms
>>> Set State
>>> : n=7
>>> tot=0.0s ave=0.104ms
>>>
>>> This is probably
>>> going to be
>>> quite useful in
>>> general! The TX
>>> call-backs don't
>>> seem to be
>>> significant
>>> here. (oh, I
>>> should probably
>>> implement a
>>> reset of the
>>> values too).
>>>
>>> //.ichael
>>>
>>> On Sun, 12 May
>>> 2024 at 22:58,
>>> Michael Geddes
>>> <frog at bunyip.wheelycreek.net>
>>> wrote:
>>>
>>> Yeah - I
>>> certainly
>>> wasn't going
>>> to put a
>>> hard limit.
>>> Just a log
>>> above a
>>> certain
>>> time, that
>>> being said,
>>> the idea of
>>> just
>>> collecting
>>> stats (being
>>> able to turn
>>> it on via a
>>> "poller
>>> timer" set
>>> of commands)
>>> would be
>>> much more
>>> useful. I'll
>>> look into that.
>>>
>>> Average time
>>> is probably
>>> a good stat
>>> - and
>>> certainly
>>> what we care
>>> about.
>>>
>>> I actually
>>> am hopeful
>>> that those
>>> couple of
>>> things I did
>>> might help
>>> reduce that
>>> average time
>>> quite a bit
>>> (that
>>> short-cutting
>>> the isotp
>>> protocol
>>> handling
>>> especially).
>>>
>>> That p/r
>>> with logging
>>> changes
>>> might help
>>> reduce the
>>> unproductive
>>> log time
>>> further, but
>>> also makes
>>> it possible
>>> to turn on
>>> the poller
>>> logging
>>> without the
>>> RX task logs
>>> kicking in.
>>>
>>> //.ichael
>>>
>>> On Sun, 12
>>> May 2024 at
>>> 22:29,
>>> Michael
>>> Balzer via
>>> OvmsDev
>>> <ovmsdev at lists.openvehicles.com>
>>> wrote:
>>>
>>> Warning
>>> /
>>> gathering
>>> debug
>>> statistics
>>> about
>>> slow
>>> processing
>>> can be
>>> helpful,
>>> but
>>> there
>>> must not
>>> be a
>>> hard
>>> limit.
>>> Frame/poll
>>> response
>>> processing
>>> may need
>>> disk or
>>> network
>>> I/O, and
>>> the
>>> vehicle
>>> task may
>>> be
>>> starving
>>> from
>>> punctual
>>> high
>>> loads on
>>> higher
>>> priority
>>> tasks
>>> (e.g.
>>> networking)
>>> or by
>>> needing
>>> to wait
>>> for some
>>> semaphore
>>> --
>>> that's
>>> outside
>>> the
>>> application's
>>> control,
>>> and must
>>> not lead
>>> to
>>> termination/recreation
>>> of the
>>> task (in
>>> case
>>> you're
>>> heading
>>> towards
>>> that
>>> direction).
>>>
>>> I have
>>> no idea
>>> how much
>>> processing
>>> time the
>>> current
>>> vehicles
>>> actually
>>> need in
>>> their
>>> respective
>>> worst
>>> cases.
>>> Your
>>> draft is
>>> probably
>>> too lax,
>>> poll
>>> responses
>>> and
>>> frames
>>> normally
>>> need to
>>> be
>>> processed
>>> much
>>> faster.
>>> I'd say
>>> 10 ms is
>>> already
>>> too
>>> slow,
>>> but any
>>> wait for
>>> a
>>> queue/semaphore
>>> will
>>> already
>>> mean at
>>> least 10
>>> ms
>>> (FreeRTOS
>>> tick).
>>> Probably
>>> best to
>>> begin
>>> with
>>> just
>>> collecting
>>> stats.
>>>
>>> Btw, to
>>> help in
>>> narrowing
>>> down the
>>> actual
>>> problem
>>> case,
>>> the
>>> profiler
>>> could
>>> collect
>>> max
>>> times
>>> per RX
>>> message ID.
>>>
>>> Regards,
>>> Michael
>>>
>>> Am
>>> 12.05.24
>>> um 10:41
>>> schrieb
>>> Michael
>>> Geddes:
>>>
>>> I
>>> have
>>> a
>>> question
>>> for
>>> Michael
>>> B
>>> (or
>>> whoever)
>>> - I
>>> have
>>> a
>>> commit
>>> lined
>>> up
>>> that
>>> would
>>> add
>>> a
>>> bit
>>> of a
>>> time
>>> check
>>> to
>>> the
>>> poller
>>> loop.
>>> What
>>> do
>>> we
>>> expect
>>> the
>>> maximum time
>>> to
>>> execute
>>> a
>>> poller
>>> loop
>>> command
>>> should
>>> be?
>>>
>>> This
>>> is a
>>> rough
>>> idea
>>> (in
>>> ms)
>>> I
>>> have..
>>> based
>>> on
>>> nothing
>>> much
>>> really,
>>> so
>>> any
>>> ideas
>>> would
>>> be
>>> appreciated:
>>>
>>>
>>> int
>>> TardyMaxTime_ms(OvmsPoller::OvmsPollEntryType
>>> entry_type)
>>> {
>>>
>>>
>>> switch
>>> (entry_type)
>>>
>>> {
>>>
>>>
>>> case
>>> OvmsPoller::OvmsPollEntryType::Poll:
>>> return
>>> 80;
>>>
>>>
>>> case
>>> OvmsPoller::OvmsPollEntryType::FrameRx:
>>> return
>>> 30;
>>>
>>>
>>> case
>>> OvmsPoller::OvmsPollEntryType::FrameTx:
>>> return
>>> 20;
>>>
>>>
>>> case
>>> OvmsPoller::OvmsPollEntryType::Command:
>>> return
>>> 10;
>>>
>>>
>>> case
>>> OvmsPoller::OvmsPollEntryType::PollState:
>>> return
>>> 15;
>>> default:
>>> return
>>> 80;
>>>
>>> }
>>> }
>>>
>>> //.ichael
>>>
>>> On
>>> Mon,
>>> 6
>>> May
>>> 2024
>>> at
>>> 07:45,
>>> Michael
>>> Geddes
>>> <frog at bunyip.wheelycreek.net>
>>> wrote:
>>>
>>> I
>>> realise
>>> that
>>> I
>>> was
>>> only
>>> using
>>> the
>>> standard
>>> cable
>>> to
>>> test
>>> -
>>> which
>>> probably is
>>> not
>>> sufficient
>>> -
>>> I
>>> haven't
>>> looked
>>> closely
>>> at
>>> how
>>> the
>>> Leaf
>>> OBD
>>> to
>>> Db9
>>> cable
>>> is
>>> different
>>> from
>>> standard.
>>>
>>> Ah,
>>> my
>>> bad
>>> out
>>> the
>>> queue
>>> length.
>>> We
>>> are
>>> definitely
>>> queueing
>>> more
>>> messages
>>> though.
>>> From
>>> my
>>> log
>>> of
>>> when
>>> the
>>> overflow
>>> happened,
>>> the
>>> poller
>>> was
>>> in
>>> state
>>> 0
>>> which
>>> means
>>> OFF
>>> -
>>> ie
>>> nothing
>>> was
>>> being
>>> sent!!
>>>
>>> I'll
>>> look
>>> at
>>> the
>>> TX
>>> message
>>> thing
>>> -
>>> opt
>>> in
>>> sounds
>>> good
>>> -
>>> though
>>> it
>>> shouldn't
>>> be
>>> playing
>>> that
>>> much
>>> of
>>> a
>>> part
>>> here
>>> as
>>> the
>>> TXs
>>> are
>>> infrequent
>>> in
>>> this
>>> case
>>> (or
>>> zero
>>> when
>>> the
>>> leaf
>>> is
>>> off
>>> or driving)
>>> -
>>> On
>>> the
>>> ioniq
>>> 5
>>> when
>>> I'm
>>> using
>>> the
>>> HUD
>>> -
>>> I'm
>>> polling
>>> quite
>>> frequently
>>> -
>>> multiple
>>> times
>>> per
>>> second
>>> and
>>> that
>>> seems
>>> to
>>> be
>>> fine!.
>>>
>>> I
>>> did
>>> find
>>> an
>>> issue
>>> with
>>> the
>>> throttling ..
>>> but
>>> it
>>> would
>>> still
>>> mostly
>>> apply
>>> the
>>> throttling
>>> where
>>> it
>>> matters,
>>> so
>>> again,
>>> it
>>> shouldn't
>>> be
>>> the
>>> problem
>>> (also,
>>> we
>>> aren't
>>> transmitting
>>> in
>>> the
>>> leaf
>>> case).
>>>
>>> The
>>> change
>>> I
>>> made
>>> to
>>> the
>>> logging
>>> of
>>> RX
>>> messages
>>> showed
>>> how
>>> many
>>> in
>>> a
>>> row
>>> were
>>> dropped...
>>> and
>>> it
>>> was
>>> mostly
>>> 1
>>> only
>>> in
>>> a
>>> run
>>> -
>>> which
>>> means
>>> even
>>> if
>>> it
>>> is
>>> a
>>> short
>>> time
>>> between
>>> -
>>> that
>>> means
>>> that
>>> the
>>> drops
>>> are
>>> being
>>> interleaved
>>> by
>>> at
>>> least
>>> one
>>> success!
>>>
>>> Sooo..
>>> I'm
>>> still
>>> wondering
>>> what
>>> is
>>> going
>>> on.
>>> Some
>>> things
>>> I'm
>>> going
>>> to
>>> try:
>>>
>>> *
>>> If
>>> the
>>> number
>>> of
>>> messages
>>> on
>>> the
>>> Can
>>> bus
>>> (coming
>>> in
>>> through
>>> RX)
>>> means
>>> that
>>> the
>>> queue
>>> is
>>> slowly
>>> getting
>>> longer
>>> and
>>> not
>>> quite
>>> catching
>>> up,
>>> then
>>> making
>>> the
>>> queue
>>> longer
>>> will
>>> help
>>> it
>>> last
>>> longer...
>>> but
>>> only
>>> pushes
>>> the
>>> problem
>>> down
>>> the
>>> road.
>>>
>>>
>>> -
>>> Add
>>> 'current
>>> queue
>>> length'
>>> to
>>> the
>>> poller
>>> status
>>> information
>>> to
>>> see
>>> if
>>> this
>>> is
>>> indeed
>>> the
>>> case?
>>>
>>>
>>>
>>> -
>>> Add
>>> some
>>> kind
>>> of
>>> alert
>>> when
>>> the
>>> queue
>>> reaches
>>> a
>>> %
>>> full?
>>>
>>> *
>>> Once
>>> you
>>> start
>>> overflowing
>>> and
>>> getting
>>> overflow
>>> log
>>> messages,
>>> I
>>> wonder
>>> if
>>> this
>>> is
>>> then
>>> contributing
>>> to
>>> the
>>> problem.
>>>
>>>
>>> -
>>> Push
>>> the
>>> overflow
>>> logging
>>> into
>>> Poller
>>> Task
>>> which
>>> can
>>> look
>>> at
>>> how
>>> many
>>> drops
>>> occurred
>>> since
>>> last
>>> received
>>> item.
>>>
>>> *
>>> Split
>>> up
>>> the
>>> flags
>>> for
>>> the
>>> poller
>>> messages
>>> into
>>> 2:
>>>
>>>
>>> -
>>> Messages
>>> that
>>> are/could
>>> be
>>> happening
>>> in
>>> the
>>> TX/RX
>>> tasks
>>>
>>>
>>> -
>>> Other
>>> noisy
>>> messages
>>> that
>>> always
>>> happen
>>> in
>>> the
>>> poller
>>> task.
>>>
>>> Thoughts
>>> on
>>> what
>>> else
>>> we
>>> might
>>> measure
>>> to
>>> figure
>>> out
>>> what
>>> is
>>> going
>>> on?
>>>
>>> //.ichael
>>>
>>> On
>>> Sun,
>>> 5
>>> May
>>> 2024,
>>> 19:29
>>> Michael
>>> Balzer
>>> via
>>> OvmsDev,
>>> <ovmsdev at lists.openvehicles.com>
>>> wrote:
>>>
>>> Michael,
>>>
>>> the
>>> queue
>>> size
>>> isn't
>>> in
>>> bytes,
>>> it's
>>> in
>>> messages:
>>>
>>>
>>> *
>>> @param
>>> uxQueueLength
>>> The
>>> maximum
>>> number
>>> of
>>> items
>>> that
>>> the
>>> queue
>>> can
>>> contain.
>>> *
>>> *
>>> @param
>>> uxItemSize
>>> The
>>> number
>>> of
>>> bytes
>>> each
>>> item
>>> in
>>> the
>>> queue
>>> will
>>> require.
>>>
>>>
>>> Also,
>>> from
>>> the
>>> time
>>> stamps
>>> in
>>> Dereks
>>> log
>>> excerpt,
>>> there
>>> were
>>> quite
>>> some
>>> dropped
>>> frames
>>> in
>>> that
>>> time
>>> window
>>> --
>>> at
>>> least
>>> 23
>>> frames
>>> in
>>> 40
>>> ms,
>>> that's
>>> bad.
>>>
>>> Queue
>>> sizes
>>> are
>>> currently:
>>>
>>> CONFIG_OVMS_HW_CAN_RX_QUEUE_SIZE=60
>>> CONFIG_OVMS_VEHICLE_CAN_RX_QUEUE_SIZE=60
>>>
>>> The
>>> new
>>> poller
>>> now
>>> channels
>>> all
>>> TX
>>> callbacks
>>> through
>>> the
>>> task
>>> queue
>>> additionally
>>> to
>>> RX
>>> and
>>> commands.
>>> So
>>> setting
>>> the
>>> queue
>>> size
>>> to
>>> be
>>> larger
>>> than
>>> the
>>> CAN
>>> RX
>>> queue
>>> size
>>> seems
>>> appropriate.
>>>
>>> Nevertheless,
>>> an
>>> overflow
>>> with
>>> more
>>> than
>>> 60
>>> waiting
>>> messages
>>> still
>>> indicates
>>> some
>>> too
>>> long
>>> processing
>>> time
>>> in
>>> the
>>> vehicle
>>> task.
>>>
>>> TX
>>> callbacks
>>> previously
>>> were
>>> done
>>> directly
>>> in
>>> the
>>> CAN
>>> context,
>>> and
>>> no
>>> current
>>> vehicle
>>> overrides
>>> the
>>> empty
>>> default
>>> handler,
>>> so
>>> this
>>> imposed
>>> almost
>>> no
>>> additional
>>> overhead.
>>> By
>>> requiring
>>> a
>>> queue
>>> entry
>>> for
>>> each
>>> TX
>>> callback,
>>> this
>>> feature
>>> now
>>> has
>>> a
>>> potentially
>>> high
>>> impact
>>> for
>>> all
>>> vehicles.
>>> If
>>> passing
>>> these
>>> to
>>> the
>>> task
>>> is
>>> actually
>>> necessary,
>>> it
>>> needs
>>> to
>>> become
>>> an
>>> opt-in
>>> feature,
>>> so
>>> only
>>> vehicles
>>> subscribing
>>> to
>>> the
>>> callback
>>> actually
>>> need
>>> to
>>> cope
>>> with
>>> that
>>> additional
>>> load
>>> &
>>> potential
>>> processing
>>> delays
>>> involved.
>>>
>>> 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.openvehicles.com
>> http://lists.openvehicles.com/mailman/listinfo/ovmsdev
>>
>>
>> _______________________________________________
>> OvmsDev mailing list
>> OvmsDev at 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 at 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openvehicles.com/pipermail/ovmsdev/attachments/20240618/1a1f9f3e/attachment-0001.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: OpenPGP_signature.asc
Type: application/pgp-signature
Size: 203 bytes
Desc: OpenPGP digital signature
URL: <http://lists.openvehicles.com/pipermail/ovmsdev/attachments/20240618/1a1f9f3e/attachment-0001.sig>