jscalls taking too long

[Stuart]

The first thing to say is that I think AnnexRDS is completely brilliant. But I seem to be pushing to the limits in my use of html and javascriot. I have been having some unexplained and unreported resets with a project. No error is trapped. The problem seemingly arises only when the program is maintaining a web page, using html to write a table and jscalls to update the data in the table as it changes. The program scans the hardware it is monitoring once every few seconds to detect the hardware state, and various updates take place including to the web page.

I noticed that some of the jscalls were taking much longer than the norm, so I began to time the calls.

All innerHTML text changes are routed through a single sub, which can measure the jscall duration. As measured this way, the initial duration might be 32mS. However, most calls take a bit longer and some calls take much longer (over a second in the example below, and I have seen several seconds) with the maximum becoming progressively longer, so I suspect something untoward is happening. The code reports the duration if it exceeds the previous longest.

This is part of a recent log, from startup, with just the relevant entries showing the longest call up to that point, to show the problem. Most updates are a short string representing numerics, some are messages of perhaps 20 bytes.

Code: [Local Link Removed for Guests]

[11/04/24-21:16:35 _6  ch SRpZhCb:CpbU] draw web table        <- empty table drawn, then initial updates
 - timestamp   - version - system state - function performed 
[11/04/24-21:16:35 _6  ch SRpZhCb:CpbU] max mS:32 hwtemp               )
                                                  - html id -
[11/04/24-21:16:35 _6  ch SRpZhCb:CpbU] max mS:33 rettemp              )  updates as things change
[11/04/24-21:16:35 _6  ch SRpZhCb:CpbU] max mS:34 retmessage           )
[11/04/24-21:16:35 _6  ch SRpZhCb:CpbU] max mS:35 localexttempmessage  )
[11/04/24-21:16:41 _6  ch SRpZhCb:CpbU] max mS:151 scandur 
[11/04/24-21:21:12 _6  ch SRpZhCb:CpbU] max mS:191 clock     <- regular clock updates
[11/04/24-21:22:13 _6  ch SRpZhCb:CpbU] max mS:211 rettemp
[11/04/24-21:24:57 _6  ch SRPZhCB:CpBU] max mS:251 flowtemp
[11/04/24-21:26:54 _6  ch SRPZhCB:CpBU] max mS:271 localexttemp
[11/04/24-21:27:33 _6  ch SRPZhCb:CpbU] max mS:291 flowtemp
[11/04/24-22:06:59 _6  ch SRpZhCb:CpbU] max mS:371 rettemp           progressive increase in max time 
[11/04/24-22:33:03 _6   SRPzhcb:CpBU] max mS:531 clock               for a function that initially only takes 32mS
[11/04/24-22:46:21 _6   SRpzhcb:CpBU] max mS:551 elapsed
[11/04/24-23:00:46 _6   SRpzhcb:CpBU] max mS:552 elapsed
[11/04/24-23:07:23 _6   SRpZhcb:CpBU] max mS:652 clock
[12/04/24-04:47:18 _6   SRpzhcb:CpBU] max mS:672 localexttemp
[12/04/24-09:20:16 _6  ch SRPZhCb:CpbU] max mS:911 localexttemp
[12/04/24-10:36:50 _6   SRpzhcb:CpbU] max mS:1072 clock
[12/04/24-12:38:31 _6   SRpzhcb:CpbU] max mS:1073 clock
[13/04/24-06:38:32 _6  ch SRPZhCB:CpBU] max mS:1095 clock
[13/04/24-06:38:37 _6  ch SRPZhCB:CpBU] html reload [loadhtml] table <- first look in the morning
[13/04/24-06:38:37 _6  ch SRPZhCB:CpBU] draw web table 
immediately followed by:
[13/04/24-49.4 _6  ch SRPZhCB:CpBU] max mS:1096 clock        <- the 49.4 is likely to be temperature data, in the wrong place
[13/04/24-49.4 _6  ch SRPZhCB:CpBU] max mS:1120 flowtemp        suggesting some sort of variable overwriting
at which point it immediately rebooted

To change the web page, the code makes e.g. this call:

Code: [Local Link Removed for Guests]

   change_text "flowtemp", flow_temp$, last_flow_temp$, textcolour$

to this SUB

Code: [Local Link Removed for Guests]

