millis() returns zero

Discussion about Z-Uno product. Visit http://z-uno.z-wave.me for more details.
Post Reply
perjar
Posts: 49
Joined: 08 Apr 2018 18:02

millis() returns zero

Post by perjar »

Dear forum,

I have encountered an issue that I can't quite understand. The issue is that the millis() function sometimes returns 0 instead of the correct timestamp, only to continue to report the correct value in the next call.

Over-simplified code for illustrational purposes:

Code: Select all

loop {
   currenttime = millis();
   Serial.println(currenttime);
   delay(2000);
}
This can give a printout as follows:

Code: Select all

>341020
>343021
>345021
>0
>349023
I am on 2.1.4.

Any ideas?

User avatar
PoltoS
Posts: 5524
Joined: 26 Jan 2011 19:36

Re: millis() returns zero

Post by PoltoS »

Could you please try it in 2.1.5?

perjar
Posts: 49
Joined: 08 Apr 2018 18:02

Re: millis() returns wrong value

Post by perjar »

I have upgraded to 2.1.5 now. Same result.

Let me adjust my initial problem statement: It also happens that millis() returns a value which is not zero, but it is lower than the previous call.

My observations so far indicate that the millis() function is set back about 60 seconds from time to time.

Example:

Code: Select all

1: 19:53:36.837 -> currenttime= 82230145, previoustime =82225387, elapsed = 4758
2: 19:53:41.709 -> currenttime= 82234936, previoustime =82230145, elapsed = 4791
3: 19:53:46.703 -> currenttime= 82239695, previoustime =82234936, elapsed = 4759
4: 19:53:51.422 -> currenttime= 82244427, previoustime =82239695, elapsed = 4732
5: 19:53:56.277 -> currenttime= 82183619, previoustime =82244427, elapsed = 4294906488
6: 19:54:01.116 -> currenttime= 82188352, previoustime =82183619, elapsed = 4733
7: 19:54:05.962 -> currenttime= 82193086, previoustime =82188352, elapsed = 4734
The sketch behind this printout counts pulses from an electrical meter and based on that calculates power consumption.
"elapsed" is an unsigned long, hence the huge number, resulting from the substraction currenttime - previoustime.

As you can see in the printout, pulse 5 gets a millis() value which is lower than pulse 4. 60808 milli sec lower to be precise. I have monitored this for a few days now and it appears that when this happens, the clock is set back between 60-66 seconds. (recent observations: 61029, 65376, 63069 and 65404 milliseconds)

User avatar
PoltoS
Posts: 5524
Joined: 26 Jan 2011 19:36

Re: millis() returns zero

Post by PoltoS »

Please try the following fix in HLCore.cpp:
dword millis() {
noInterrupts(); // <-Add
g_ms_counter += zunoGI("TMR");
zunoSI("TMR",0);
interrupts(); // <-Add
return g_ms_counter;
}

Looks like interrupts are making troubles.

Would be perfect if you report us back your results as we can not reproduce it.

ove.nystas
Posts: 3
Joined: 23 Oct 2016 22:42
Location: Sweden

Re: millis() returns zero

Post by ove.nystas »

Hi,

As a hobby project I am doing a Water meter sensor based on Z-Uno and I had issues with sporadic extremely high water flow values.
I found that there were sporadic jumps in the millis() value which I use in calculation of the water flow.

I searched the forum to see if someone else had reported this problem and found this thread that exactly match what I also have seen.
Since I'm running Z-Uno version 2.1.5 I can sadly say that the suggested fix didn't solve the problem. I can see that the fix is implemented in HLCore.cpp in 2.1.5.

I changed my sketch from using millis() function for calculating water flow to instead use ZUNO_1MS_TIMER() to increment a counter and the issues disappered.

To investigate the issue with sporadic jumps in the millis() value even more, I wrote the supplied sketch to test how the millis() function behaves compared to the ZUNO_1MS_TIMER().
I found out that millis() actually do have issues with sporadic jumps and there are also some drift issues.

When looking at the log, as supplied, I can see that the millis() function seem to have problems when wrapping the low 16-bits (from 0x****FFFF to 0x****0000.)
- Most times it goes OK.
- Sometimes it jumps +256.
- Sometimes it jumps -65536.
In the provided log you can see that when the +256 or -65536 jump occurs the 16 low bits of the mills() value has just wrapped around.

