low memory issues with a multicock variant

I am attempting to build my ultimate multiclock style watch which is a combination of 3 of my clocks, namely "stepo", "waypointer" and "walkers clock". Each uses an arrayBuffer for the display so I need to be careful not to have any memory leaks or bad code.

Each watch face will have an init() function to create any resources and a freeResource() function to set all the variables to undefined.

(() => {
  function getFace(){
    var buf1;
    // desclare variables

    function init() {
      buf1 = Graphics.createArrayBuffer(160,160,1, {msb:true});
      // etc
    }

    function freeResources() {
      buf1 = undefined;
      // etc
    }

    // other functions as required
    return {init:init, freeResources:freeResources, startTimer:startTimer, stopTimer:stopTimer,
            onButtonShort:onButtonShort, onButtonLong:onButtonLong};
  }
  return getFace;
})();

When switching watch faces...

function stopdraw() {
  face.stopTimer();
  face.freeResources();
}

function startdraw() {
  Bangle.drawWidgets();
  face.init();
  face.startTimer();
}

function setButtons(){

  function nextFace(){
    iface += 1
    iface = iface % FACES.length;
    stopdraw();
    face = FACES[iface]();
    g.clear();
    g.reset();
    startdraw();
  }

Everything works fine for the first cycle through the watch faces. But within a few minutes I get a RED MEMORY_LOW warning at the bottom of the watch face. All the individual Apps work without memory problems.

Anyone any suggestions on if the approach should work and whre to look for memory leaks.

Hugh

Tue 2021.03.09

Hi Hugh,

Has an attempt to review the amount of 'Free' memory been tracked just after your init() functions to determine whether resources from memory are released after each task?

Maybe try printing inside a setInterval() and monitor?

http://www.espruino.com/Reference#l_process_memory

process.memory();

process.memory().free;

I also noticed the use of timers. Any chance one is still running, say for instance that keeps
creating objects? Snippet below that may be entered into L-Hand WebIDE console to view:

console.log(global["\xFF"].timers); //nice, less info

trace(global["\xFF"].timers); //full info

As @Robin says, it's worth checking for timers (and also watches - with console.log(global["\xFF"].watches);).

Ideally dump them with no watch face loaded, then load the watch face, unload it, and see if anything else is there.

One option is to use dump() - you'll have to ignore the second half of the code (which is just the bootloader) but the first half is a reconstruction of what is in RAM. Run it as suggested above, then 'diff' the two results and see what is different.

Just a note on freeResources - you don't have to set any of the variables you defined inside your function to undefined. As long as you don't reference the function from anywhere else, everything inside it will be freed automatically.

However the trick is ensuring that you're really not referencing that function from anywhere!

I tracked it down. See comments below.

function startdraw() {
  Bangle.drawWidgets();
  ///face.init();   // No as startDraw() will be called when LCD comes on again
  face.startTimer();
}
function setButtons(){
  function nextFace(){
    iface += 1
    iface = iface % FACES.length;
    stopdraw();
    face = FACES[iface]();
    face.init();   //  only call init() when switching faces 
    g.clear();
    g.reset();
    startdraw();
  }

the standard code for stopping / starting the draw/timers

Bangle.on('lcdPower',function(on) {
  if (on) {
    startdraw();
  } else {
    stopdraw();
  }
});

I do however have an odd performance issue with one of the Apps.

I have a compass app based on the Magnav code. I use the same compass code in Waypointer and Arrow. All of these compass apps start to run slow after a while and become unresponsive to BTN3 presses. I have been trying to track down the issue.

I am wondering if the following approach is an indicator of performance.
Set a timer for a known time
Record the time using getTime
Then check that the time against the expected time.

    
    function startTimer() {
      draw();
      readCompass();
      intervalRefSec = setInterval(readCompass, 200);
      tPerf = getTime();
      intervalPerf = setInterval(perfCheck, 1000);
    }


    function perfCheck() {
      var tNow  = getTime();
      var tDiff = 1000*(tNow - tPerf) - 1000;
      tPerf = tNow;
      console.log("perf=" + tDiff);
    }

If all is good you would expect the timer to come in close to the expected number of milliseconds. In this case if the diff is greater than 1000ms then the timer was delayed.
Sometimes I am seeing this sort of output.

>
 ____                 _
|  __|___ ___ ___ _ _|_|___ ___
|  __|_ -| . |  _| | | |   | . |
|____|___|  _|_| |___|_|_|_|___|
         |_| espruino.com
 2v08.187 (c) 2019 G.Williams
perf=2.01586914062
perf=-0.63916015625
perf=0.06274414062
perf=-0.08984375
perf=0.0322265625
perf=-0.02880859375
perf=0.00170898437
perf=0.0322265625
perf=140.07739257812     <<<<=== LCD times out, have to BTN3 press
perf=1.7412109375
perf=0.06274414062
perf=-0.02880859375
perf=-0.02880859375
perf=0.00170898437
perf=0.00170898437
perf=0.00170898437
perf=0.154296875
perf=-0.08984375
perf=1.77172851562
perf=0.0322265625
perf=-0.02880859375
perf=0.00170898437
perf=1.52758789062
perf=-1.52416992187
perf=0.00170898437
perf=1794.40478515625    <<<<=== LCD times out, have to BTN3 press
perf=335.90869140625    <<<< now we see 300+ms delays on a 1000s timer
perf=363.13037109375
perf=346.37622070312
perf=1860.96362304687
perf=432.55786132812
perf=427.15625
perf=443.17797851562
perf=338.38061523437
perf=355.68408203125
perf=364.16796875
perf=443.30004882812
perf=443.78833007812
perf=1974.03125
perf=414.91870117187
perf=431.39819335937
perf=421.87670898437
perf=419.43530273437
perf=433.10717773437
perf=364.13745117187
perf=336.15283203125
perf=341.79858398437
perf=442.537109375
perf=398.4697265625
perf=399.53784179687
>
>

The above is a lucky example, it does not usually happen with the screen going off (I think that is cooincidence here). I can keep the screen on by pressing BTN3 before it goes off and sometimes I will see this.

If feels like something else is grabbing resource.

Kind of need the equivalent of the unix uptime command to see how loaded the CPU is.

It looks to me that watches tells you what you have bound to the Buttons.
Below is the result of my stepo watch, which detects press and release of BTN2.

global["\xFF"].watches
=[
  undefined,
  { pin: D22, recur: true, debounce: 26214, edge: 1,
    callback: function () { ... },
    state: false },
  { pin: D22, recur: true, debounce: 26214, edge: -1,
    callback: function () { ... },
    state: false }
 ]
>

Below is the result of my experimental multiclock where I want to have {BTN1, BTN2} short and long presses passed onto the current watch face. I use BTN3 rising edge to switch faces and leave BTN3 long press for the reset.

>global["\xFF"].watches
=[
  undefined,
  { pin: D24, recur: true, debounce: 26214, edge: 1,
    callback: function (btn) { ... },
    state: false },
  { pin: D22, recur: true, debounce: 26214, edge: 1,
    callback: function (btn) { ... },
    state: false },
  { pin: D23, recur: true, debounce: 26214, edge: 1,
    callback: function () { ... },
    state: false, lastTime: 1615420296.37918376922 },
  { pin: D24, recur: true, debounce: 26214, edge: -1,
    callback: function (btn) { ... },
    state: false },
  { pin: D22, recur: true, debounce: 26214, edge: -1,
    callback: function (btn) { ... },
    state: false }
 ]

So these are both what I would expect.

  setWatch(btn_pressed.bind(null,1), BTN1, {repeat:true,edge:"rising"});
  setWatch(btn_pressed.bind(null,2), BTN2, {repeat:true,edge:"rising"});
  setWatch(nextFace, BTN3, {repeat:true,edge:"rising"});

  setWatch(btn_released.bind(null,1), BTN1, {repeat:true,edge:"falling"});
  setWatch(btn_released.bind(null,2), BTN2, {repeat:true,edge:"falling"});
  // BTN 3 long press should always reset the bangle

dump() looks useful. Will give that a try out.

Wed 2021.03.10

'In this case if the diff is greater than 1000ms then the timer was delayed.'

Hugh,

I'm not sure I'm 100% with what is attmepted here, but as getTime() returns consecutive incrementing floating point values,

http://www.espruino.com/Reference#l__global_getTime
'Return the current system time in Seconds (as a floating point number)'

why not place one inside the setInterval() at L7 and print that to the console?

That should help narrow down if the perfCheck() loop functions as expected.

Haven't tested, but if less than 1000msec then they should toggle, e.g. L7 :: L15, and on a delay the console should just update each 1000msec e.g. L7 only. Also time stamping inside perfCheck() should also coincide with L7


Would setTimeout() as it fires just once be a better choice?

https://www.w3schools.com/jsref/met_win_settimeout.asp

Personally I'd look at readCompass - putting a getTime() at the start, and one at the end, and comparing.

If an interval gets delayed, it'll be because some other bit (or bits) of JavaScript is taking a long time to execute.

If it's getting slower over time, is it possible you're not doing a clearInterval(..) for your intervalRefSec = setInterval(readCompass, 200);?

If it's getting slower over time, is it possible you're not doing a
clearInterval(..) for your intervalRefSec = setInterval(readCompass,
200);?

This compass code seems to get slower over time. There is a stopTimer() call which gets called everytime the LCD screen goes off.

function stopTimer() {
      if(intervalRefSec) {intervalRefSec=clearInterval(intervalRefSec);}
      if(intervalPerf) {intervalPerf=clearInterval(intervalPerf);}
    }

Overtime, or sometimes fairly quickly the Buttons become unresponsive as it the edge detection did not kick in. Not sure if the firmware is interrupt driven or just polls the state of the buttons. Clearly something is going on with the readCompass() (the code is copied from the Navigation Compass - I think the problem maybe the tilt correction code as it has a lot of Math.sin tan etc in it.

The intervalPerf timer is acting a bit like a watchdog for the purpose of me understanding what load is being run on the CPU. So if this time is delayed by 300+ms then something is seriously wrong.

Changing perfCheck() to switch LED1 on/off if we detect that the timer was delayed has allowed me to see that when there is a lot of arm movement then the 1000ms timer gets delayed and that is pointing me at the tilt correction code in the Magnav compass.

I will also profile the times for the different funtions.

   function perfCheck() {
      var tNow  = getTime();
      var tDiff = 1000*(tNow - tPerf) - 1000;
      tPerf = tNow;
      //console.log("perf=" + tDiff);
      LED1.write((tDiff > 50));
    }

Here is the result of my investigations.

1) the drawCompass() function was taking 98,99ms. But sometimes I was seeing this go to 130ms.
Then when the buttons become unresponsive I was seeing it take 1300ms. It is as if 100ms is just too much of a chunk of processing and stuff that the firmware does starts to back up.

This is really interesting. Here are the different timings for different methods to draw the compass arrow:

1) Original method tha rotated an image for the arrow - 98ms.

    // takes ~95-100ms, have seen it take 1200ms though which will cause tasks to back up
    function drawCompass(hd) {
      var t1 = getTime();
      buf1.setColor(1);
      buf1.fillCircle(80,80,79,79);
      buf1.setColor(0);
      buf1.fillCircle(80,80,69,69);
      buf1.setColor(1);
      buf1.drawImage(img, 80, 80, {scale:3,  rotate:radians(hd)} );
      flip1(40, 30);
      var t = Math.round((getTime() - t1)*1000);
      LED1.write((t > 130));
    }

2) TEST_7: An experiment using a modified version of the arrow() function in the route App.
Takes 9ms BUT you have to call it twice once to draw the arrow and the next time to remove the old one. So 18ms total.

    function arrow(angle,col) {
      var t1 = getTime();
      angle=angle*Math.PI/180;
      var p = [0, 1.1071, Math.PI/4, 2.8198, 3.4633, 7*Math.PI/4 , 5.1760];
      g.setColor(col);

      var poly = [
        120+60*Math.sin(angle+p[0]),       120-60*Math.cos(angle+p[0]),
        120+44.7214*Math.sin(angle+p[1]),  120-44.7214*Math.cos(angle+p[1]),
        120+28.2843*Math.sin(angle+p[2]),  120-28.2843*Math.cos(angle+p[2]),
        120+63.2455*Math.sin(angle+p[3]),  120-63.2455*Math.cos(angle+p[3]),
        120+63.2455*Math.sin(angle+p[4]),  120-63.2455*Math.cos(angle+p[4]),
        120+28.2843*Math.sin(angle+p[5]),  120-28.2843*Math.cos(angle+p[5]),
        120+44.7214*Math.sin(angle+p[6]),  120-44.7214*Math.cos(angle+p[6])
      ];
      
      //console.log(poly);
      g.fillPoly(poly);
      console.log("arrow: " + Math.round((getTime() - t1)*1000) );
    }