sub change_text (targ$,newtext$,last_newtext$,colour$)
   if (last_newtext$ = newtext$) then exit sub 
   in_millis = millis
   last_newtext$ = newtext$  'save value via pass-by-name
   jscall |_$("|+targ$+|").innerHTML ="| + newtext$ +| "|
   if colour$ <> null$ then jscall |document.getElementById("|+targ$+|").style.color = "|+colour$+|";|
   scan_duration = millis - in_millis
   if scan_duration>max_scan_duration then max_scan_duration=scan_duration:timestamp "max mS:"+str$(max_scan_duration)
   end sub

I'm using 1.52.4 on an M5Tough with lots of ram and flash, one gpio is used for temperatures and all the other i/o is via an i2c board and the tft. The same problems are seen with both Firefox and Chrome on Ubuntu and Safari on Android.

The core question therefore is: why would jscalls occasionally take progressively longer than the norm, sometimes much longer, and possibly linked with unexplained program restarts? Would the restarts be related to the data corruption noted in the last two lines of the log?

Stuart

[cicciocb]

Very probably you are sending too much messages in a short time using JSCALL.
In particular, in your routine "change_text" you do even 2 JSCALL (if colour$ <> null$).

The best rule is the following :
limits the HTML, CSS, JSCALL, ... at no more than 5 per second.
limit the use of wlog ... it should be used only for debug at no more than 5 per second.
All these commands are buffered and put into a stack ... sending too much messages can fill the stack and go out of memory -> crash.
If you want log all the time, use serial port or udp communication
Check the ramfree regularly (use ramfree(1) because it is the real RAM that the module use internally) to see if there is a memory leak
Try to reduce the number of calls ... for example, in your routine, you could just do a single JSCALL like that :

Code: [Local Link Removed for Guests]

sub change_text (targ$,newtext$,last_newtext$,colour$)
   if (last_newtext$ = newtext$) then exit sub 
   in_millis = millis
   last_newtext$ = newtext$  'save value via pass-by-name
   js$ = |_$("|+targ$+|").innerHTML ="| + newtext$ +| ";|
   if colour$ <> null$ then js$ = js$ + |document.getElementById("|+targ$+|").style.color = "|+colour$+|";|
   jscall js$
   scan_duration = millis - in_millis
   if scan_duration>max_scan_duration then max_scan_duration=scan_duration:timestamp "max mS:"+str$(max_scan_duration)
end sub

Try also to refresh the browser (using F5) to see if the delay comes from the browser itself.

[Stuart]

Good points, but I did consider overload, and calls are minimised. Will combine the colour update as you suggest. Generally not more than two or three jscalls each 3 second cycle, and rarely more than a couple of timestamps each cycle, if any, except at startup though there are no ill effects then. Ramfree(1) was around 170k +/- 2k all the time under 1.52.4. Under 1.52.6BLE (just installed) I see it is now ~68k, a bit surprising. Main logging is to udp. It is the over-writing that makes me suspicious: getting a temperature when it should be a time.

[cicciocb]

Don't use the version with BLE if you don't really need as it "eats" a lot of RAM even if not used.

You should try to follow regularly the ramfree(1) and see if the memory goes down slowly.
Maybe there is a memory leak somewhere to fix ...

[cicciocb]

What are you using for the temperature ?
DS18B20?

[Stuart]

1: I studied the ramfree(1) on 1.52.4 and it was pretty stable (170k +/- 2k) so I didn't conclude there was likely a leak.
2: There wasn't a BLE version of 1.52.4. I tried the new BLE version of .6 just to see if BLE might be useful, I'll revert for now.
3: Temperature sensors are indeed db18B20. Four sensors on a single pin. Initiate conversion on one cycle and read the values next time round and initiate the next. Seems very reliable, some errors but quite rare.

[Stuart]

Reverting to 1.52.6 non-BLE puts ramfree(1) back to around 168k as with .4
I can hardly believe how simple and reliable the OTA thing is!

[cicciocb]

Hi Stuart,
if you are able to send me a little snippet that reproduce the problem I'll try to investigate on that issue

[Stuart]

Interestingly, while the calls are still sometimes taking a while (highest during the last 50 hours is 559mS), since I installed 1.52.6 there haven't been any resets. I can live with delays to calls as they don't affect anything in themselves, it is the resets that were the problem. I will leave it running untouched doing its job and see what happens.

I'll see if I can make a test setup for the jscalls on my development machine.

[Stuart]

1.52.7 seems to have reduced the jscall time. Highest recently was 127mS. I just started a 48 hour test to see if my restart problem is solved. I tried to understand the page source but not a chance!

Interestingly, when accessing the system from Firefox and Chrome on the same laptop the config 'menu bar disabled' is obeyed, but accessing at the same time from Firefox on Android, it isn't and I get a menu bar.