Go Down

Topic: Improving millis() (Read 4860 times) previous topic - next topic

mikalhart

#45
Sep 02, 2008, 05:19 pm Last Edit: Sep 02, 2008, 05:32 pm by mikalhart Reason: 1
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

mem

#46
Sep 02, 2008, 05:42 pm Last Edit: Sep 02, 2008, 05:43 pm by mem Reason: 1
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: [Select]

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!

mikalhart

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: [Select]
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

mem

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

mikalhart

#49
Sep 02, 2008, 07:50 pm Last Edit: Sep 02, 2008, 10:40 pm by mikalhart Reason: 1
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

Go Up