TEST_8: The arrow shape I require: Takes twice as long, called twice tatal = 32ms.

function arrow(angle,col) {
      var t1 = getTime();
      angle=angle*Math.PI/180;
      var p = [0, 1.1071, Math.PI/4, 2.8198, 3.4633, 7*Math.PI/4 , 5.1760];
      g.setColor(col);

      poly = [
        120+60*Math.sin(angle+p[0]),       120-60*Math.cos(angle+p[0]),
        120+44.7214*Math.sin(angle+p[1]),  120-44.7214*Math.cos(angle+p[1]),
        120+28.2843*Math.sin(angle+p[2]),  120-28.2843*Math.cos(angle+p[2]),
        120+63.2455*Math.sin(angle+p[3]),  120-63.2455*Math.cos(angle+p[3]),
        120+63.2455*Math.sin(angle+p[4]),  120-63.2455*Math.cos(angle+p[4]),
        120+28.2843*Math.sin(angle+p[5]),  120-28.2843*Math.cos(angle+p[5]),
        120+44.7214*Math.sin(angle+p[6]),  120-44.7214*Math.cos(angle+p[6])
      ];
      g.fillPoly(poly);

      var t = Math.round((getTime() - t1)*1000);
      LED1.write((t > 30));
      //console.log("T8: " + t);
      return t;
    }

