UNIX Time



  • I have been able to initialize the RTC to match current time via NIST website.

    However, when I read back time via utime.time() to get seconds since 1970, the value doesn't update. As if number is to large for OS?

    It works fine if I don't update the RTC (that is, board thinks it is living in 1970 so that accumulated seconds are small.

    Is this a limitation of the system (can't handle 10 digit number) or am I doing something wrong? Examples below:

    Simple code:

    import time
    import utime
    import machine
    
    rtc = machine.RTC()
    
    while True:
       print ('rtc.now:'+str(rtc.now())+"  utime.time:"+str(int(utime.time())))
       time.sleep (1)
    

    Output without updating clock to current time (you will see both values incrementing):

    rtc.now:(1970, 1, 1, 0, 9, 36, 643867, None)  utime.time:576
    rtc.now:(1970, 1, 1, 0, 9, 37, 645865, None)  utime.time:577
    rtc.now:(1970, 1, 1, 0, 9, 38, 647876, None)  utime.time:578
    rtc.now:(1970, 1, 1, 0, 9, 39, 649865, None)  utime.time:579
    rtc.now:(1970, 1, 1, 0, 9, 40, 651866, None)  utime.time:580
    rtc.now:(1970, 1, 1, 0, 9, 41, 653864, None)  utime.time:581
    rtc.now:(1970, 1, 1, 0, 9, 42, 655889, None)  utime.time:582
    rtc.now:(1970, 1, 1, 0, 9, 43, 657864, None)  utime.time:583
    rtc.now:(1970, 1, 1, 0, 9, 44, 659866, None)  utime.time:584
    rtc.now:(1970, 1, 1, 0, 9, 45, 661872, None)  utime.time:585
    rtc.now:(1970, 1, 1, 0, 9, 46, 663865, None)  utime.time:586
    

    Output after RTC is sync'd to current time:

    rtc.now:(2017, 1, 26, 18, 18, 36, 801757, None)  utime.time:1485454720
    rtc.now:(2017, 1, 26, 18, 18, 37, 804763, None)  utime.time:1485454720
    rtc.now:(2017, 1, 26, 18, 18, 38, 807756, None)  utime.time:1485454720
    rtc.now:(2017, 1, 26, 18, 18, 39, 810742, None)  utime.time:1485454720
    rtc.now:(2017, 1, 26, 18, 18, 40, 812750, None)  utime.time:1485454720
    rtc.now:(2017, 1, 26, 18, 18, 41, 814746, None)  utime.time:1485454720
    rtc.now:(2017, 1, 26, 18, 18, 42, 816750, None)  utime.time:1485454720
    rtc.now:(2017, 1, 26, 18, 18, 43, 819752, None)  utime.time:1485454720
    rtc.now:(2017, 1, 26, 18, 18, 44, 822750, None)  utime.time:1485454720
    rtc.now:(2017, 1, 26, 18, 18, 45, 825771, None)  utime.time:1485454720
    rtc.now:(2017, 1, 26, 18, 18, 46, 828743, None)  utime.time:1485454720
    


  • After thinking it through and discussing it with my fellow workers, the only posible solution is to go back to integers. The reason is that at present time mp_float_t is now a C float, that only has 23 bit to represent the mantissa. This could be changed, but needs proper testing. Perhaps in the future this will change, but until then, time.time() will return an integer.



  • @dchappel, @jmarcelino, and everyone else that reads this. I hope you guys all accept my humble apology. @jmarcelino made me realize of a mistake I made while coming into this conclusions (and in the original software too).

    I had forgotten that single floating point values are 32 bit (so only 23 bits represent the fraction). The results are then correct. I'll check into the reported bug and look for a way to fix it ASAP. Probably it won't be included in today's release, as I want to test it properly this time.



  • @abilio

    I meant that %f in the printf is usually a double not a float



  • @jmarcelino, actually in the line:

    printf("%lld %f\n", mach_rtc_get_us_since_epoch(), mach_rtc_get_us_since_epoch() / 1000000.0);
    

    I wanted to print the us value after epoch, which is internally kept as a 64 bit integer (to go beyond the 2K38 problem), hence the %lld. Then at the same line I wanted to test that it was not an issue with converting it to a float seconds value (which proved not to be the case).



  • Thank you so much for posting your thoughts and debugging steps @abilio
    This is really excellent for us entering the world of μpython internals debugging - and do I love a good mystery to apply some detective work ;-)

    That the problem appears at 24 bits is interesting and I remember floats (when stored as 32 bit) only have 23 bits for the significant digits so maybe that explains it.

    I think printf("%lld %f\n" ...) uses doubles so that's probably why you didn't see it there.

    Just a theory at least. I'll look into it a bit more later if we're still stuck.



  • I've been doing some tests, and found this to be related to the Espressif tools. I created this simple test:

    void check_this_float_passing(float f) {
        printf("this is a float: %f\n", f - 16777215.0); // the constant is there to prove that is not fault of the printf */
    }
    
    void test_float(void) {
        check_this_float_passing(16777215.0);
        check_this_float_passing(16777216.0);
        check_this_float_passing(16777216.1); // buggy from now on
        check_this_float_passing(16777217.0);
        printf("this is a big float showing it works: %f\n", 16777217.0); // this works
    }
    

    Expected result:

    this is a float: 0.000000
    this is a float: 1.000000
    this is a float: 1.100000
    this is a float: 2.000000
    this is a big float showing it works: 16777217.000000
    

    Obtained:

    this is a float: 0.000000
    this is a float: 1.000000
    this is a float: 1.000000
    this is a float: 1.000000
    this is a big float showing it works: 16777217.000000
    

    As you see, there is a problem with passing floats as a parameter of a function for numbers higher than 2^24. I'm going to investigate further.

    Note: this is not related to the previous floating point bug (80000000.0 / 1000000.0 != 80).



  • @dchappel, @jmarcelino, thanks for the report. You're totally right about time not working properly after initialization.

    To continue with @jmarcelino's finding, the reason why returns a float is to making it more compatible with CPython, taking advantage of the fact that floating point is supported. (reference here). It was a last minute change before the release, and must admit, not tested in the way you did, but only with the RTC in reset after boot state.

    The original line reads:

    return mp_obj_new_float(mach_rtc_get_us_since_epoch() / 1000000.0);
    

    The fact is that if you do some printing:

    printf("%lld %f\n", mach_rtc_get_us_since_epoch(), mach_rtc_get_us_since_epoch() / 1000000.0);
    

    You'll see the value changing, yet the float object returned always have the same value. Furthermore, if you replace the C code by:

    STATIC mp_obj_t time_time(void) {
        static float t = 1483229312.0;
        t = t + 1.0;
       // get date and time
       return mp_obj_new_float(t);
    }
    

    You would expect the value to change, but it doesn't. But if you do initialize t to 1.0, as in: static float t = 1.0; then it changes.

    Now if t = 16777215.0, you'll see the value increment once, then get stuck at 16777216.0, which is 2 ˆ24.

    I have to investigate further.



  • I traced the problem to esp32/mods/modutime.c and added a comment to the issue on github: https://github.com/pycom/pycom-micropython/issues/71#issuecomment-275624314

    Simply changing time_time() to return an int fixed it for me, but not sure why it was returning a float in the first place so maybe I'm missing something :-)

    With the patch in place it seems to be working

    >>> rtc.init((2017,1,27,9,0))
    
    Running utimeTest.py
    rtc.now:(2017, 1, 27, 9, 0, 9, 37484, None)  utime.time:1485507609
    rtc.now:(2017, 1, 27, 9, 0, 10, 39594, None)  utime.time:1485507610
    rtc.now:(2017, 1, 27, 9, 0, 11, 41610, None)  utime.time:1485507611
    rtc.now:(2017, 1, 27, 9, 0, 12, 43605, None)  utime.time:1485507612
    rtc.now:(2017, 1, 27, 9, 0, 13, 45611, None)  utime.time:1485507613
    rtc.now:(2017, 1, 27, 9, 0, 14, 48617, None)  utime.time:1485507614
    rtc.now:(2017, 1, 27, 9, 0, 15, 50614, None)  utime.time:1485507615
    rtc.now:(2017, 1, 27, 9, 0, 16, 52619, None)  utime.time:1485507616
    


  • @dchappel
    report this issue on github



  • @livius

    Here's the output without any formatting or use of int:

    rtc.now:(2017, 1, 26, 20, 50, 14, 559838, None)  utime.time:1.485464e+09
    rtc.now:(2017, 1, 26, 20, 50, 15, 562317, None)  utime.time:1.485464e+09
    rtc.now:(2017, 1, 26, 20, 50, 16, 565325, None)  utime.time:1.485464e+09
    rtc.now:(2017, 1, 26, 20, 50, 17, 567325, None)  utime.time:1.485464e+09
    rtc.now:(2017, 1, 26, 20, 50, 18, 569324, None)  utime.time:1.485464e+09
    rtc.now:(2017, 1, 26, 20, 50, 19, 571324, None)  utime.time:1.485464e+09
    rtc.now:(2017, 1, 26, 20, 50, 20, 573324, None)  utime.time:1.485464e+09
    rtc.now:(2017, 1, 26, 20, 50, 21, 575324, None)  utime.time:1.485464e+09
    rtc.now:(2017, 1, 26, 20, 50, 22, 577342, None)  utime.time:1.485464e+09
    rtc.now:(2017, 1, 26, 20, 50, 23, 580311, None)  utime.time:1.485464e+09
    rtc.now:(2017, 1, 26, 20, 50, 24, 582313, None)  utime.time:1.485464e+09
    

    And for what it's worth, sys.maxsize comes back with 2147483647. So we are working within that limitation.



  • @livius

    The number is same on every line. Digits to the right of the decimal point stop before point That they would show change.

    Not in front of setup at the moment. Will post output a bit later.



  • @dchappel
    yes but it is different for every line?



  • That gives a truncated scientific notation output.

    I need the full digit representation to pass to service as my timestamp.



  • @dchappel
    i can not test now - i am running stability test it must work 1 day
    but what if you change line to:
    print ('rtc.now:'+str(rtc.now())+" utime.time:"+str(utime.time()))


Log in to reply
 

Looks like your connection to Pycom Forum was lost, please wait while we try to reconnect.