As also can be seen from the log:
- millis() is drifting compared to the 1MS_TIMER and is about 1 ms slower per 20-50 s.
What can be the reason for that? Can it be fixed?
- The 1MS_TIMER is drifting compared to the PC clock and is about 100 ms slower per 10 s.
- What is the expected accuracy of the 1MS_TIMER?
- Can the accuracy be determined from the datasheet of the Z-Wave chip?
- Can the accuracy of the 1MS_TIMER be improved?

To summarize:
- The millis() value sometimes jumps +256 or -65536 and the suggested fix does not fix the problem.
- millis() is about 1 ms slower per 20-50 s than 1MS_TIMER
- The 1MS_TIMER is about 100 ms slower per 10 s than the PC clock.

Code: Select all

ZUNO_SETUP_ISR_1MSTIMER(int_1ms_handler);

unsigned long int1ms = 0;
unsigned long last_millis = 0;
boolean print_it;

void setup() {
  Serial0.begin(115200);
  Serial0.println("int1ms, millis, diff");
}

void loop() {
  unsigned long local_int1ms = int1ms;
  unsigned long curr_millis = millis();

  if (curr_millis < last_millis) {
    Serial0.print("ERROR: ");
    Serial0.print(last_millis);
    Serial0.print(", ");
    Serial0.print(curr_millis);
    Serial0.print(", ");
    Serial0.println((long)(curr_millis - last_millis));
  }

  if (print_it) {
    print_it = false;
    Serial0.print(local_int1ms);
    Serial0.print(", ");
    Serial0.print(curr_millis);
    Serial0.print(", ");
    Serial0.println((long)(local_int1ms - curr_millis));
  }

  last_millis = curr_millis;
}

void int_1ms_handler(void) {
  if (int1ms % 10000 == 0)
  {
    print_it = true;
  }
  ++int1ms;
}

Code: Select all

18:33:32.238 -> int1ms, millis, diff
18:33:32.238 -> 2, 3, -1
18:33:42.450 -> 10007, 10007, 0
18:33:52.575 -> 20014, 20014, 0
18:34:02.641 -> 30004, 30004, 0
18:34:12.768 -> 40013, 40013, 0
18:34:22.854 -> 50004, 50004, 0
18:34:32.985 -> 60012, 60011, 1
18:34:43.041 -> 70001, 70000, 1
18:34:53.159 -> 80009, 80008, 1
18:35:03.243 -> 90017, 90016, 1
18:35:13.354 -> 100005, 100003, 2
18:35:23.458 -> 110015, 110013, 2
18:35:33.542 -> 120004, 120001, 3
18:35:43.645 -> 130013, 130010, 3
18:35:53.748 -> 140003, 140000, 3
18:36:03.839 -> 150012, 150009, 3
18:36:13.929 -> 160002, 159999, 3
18:36:24.065 -> 170012, 170009, 3
18:36:34.151 -> 180002, 179999, 3
18:36:44.255 -> 190017, 190013, 4        // 190013 = 0x0002e63d
18:36:54.327 -> 200007, 200259, -252   // About a +256 jump in millis() value
18:37:04.458 -> 210021, 210273, -252
18:37:14.548 -> 220013, 220265, -252
18:37:24.647 -> 230006, 230258, -252
18:37:34.747 -> 240018, 240270, -252
18:37:44.835 -> 250009, 250261, -252
18:37:54.926 -> 260001, 260252, -251                   // 260252 = 0x0003 f89c
18:37:56.874 -> ERROR: 262143, 196627, -65516   // About a -65536 jump in millis() value, 
18:38:05.046 -> 270006, 204721, 65285
18:38:15.134 -> 280019, 214734, 65285
18:38:25.212 -> 290012, 224727, 65285
18:38:35.326 -> 300005, 234720, 65285
18:38:45.429 -> 310000, 244716, 65284
18:38:55.534 -> 320013, 254727, 65286
18:39:05.636 -> 330006, 264720, 65286
18:39:15.732 -> 340020, 274734, 65286
18:39:25.836 -> 350014, 284728, 65286
18:39:35.935 -> 360009, 294723, 65286
18:39:46.033 -> 370003, 304716, 65287
18:39:56.123 -> 380017, 314730, 65287
18:40:06.231 -> 390016, 324729, 65287
18:40:16.305 -> 400010, 334723, 65287