TEST_10: The required Arrow shape, with a circle round it and using an arrayBuffer. 62ms.
BUT i have seen this go to 200ms on occassion, so there is obviously a risk that this can cause issues and become unresponsive.

// takes 62 ms
    function drawCompass(hd) {
      if (hd === oldHeading) return;
      var t1 = getTime();

      buf1.setColor(1);
      buf1.fillCircle(80,80,79,79);
      buf1.setColor(0);
      buf1.fillCircle(80,80,69,69);
      buf1.setColor(1);
      
      hd=hd*Math.PI/180;
      var p = [0, 1.1071, Math.PI/4, 2.8198, 3.4633, 7*Math.PI/4 , 5.1760];

      var poly = [
        80+60*Math.sin(hd+p[0]),       80-60*Math.cos(hd+p[0]),
        80+44.7214*Math.sin(hd+p[1]),  80-44.7214*Math.cos(hd+p[1]),
        80+28.2843*Math.sin(hd+p[2]),  80-28.2843*Math.cos(hd+p[2]),
        80+63.2455*Math.sin(hd+p[3]),  80-63.2455*Math.cos(hd+p[3]),
        80+63.2455*Math.sin(hd+p[4]),  80-63.2455*Math.cos(hd+p[4]),
        80+28.2843*Math.sin(hd+p[5]),  80-28.2843*Math.cos(hd+p[5]),
        80+44.7214*Math.sin(hd+p[6]),  80-44.7214*Math.cos(hd+p[6])
      ];
      
      buf1.fillPoly(poly);
      flip1(40, 30);
      var t = Math.round((getTime() - t1)*1000);
      LED1.write((t > 100));
      //console.log("T10: " + t);
      return t;
    }

What is the flip1 function? Everything else looks pretty straightforward and should take a pretty normal amount of time.

When drawCompass is running slow, does it run slow every time from then on?

There is one other possibility - What is your memory usage?

When the memory gets quite full and it is fragmented, it becomes impossible to allocate a large contiguous area of memory. In this case Espruino still soldiers on and allocates arrays (eg the buffer for your offscreen graphics) split across memory - however that means that from then on every operation on that data ends up substantially slower.

So what you could do to fix this is ensure that you deallocate your old watch face before loading a new one. You could check process.memory().usage to ensure it's gone.

You could also call E.defrag() before loading the new watch face in the hope that it'd rearrange things enough that big memory areas could be allocated.

In this case Espruino still soldiers on and allocates arrays (eg the buffer for your offscreen >graphics) split across memory - however that means that from then on every operation on that >data ends up substantially slower.

This could be it as removing the draw of the outer yellow ring and reducing the arraybuffer to 128x128 from 160x160 seems to eliminate the issue all together and bring the time for the function down to 36ms.

I think I am de-allocating all memory using freeResources(). will have a try of 'E.defrag()' at some point.