<html><head><meta http-equiv="Content-Type" content="text/html; charset=utf-8"></head><body style="word-wrap: break-word; -webkit-nbsp-mode: space; line-break: after-white-space;" class="">Strange. Connected to my car, and from ovms_shell asked for ‘module tasks’:<div class=""><br class=""></div><blockquote style="margin: 0 0 0 40px; border: none; padding: 0px;" class=""><div class=""><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class="">ovms> module tasks</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class="">...</span></font></div></div><div class=""><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class="">Vehicle Response:</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> Number of Tasks = 17 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFAFBF4 1 Blk esp_timer 400 656 4096 35944 6442122956 0 22 2%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFBDBBC 2 Blk eventTask 440 1928 4608 140 0 0 0 20 0%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFBFF00 3 Blk OVMS Events 444 3404 8192 70816 0 21092 1 5 9%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFC3300 4 Blk OVMS DukTape 460 9548 12288 188 0 31020 1 3 12%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFC4FF4 5 Blk OVMS CanRx 432 832 2048 3144 0 32072 0 23 120%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFC5D3C 6 Blk ipc0 392 504 1024 7804 0 0 0 24 2%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFC6340 7 Blk ipc1 396 444 1024 12 0 0 1 24 0%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFC8194 10 Rdy IDLE0 416 512 1024 0 0 0 0 0 362%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFC872C 11 Rdy IDLE1 408 504 1024 0 0 0 1 0 387%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFC94C4 12 Blk Tmr Svc 352 912 3072 88 0 0 0 20 1%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFC6794 17 Blk tiT 504 2536 3072 7668 0 0 * 18 6%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFCF3E0 18 Blk OVMS SIMCOM 460 2412 4096 40 0 3892 1 5 1%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFD0C10 19 Blk wifi 460 2716 3584 36356 0 2912 0 22 23%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFDBD70 20 Blk OVMS Vehicle 460 1308 6144 0 0 2336 1 10 95%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFDF0FC 21 Rdy OVMS Console 488 1736 6144 0 0 20 1 5 0%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFDF64C 22 Blk mdns 472 1576 4096 108 0 0 0 1 1%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFE38F0 35 Rdy OVMS NetMan 1384 2984 8192 144 25180 5004 1 5 3%</span></font></div></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""><br class=""></span></font></div><div class=""><div class=""><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class="">ovms> module tasks</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class="">...</span></font></div></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class="">Vehicle Response:</span></font></div></div><div class=""><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> Number of Tasks = 17 Stack: Now Max Total Heap 32-bit SPIRAM C# PRI CPU%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFAFBF4 1 Blk esp_timer 400 656 4096 35944 6442122956 0 22 0%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFBDBBC 2 Blk eventTask 440 1928 4608 140 0 0 0 20 0%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFBFF00 3 Blk OVMS Events 444 3404 8192 70816 0 21092 1 5 0%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFC3300 4 Blk OVMS DukTape 460 9548 12288 188 0 23712 1 3 1%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFC4FF4 5 Blk OVMS CanRx 432 832 2048 3144 0 32072 0 23 4%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFC5D3C 6 Blk ipc0 392 504 1024 7804 0 0 0 24 0%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFC6340 7 Blk ipc1 396 444 1024 12 0 0 1 24 0%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFC8194 10 Rdy IDLE0 416 512 1024 0 0 0 0 0 96%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFC872C 11 Rdy IDLE1 408 504 1024 0 0 0 1 0 95%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFC94C4 12 Blk Tmr Svc 352 912 3072 88 0 0 0 20 0%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFC6794 17 Blk tiT 504 2536 3072 7668 0 0 * 18 0%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFCF3E0 18 Blk OVMS SIMCOM 668 2412 4096 40 0 3892 1 5 0%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFD0C10 19 Blk wifi 460 2716 3584 36356 0 2912 0 22 0%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFDBD70 20 Blk OVMS Vehicle 460 1308 6144 0 0 2336 1 10 3%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFDF0FC 21 Blk OVMS Console 552 1736 6144 0 0 20 1 5 0%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFDF64C 22 Blk mdns 472 1576 4096 108 0 0 0 1 0%</span></font></div><div class=""><font face="Andale Mono" class=""><span style="font-style: normal; font-size: 14px;" class=""> 3FFE38F0 35 Rdy OVMS NetMan 1896 3240 8192 400 25180 5392 1 5 0%</span></font></div></div></blockquote><div class=""><div><br class=""></div><div>The second one is what I normally see, but the first is bizarre. Any idea what the time frame for the CPU% is?</div><div><br class=""></div><div>Regards, Mark</div><div><br class=""></div><div><blockquote type="cite" class=""><div class=""><div text="#000000" bgcolor="#FFFFFF" class=""><blockquote type="cite" class=""><blockquote type="cite" class=""><blockquote type="cite" class=""><div class=""><div class=""><blockquote type="cite" class=""><div class=""><div class=""><blockquote type="cite" class="">
<blockquote type="cite" class=""></blockquote></blockquote><blockquote type="cite" class=""><blockquote type="cite" class=""></blockquote></blockquote></div></div></blockquote><blockquote type="cite" class=""><div class=""><div class=""><blockquote type="cite" class=""><blockquote type="cite" class=""></blockquote></blockquote></div></div></blockquote></div></div></blockquote><blockquote type="cite" cite="mid:BFED773E-0CFE-4EBB-A3B4-9B44FE4A783D@webb-johnson.net" class=""><div class=""><div class=""><blockquote type="cite" class=""><div class=""><div class=""><blockquote type="cite" class=""><blockquote type="cite" class=""></blockquote></blockquote></div></div></blockquote></div></div></blockquote></blockquote><blockquote type="cite" cite="mid:7a3bb65a-9a54-6f67-c794-4b6f8d4ca2b8@expeedo.de" class=""><blockquote type="cite" cite="mid:BFED773E-0CFE-4EBB-A3B4-9B44FE4A783D@webb-johnson.net" class=""><div class=""><div class=""><blockquote type="cite" class=""><div class=""><div class=""><blockquote type="cite" class=""><blockquote type="cite" class=""></blockquote></blockquote></div></div></blockquote></div></div></blockquote></blockquote></blockquote><blockquote type="cite" cite="mid:76a60138-8d46-0703-d9d0-6b2f5daa20da@expeedo.de" class=""><blockquote type="cite" cite="mid:7a3bb65a-9a54-6f67-c794-4b6f8d4ca2b8@expeedo.de" class=""><blockquote type="cite" cite="mid:BFED773E-0CFE-4EBB-A3B4-9B44FE4A783D@webb-johnson.net" class=""><div class=""><div class=""><blockquote type="cite" class=""><div class=""><div class=""><blockquote type="cite" class=""><blockquote type="cite" class=""></blockquote></blockquote></div></div></blockquote></div></div></blockquote></blockquote></blockquote></div></div></blockquote><div class=""><div text="#000000" bgcolor="#FFFFFF" class=""><blockquote type="cite" cite="mid:7a3bb65a-9a54-6f67-c794-4b6f8d4ca2b8@expeedo.de" class=""><blockquote type="cite" cite="mid:BFED773E-0CFE-4EBB-A3B4-9B44FE4A783D@webb-johnson.net" class=""><div class=""><div class=""><blockquote type="cite" class=""><div class=""><div class=""><blockquote type="cite" class=""><blockquote type="cite" class="">On 8 Sep 2019, at
5:43 PM, Michael Balzer <<a href="mailto:dexter@expeedo.de" class="" moz-do-not-send="true">dexter@expeedo.de</a>>
wrote:<br class="">
<br class="">
I've pushed some modifications and improvements
to (hopefully) fix the timer issue or at least
be able to debug it.<br class="">
<br class="">
Some sdkconfig changes are necessary.<br class="">
<br class="">
The build including these updates is on my edge
release as 3.2.002-258-g20ae554b.<br class="">
<br class="">
Btw: the network restart strategy seems to
mitigate issue #241; I've seen a major drop on
record repetitions on my server since the
rollout.<br class="">
<br class="">
<br class="">
commit 99e4e48bdd40b7004c0976f51aba9e3da4ecab53<br class="">
<br class="">
Module: add per task CPU usage statistics,
add task stats history records<br class="">
<br class="">
To enable CPU usage statistics, apply the
changes to sdkconfig<br class="">
included. The CPU usage shown by the commands
is calculated against<br class="">
the last task status retrieved (or system
boot).<br class="">
<br class="">
Command changes:<br class="">
- "module tasks" -- added CPU (core) usage in
percent per task<br class="">
<br class="">
New command:<br class="">
- "module tasks data" -- output task stats in
history record form<br class="">
<br class="">
New config:<br class="">
- [module] debug.tasks -- yes (default) =
send task stats every 5 minutes<br class="">
<br class="">
New history record:<br class="">
- "*-OVM-DebugTasks" v1:
<taskcnt,totaltime> + per task:<br class="">
<tasknum,name,state,stack_now,stack_max,stack_total,<br class="">
heap_total,heap_32bit,heap_spi,runtime><br class="">
Note: CPU core use percentage = runtime /
totaltime<br class="">
<br class="">
commit 950172c216a72beb4da0bc7a40a46995a6105955<br class="">
<br class="">
Build config: default timer service task
priority raised to 20<br class="">
<br class="">
Background: the FreeRTOS timer service shall
only be used for very<br class="">
short and non-blocking jobs. We delegate
event processing to our<br class="">
events task, anything else in timers needs
to run with high<br class="">
priority.<br class="">
<br class="">
commit 31ac19d187480046c16356b80668de45cacbb83d<br class="">
<br class="">
DukTape: add build config for task priority,
default lowered to 3<br class="">
<br class="">
Background: the DukTape garbage collector
shall run on lower<br class="">
priority than tasks like SIMCOM &
events<br class="">
<br class="">
commit e0a44791fbcfb5a4e4cad24c9d1163b76e637b4f<br class="">
<br class="">
Server V2: use esp_log_timestamp for timeout
detection,<br class="">
add timeout config, limit data records
& size per second<br class="">
<br class="">
New config:<br class="">
- [server.v2] timeout.rx -- timeout in
seconds, default 960<br class="">
<br class="">
commit 684a4ce9525175a910040f0d1ca82ac212fbf5de<br class="">
<br class="">
Notify: use esp_log_timestamp for creation
time instead of monotonictime<br class="">
to harden against timer service starvation
/ ticker event drops<br class="">
<br class="">
<br class="">
Regards,<br class="">
Michael<br class="">
<br class="">
<br class="">
Am 07.09.19 um 10:55 schrieb Michael Balzer:<br class="">
<blockquote type="cite" class="">I think the
RTOS timer service task starves. It's running
on core 0 with priority 1.<br class="">
<br class="">
Taks on core 0 sorted by priority:<br class="">
<br class="">
Number of Tasks = 20 Stack: Now Max
Total Heap 32-bit SPIRAM C# PRI<br class="">
3FFC84A8 6 Blk ipc0 388 500
1024 7788 0 0 0 24<br class="">
3FFC77F0 5 Blk OVMS CanRx 428 428
2048 3052 0 31844 0 23<br class="">
3FFAFBF4 1 Blk esp_timer 400 656
4096 35928 644 25804 0 22<br class="">
3FFD3240 19 Blk wifi 460 2716
3584 43720 0 20 0 22<br class="">
3FFC03C4 2 Blk eventTask 448 1984
4608 104 0 0 0 20<br class="">
3FFC8F14 17 Blk tiT 500 2308
3072 6552 0 0 * 18<br class="">
3FFE14F0 26 Blk OVMS COrx 456 456
4096 0 0 0 0 7<br class="">
3FFE19D4 27 Blk OVMS COwrk 476 476
3072 0 0 0 0 7<br class="">
3FFCBC34 12 Blk Tmr Svc 352 928
3072 88 0 0 0 1<br class="">
3FFE7708 23 Blk mdns 468 1396
4096 108 0 0 0 1<br class="">
<br class="">
I don't think it's our CanRx, as that only
fetches and queues CAN frames, the actual work
is done by the listeners. The CO tasks only
run for CANopen jobs, which are few for normal
operation.<br class="">
<br class="">
That leaves the system tasks, with main
suspect -once again- the wifi blob.<br class="">
<br class="">
We need to know how much CPU time the tasks
actually use now. I think I saw some option
for this in the FreeRTOS config.<br class="">
<br class="">
Regards,<br class="">
Michael<br class="">
<br class="">
<br class="">
Am 06.09.19 um 23:15 schrieb Michael Balzer:<br class="">
<blockquote type="cite" class="">The
workaround is based on the monotonictime
being updated per second, as do the history
record offsets.<br class="">
<br class="">
Apparently, that mechanism doesn't work
reliably. That may be an indicator for some
bigger underlying issue.<br class="">
<br class="">
Example log excerpt:<br class="">
<br class="">
2019-09-06 22:07:48.126919 +0200 info main:
#173 C MITPROHB rx msg h
964,0,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:09:03.089031 +0200 info main:
#173 C MITPROHB rx msg h
964,-10,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:09:05.041574 +0200 info main:
#173 C MITPROHB rx msg h
964,-20,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:09:05.052644 +0200 info main:
#173 C MITPROHB rx msg h
964,-30,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:09:05.063617 +0200 info main:
#173 C MITPROHB rx msg h
964,-49,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:09:05.077527 +0200 info main:
#173 C MITPROHB rx msg h
964,-59,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:09:05.193775 +0200 info main:
#173 C MITPROHB rx msg h
964,-70,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:09:13.190645 +0200 info main:
#173 C MITPROHB rx msg h
964,-80,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:09:22.077994 +0200 info main:
#173 C MITPROHB rx msg h
964,-90,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:09:54.590300 +0200 info main:
#173 C MITPROHB rx msg h
964,-109,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:11:10.127054 +0200 info main:
#173 C MITPROHB rx msg h
964,-119,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:11:16.794200 +0200 info main:
#173 C MITPROHB rx msg h
964,-130,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:11:22.455652 +0200 info main:
#173 C MITPROHB rx msg h
964,-140,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:12:49.423412 +0200 info main:
#173 C MITPROHB rx msg h
964,-150,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:12:49.442096 +0200 info main:
#173 C MITPROHB rx msg h
964,-169,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:12:49.461941 +0200 info main:
#173 C MITPROHB rx msg h
964,-179,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:14:39.828133 +0200 info main:
#173 C MITPROHB rx msg h
964,-190,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:14:39.858144 +0200 info main:
#173 C MITPROHB rx msg h
964,-200,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:14:52.020319 +0200 info main:
#173 C MITPROHB rx msg h
964,-210,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:14:54.452637 +0200 info main:
#173 C MITPROHB rx msg h
964,-229,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:15:12.613935 +0200 info main:
#173 C MITPROHB rx msg h
964,-239,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:15:35.223845 +0200 info main:
#173 C MITPROHB rx msg h
964,-250,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:16:09.255059 +0200 info main:
#173 C MITPROHB rx msg h
964,-260,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:17:31.919754 +0200 info main:
#173 C MITPROHB rx msg h
964,-270,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:19:23.366267 +0200 info main:
#173 C MITPROHB rx msg h
964,-289,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:21:57.344609 +0200 info main:
#173 C MITPROHB rx msg h
964,-299,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:23:40.082406 +0200 info main:
#31 C MITPROHB rx msg h
964,-1027,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
2019-09-06 22:25:58.061883 +0200 info main:
#31 C MITPROHB rx msg h
964,-1040,RT-BAT-C,5,86400,2,1,3830,3795,3830,-10,25,25,25,0<br class="">
<br class="">
<br class="">
This shows the ticker was only run 299 times
from 22:07:48 to 22:21:57.<br class="">
<br class="">
After 22:21:57 the workaround was triggered
and did a reconnect. Apparently during that
network reinitialization of 103 seconds, the
per second ticker was run 628 times.<br class="">
<br class="">
That can't be catching up on the event
queue, as that queue has only 20 slots. So
something strange is going on here.<br class="">
<br class="">
Any ideas?<br class="">
<br class="">
Regards,<br class="">
Michael<br class="">
<br class="">
<br class="">
Am 06.09.19 um 08:04 schrieb Michael Balzer:<br class="">
<blockquote type="cite" class="">Mark &
anyone else running a V2 server,<br class="">
<br class="">
as most cars don't send history records,
this also needs the change to the server I
just pushed, i.e. server version 2.4.2.<br class="">
<br class="">
<a href="https://github.com/openvehicles/Open-Vehicle-Monitoring-System/commits/master" class="" moz-do-not-send="true">https://github.com/openvehicles/Open-Vehicle-Monitoring-System/commits/master</a>
<<a href="https://github.com/openvehicles/Open-Vehicle-Monitoring-System/commits/master" class="" moz-do-not-send="true">https://github.com/openvehicles/Open-Vehicle-Monitoring-System/commits/master</a>><br class="">
<br class="">
Regards,<br class="">
Michael<br class="">
<br class="">
<br class="">
Am 05.09.19 um 19:55 schrieb Michael
Balzer:<br class="">
<blockquote type="cite" class="">I've
pushed the nasty workaround: the v2
server checks for no RX over 15 minutes,
then restarts the network (wifi &
modem) as configured for autostart.<br class="">
<br class="">
Rolled out on my server in edge as
3.2.002-237-ge075f655.<br class="">
<br class="">
Please test.<br class="">
<br class="">
Regards,<br class="">
Michael<br class="">
<br class="">
<br class="">
Am 05.09.19 um 01:58 schrieb Mark
Webb-Johnson:<br class="">
<blockquote type="cite" class="">
<blockquote type="cite" class="">Mark,
you can check your server logs for
history messages with ridiculous
time offsets:<br class="">
[sddexter@ns27 server]$ cat
log-20190903 | egrep "rx msg h
[0-9]+,-[0-9]{4}" | wc -l<br class="">
455283<br class="">
</blockquote>
<br class="">
I checked my logs and see 12 vehicles
showing this. But, 2 only show this
for a debugcrash log (which is
expected, I guess, if the time is not
synced at report time). I’ve got 4
cars with the offset > 10,000.<br class="">
<br class="">
Regards, Mark.<br class="">
<br class="">
<blockquote type="cite" class="">On 4
Sep 2019, at 4:45 AM, Michael Balzer
<<a href="mailto:dexter@expeedo.de" class="" moz-do-not-send="true">dexter@expeedo.de</a>
<<a href="mailto:dexter@expeedo.de" class="" moz-do-not-send="true">mailto:dexter@expeedo.de</a>>>
wrote:<br class="">
<br class="">
Everyone,<br class="">
<br class="">
I've pushed a change that needs some
testing.<br class="">
<br class="">
I had the issue myself now parking
at a certain distance from my garage
wifi AP, i.e. on the edge of "in",
after wifi had been disconnected for
some hours, and with the module
still connected via modem. The wifi
blob had been trying to connect to
the AP for about two hours.<br class="">
<br class="">
As seen before, the module saw no
error, just the server responses and
commands stopped coming in. I
noticed the default interface was
still "st1" despite wifi having been
disconnected and modem connected.
The DNS was also still configured
for my wifi network, and the
interface seemed to have an IP
address -- but wasn't pingable from
the wifi network.<br class="">
<br class="">
A power cycle of the modem solved
the issue without reboot. So the
cause may be in the modem/ppp
subsystem, or it may be related (in
some weird way) to the default
interface / DNS setup.<br class="">
<br class="">
More tests showed the default
interface again/still got set by the
wifi blob itself at some point,
overriding our modem prioritization.
The events we didn't handle up to
now were "sta.connected" and
"sta.lostip", so I added these, and
the bug didn't show up again since
then. That doesn't mean anything, so
we need to test this.<br class="">
<br class="">
The default interface really
shouldn't affect inbound packet
routing of an established
connection, but there always may be
strange bugs lurking in those libs.<br class="">
<br class="">
The change also reimplements the
wifi signal strength reading, as the
tests also showed that still wasn't
working well using the CSI callback.
It now seems to be much more
reliable.<br class="">
<br class="">
Please test & report. The single
module will be hard to test, as the
bug isn't reproducable easily, but
you can still try if wifi / modem
transitions work well.<br class="">
<br class="">
Mark, you can check your server logs
for history messages with ridiculous
time offsets:<br class="">
[sddexter@ns27 server]$ cat
log-20190903 | egrep "rx msg h
[0-9]+,-[0-9]{4}" | wc -l<br class="">
455283<br class="">
The bug now severely affects the V2
server performance, as the server is
single threaded and doesn't scale
very well to this kind of bulk data
bursts, especially when coming from
multiple modules in parallel. So we
really need to solve this now. Slow
reactions or connection drops from
my server lately have been due to
this bug. If this change doesn't
solve it, we'll need to add some
reboot trigger on "too many server
v2 notification retransmissions" --
or maybe a modem power cycle will
do, that wouldn't discard the data.<br class="">
<br class="">
Thanks,<br class="">
Michael<br class="">
<br class="">
<br class="">
Am 03.09.19 um 07:46 schrieb Mark
Webb-Johnson:<br class="">
<blockquote type="cite" class="">No
problem. We can hold. I won’t
commit anything for the next few
days (and agree to hold-off on
Markos’s pull). Let me know when
you are ready.<br class="">
<br class="">
Regards, Mark.<br class="">
<br class="">
<blockquote type="cite" class="">On
3 Sep 2019, at 1:58 AM, Michael
Balzer <<a href="mailto:dexter@expeedo.de" class="" moz-do-not-send="true">dexter@expeedo.de</a>>
<<a href="mailto:dexter@expeedo.de" class="" moz-do-not-send="true">mailto:dexter@expeedo.de</a>>
wrote:<br class="">
<br class="">
Mark, please wait.<br class="">
<br class="">
I may just have found the cause
for issue #241, or at least
something I need to investigate
before releasing.<br class="">
<br class="">
I need to dig into my logs
first, and try something.<br class="">
<br class="">
Regards,<br class="">
Michael<br class="">
<br class="">
<br class="">
Am 02.09.19 um 12:23 schrieb
Michael Balzer:<br class="">
<blockquote type="cite" class="">Nothing
open from my side at the
moment.<br class="">
<br class="">
I haven't had the time to look
in to Markos pull request, but
from a first check also think
that's going too deep to be
included in this release.<br class="">
<br class="">
Regards,<br class="">
Michael<br class="">
<br class="">
<br class="">
Am 02.09.19 um 04:15 schrieb
Mark Webb-Johnson:<br class="">
<blockquote type="cite" class="">I think it is well
past time for a 3.2.003
release. Things seems table
in edge (although some
things only partially
implemented).<br class="">
<br class="">
Anything people want to
include at the last minute,
or can we go ahead and
build?<br class="">
<br class="">
Regards, Mark.<br class="">
<br class="">
</blockquote>
</blockquote>
</blockquote>
</blockquote>
</blockquote>
</blockquote>
</blockquote>
</blockquote>
</blockquote>
</blockquote>
</blockquote>
</blockquote>
</div>
</div>
</blockquote>
</div>
</div>
</blockquote>
<br class="">
<pre class="moz-signature" cols="144">--
Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal
Fon 02333 / 833 5735 * Handy 0176 / 206 989 26</pre></blockquote></div></div></div></div></body></html>