p0lyg0n1
Posts: 181
Joined: 04 Aug 2016 07:14

Re: millis() returns zero

Post by p0lyg0n1 »

Hi, guys!
Thanks for your reports! ove.nystas my congratulations for you! Great job! Awesome test case!
Finally we have found the problem. Anyone can try new version of bootloader. I have attached it here.
ove.nystas test sketch output is like this:

Code: Select all

10011, 10012, -1
20019, 20020, -1
30012, 30013, -1
50013, 50014, -1
60006, 60007, -1
70017, 70018, -1
80010, 80011, -1
90002, 90003, -1
100016, 100017, -1
110012, 110013, -1
120008, 120009, -1
130019, 130020, -1
140013, 140014, -1
150007, 150008, -1
160006, 160007, -1
170003, 170004, -1
180021, 180022, -1
190004, 190005, -1
200001, 200002, -1
210019, 210020, -1
220019, 220020, -1
230015, 230016, -1
240008, 240009, -1
250005, 250006, -1
260001, 260002, -1
270016, 270017, -1
280014, 280015, -1
290010, 290011, -1
300005, 300006, -1
310018, 310020, -2
320015, 320016, -1
330017, 330018, -1
340001, 340002, -1
350005, 350006, -1
360003, 360004, -1
370004, 370005, -1
380009, 380010, -1
390009, 390010, -1
400005, 400006, -1
410006, 410007, -1
420011, 420012, -1
430016, 430017, -1
440017, 440018, -1
450019, 450020, -1
460021, 460022, -1
470004, 470005, -1
480010, 480011, -1
490014, 490015, -1
500019, 500020, -1
510020, 510021, -1
To try this you have to do these steps:
1) You have to use 2.16 (beta, replace repository path to: http://z-uno.z-wave.me/files/z-uno/test ... index.json and install 2.16)
2) Upgrade your board bootloader if it's not 2.16 yet
3) Download zuno_bootloader_AAAABBBB0115011000010210028013.bin from https://yadi.sk/d/YMHdS-P2iYcd6g.
4) You have to substitute bootloader file zuno_bootloader_AAAABBBB011501100001021002xxxx.bin (xxxx - any 4 hexadecimals ) inside the Z-Uno bootloader folder withzuno_bootloader_AAAABBBB01150110000102100280137.bin (You can easily find the bootloader folder if you go to "preference"
and tap to configuration file href. Then go in opened explorer to ⁨packages⁩ ▸ ⁨Z-Uno⁩ ▸ ⁨hardware⁩ ▸ ⁨zw8051⁩ ▸ ⁨2.1.6 ▸ bootloaders⁩ ).
5) Upgrade boot loader once more time. (Sorry, but we have only 2.16 to 2.16 upgrade file at this moment).
6) Download ZWSupport.ucxt from https://yadi.sk/d/2bD3faS1-LDh3A
7) substitute ZWSupport.ucxt in your core folder ( ⁨⁨packages⁩ ▸ ⁨Z-Uno⁩ ▸ ⁨hardware⁩ ▸ ⁨zw8051⁩ ▸ ⁨2.1.6⁩ ▸ ⁨cores⁩ ▸ ⁨zuno⁩⁩) with downloaded file.
8) Recompile your sketch & enjoy :)

Of course, we will release new beta version with this fix soon, but I don't know yet when.

ove.nystas
Posts: 3
Joined: 23 Oct 2016 22:42
Location: Sweden

Re: millis() returns zero

Post by ove.nystas »

Great work p0lyg0n1!
I have tried the new version and the occasional jumps in millis() and the small drift between millis() and 1MS_TIMER is now solved. Great!
I'm looking forward to the release of version 2.16.

However the 1MS_TIMER and millis() is still about 100ms slower per 10s than the PC clock and also compared to a stopwatch. In 10 minutes the Z-Uno is about 6 seconds slower. I expect better accuracy than that. Do you want to continue discuss that issue in this thread or shall I start a new thread with that issue?

splitfile
Posts: 7
Joined: 11 Jul 2019 14:04

Re: millis() returns zero

Post by splitfile »

Any news about the 2.1.6 release?

User avatar
PoltoS
Posts: 5524
Joined: 26 Jan 2011 19:36

Re: millis() returns zero

Post by PoltoS »

It is on testing in test branch. You can install it. Will be released next week if we find nothing critical

Post Reply