strange timing with setTimeout

During testing a rotary phone, I ran into problems recognizing pulses.

After some testing brought it down to following samples.
Duration is always much more than expected (by me).

Interesting is last example where only first timeout is wrong.

Testing is done with WebIde. First examples use terminal window for input.
Last testing is uploaded from editor window and called from terminal.
Board is MDBT42Q with 2v06, downloaded from binary

for(var i = 0; i < 10; i++) {var dt = new Date();setTimeout(function(){console.log(new Date() - dt);},1000);}
=undefined
2159.7900390625
2161.0107421875
2162.90283203125
2164.21508789062
2165.67993164062
.....

var dt = new Date();setTimeout(function(){console.log(new Date() - dt);},100);
=1
958.46557617187
>var dt = new Date();setTimeout(function(){console.log(new Date() - dt);},100);
=1
1476.01318359375
>var dt = new Date();setTimeout(function(){console.log(new Date() - dt);},100);
=1
1280.94482421875
>var dt = new Date();setTimeout(function(){console.log(new Date() - dt);},1000);
=1
1865.69213867187
>var dt = new Date();setTimeout(function(){console.log(new Date() - dt);},1000);
=1
2315.673828125

function tst(duration){
  var pnt = 0;
  function tstTimeout(){
    var dt = new Date();
    setTimeout(function(){ 
      console.log(new Date() - dt);
      if(pnt++ < 4) tstTimeout();
    },duration);
  }
  clearTimeout();
  tstTimeout();
}
tst(1000);
=undefined
1828.857421875
1001.43432617187
1001.46484375
1001.43432617187
1001.46484375

Is it possible you have some other interval or setWatch running in the background that could be keeping it really busy? Maybe try a reset(1) to be sure?

From a board I just tried:

>for(var i = 0; i < 10; i++) {var dt = new Date();setTimeout(function(){console.log(new Date() - dt);},1000);}
=undefined
992.88940429687
994.90356445312
996.18530273437
997.86376953125
999.1455078125
1000.42724609375
1002.01416015625
1003.44848632812
1004.73022460937
1010.58959960937

>var dt = new Date();setTimeout(function(){console.log(new Date() - dt);},100);
=1
101.13525390625
>var dt = new Date();setTimeout(function(){console.log(new Date() - dt);},100);
=1
101.25732421875
>var dt = new Date();setTimeout(function(){console.log(new Date() - dt);},100);
=1
101.13525390625
>var dt = new Date();setTimeout(function(){console.log(new Date() - dt);},100);
=1
101.13525390625
>var dt = new Date();setTimeout(function(){console.log(new Date() - dt);},100);
=1
101.13525390625


>function tst(duration){
:  var pnt = 0;
:  function tstTimeout(){
:    var dt = new Date();
:    setTimeout(function(){
:      console.log(new Date() - dt);
:      if(pnt++ < 4) tstTimeout();
:    },duration);
:  }
:  clearTimeout();
:  tstTimeout();
:}
=function (duration) { ... }
>tst(1000);
=undefined
1001.55639648437
1001.67846679687
1001.52587890625
1001.52587890625
1001.46484375

So all that looks pretty good. You'd expect the ~1ms delay because of the time taken to parse and execute setTimeout after the initial Date variable is created.

Sorry, you're right. Just tried with version 2v06 and something isn't right.

Please could you try a cutting edge build? That's what I tried before and it worked fine.

Hmm,
tested with 2V06,78 from http://www.espruino.com/binaries/travis/master/
Still same problem.
Latest entry is from 2020-07-30
Looks like there is no update since end of July

Tested with Android and nrf
Got same problem, so its not a windows problem.
With Android its even worth, first time it takes >30 secs

Just seen new version(V2.06.81) in binaries.
I did some extended testing with other boards

board V2.04 V2.06
========= ===== =====
Espruino ok ok
ESP32 ok ok
MDBT42Q ok bad
Puck ok bad

Based on that, my first guess would be somewhere around implementation of UART for BLE

Thanks - so it'll be related to the nRF52 I guess.

I think it's less likely to be a BLE issue, because the entire line is executed only when you hit enter - so in your example - especially var dt = new Date();setTimeout(function(){console.log(new Date() - dt);},100); - the UART shouldn't be doing anything while code is running.

I guess it could be related to the 'Utility Timer' somehow - that is platform-specific and may have some issues

Hmm, some more (may be helpful) info
One more problem I have around is disconnecting of UART on MDBT42Q.
Did not encounter this with Puck (yet?)
From time to time it happens, that connection is kind of frozen. There is no echo in terminal window anymore. This happens at crlf or in the middle of a command.
Or, another problem, sending even some lines of code, less than 3kb, from source window to Espruino stops somewhere in the middle.
And one more, sometimes after reset, startinfo comes in very slow only, char by char.

That's a strange one. Does Ctrl-C sort it out? Or does the Web IDE console show a flow control message?

Ok, I'm pretty sure I've figured this out now. It's definitely a firmware issue that's been around for a while I think.

In fact if you:

• Paste in var dt = new Date();setTimeout(function(){console.log­(new Date() - dt);},100);
  
• Wait X seconds then press Enter
  
• Timeout happens X seconds after this
  
  

It's to do with the device sleeping - you probably don't notice it in STM32 boards because they don't sleep when you're connected via USB

Ok, just fixed! If you try a cutting edge build now it should be sorted.

It seems this got introduced about 2 months ago and got into 2v06. Just a really minor change that had a big effect!

I doubt this will affect your connection issues - but the only times I've had issues with that is when there's extremely poor signal strength.

Its fixed and works fine. Well done ;-)
Connection issue did happen one time only today.
Usual problem, if you want to show strange behaviour, it never happens :-(
Poor signal should not be the problem, distance between board and laptop is less than 20cm