next topic »

[Reply #45 on:]

Hi mem.

If you temporarily change the initial value of prevMillis to something like:

static unsigned long prevMillis = 1000;

and then just call now(), this simulates the "worst case", which I imagine is something like the situation you'd see after 49 days.  Since this took ~187 seconds, I calculated the one hour of "drift" would take proportionally less, i.e. 187s/49days/24hours = ~157ms.

I did some similar experiments to the one you excerpt above, and after getting astonishingly quick times (1ms!), I realized that that too-smart-for-its-own-good compiler is cleverly optimizing out the call to millis()!  If you modify your test slightly to something like

for(int i = 0; i < 3600; i++)
{
  if (millis() == 0xDEADBEEF)
    Serial.println("Foo");
  sysTime++;
  prevMillis += 1000;
}

you'll get the 150ms figure.

That said, I'm in complete agreement that most apps would probably call now() so frequently as to not notice.  But there are some out there that will break.  I wouldn't like that. And I respectfully disagree that the best strategy to find out what time the sunlight hits your sensor is to have to write a new interrupt handler.  That's what we have DateTime::now() for!!


Mikal

[Reply #46 on:]

Millis doesn't roll over cleanly so I am not sure what your test is doing, but the code I ran isn't being optimized out. Here is the actual code that the compiler produced for the test that I ran:

Code:

unsigned long now() // return the elapsed seconds since system start
    1626:      cf 93             push      r28
    1628:      df 93             push      r29
    162a:      c0 e0             ldi      r28, 0x00      ; 0
    162c:      d0 e0             ldi      r29, 0x00      ; 0
{

  for(int i = 0; i < 3600; i++){
    millis();
    162e:      0e 94 e2 0c       call      0x19c4      ; 0x19c4 <millis>
    sysTime++;
    1632:      20 91 17 01       lds      r18, 0x0117
    1636:      30 91 18 01       lds      r19, 0x0118
    163a:      40 91 19 01       lds      r20, 0x0119
    163e:      50 91 1a 01       lds      r21, 0x011A
    1642:      2f 5f             subi      r18, 0xFF      ; 255
    1644:      3f 4f             sbci      r19, 0xFF      ; 255
    1646:      4f 4f             sbci      r20, 0xFF      ; 255
    1648:      5f 4f             sbci      r21, 0xFF      ; 255
    164a:      20 93 17 01       sts      0x0117, r18
    164e:      30 93 18 01       sts      0x0118, r19
    1652:      40 93 19 01       sts      0x0119, r20
    1656:      50 93 1a 01       sts      0x011A, r21
    prevMillis += 1000;
    165a:      80 91 1b 01       lds      r24, 0x011B
    165e:      90 91 1c 01       lds      r25, 0x011C
    1662:      a0 91 1d 01       lds      r26, 0x011D
    1666:      b0 91 1e 01       lds      r27, 0x011E
    166a:      88 51             subi      r24, 0x18      ; 24
    166c:      9c 4f             sbci      r25, 0xFC      ; 252
    166e:      af 4f             sbci      r26, 0xFF      ; 255
    1670:      bf 4f             sbci      r27, 0xFF      ; 255
    1672:      80 93 1b 01       sts      0x011B, r24
    1676:      90 93 1c 01       sts      0x011C, r25
    167a:      a0 93 1d 01       sts      0x011D, r26
    167e:      b0 93 1e 01       sts      0x011E, r27
    1682:      21 96             adiw      r28, 0x01      ; 1
    1684:      8e e0             ldi      r24, 0x0E      ; 14
    1686:      c0 31             cpi      r28, 0x10      ; 16
    1688:      d8 07             cpc      r29, r24
    168a:      89 f6             brne      .-94           ; 0x162e <_Z3nowv+0x8>
  }
  return sysTime;

There is a significant performance hit on making a function call so your call to Serial.println()  probably takes much more time than all the other code in the function (my guess is 130ms of the 150ms you measured is spent doing the Serial.println call.

Anyway, although  we are getting quite different measurements, I don't think we are really disagreeing on the principles being discussed here.

Have fun!

[Reply #47 on:]

Ah, no, no!  My sample code never calls Serial.println at all (because millis() is never equal to 0xDEADBEEF)!

I am puzzled why your results differ so much.  Even when I run your test code -- the one I incorrectly presumed was being optimized -- I still get ~157ms.  May I ask what you get when you run this program -- which is just your code with a diagnostic thrown in?

Code:

static unsigned long sysTime;  
static unsigned long prevMillis;  
  
unsigned long now() {
 
  for(int i = 0; i < 3600; i++){
    millis();
    sysTime++;
    prevMillis += 1000;
  }
  return sysTime;
}  
 
void  loop(){
  long startMillis = millis();
  now();  
  int dur = millis() - startMillis;
  Serial.println(dur);
}

void setup()
{
  Serial.begin(9600);
}

I consistently get ~157-164ms.  If you are getting 20ms, I wonder if you have some better optimizations going?  Can you point me to a document that describes how to produce a disassembly?  I really want to learn how to do that.

Cheers, and thanks much!

Mikal

[Reply #48 on:]

I get 19 and 20 when running that code.

I am running Arduino version 0011 with the default compiler settings but with wiring.c modified with the 0012 millis() code as posted earlier in this thread.

You can view the assembler by running a utility called avr-objdump.exe on the elf file.  There is a thread that discusses how to do it here: http://www.arduino.cc/cgi-bin/yabb2/YaBB.pl?num=1207951658

[Reply #49 on:]

Ah, yes!  That makes a lot of sense.  Since the v. 012 version of millis() is so much simpler than its v. 011 counterpart, your results are very understandable.  Thanks!

Mikal