Troubles using micros()/millis() form esp-idf

[unixway]

Hardware:

Board: ESP32 DEVKITV1
Core Installation/update date: 25/apr/2018
IDE name: Arduino IDE/IDF component
Flash Frequency: 80Mhz
Upload Speed: 115200

Description:

micros() returns strange values when using arduino-esp32 as component of esp-idf,
millis() returns values higher when using arduino-esp32 as component of esp-idf, then values using simply from Arduino IDE

Primarily I used Arduino IDE to code MCU, I had simple code to measure performance of some calculations, used method micros() to calculate difference. After some playing and toying I decided to try esp-idf to take advantage of multiple cores and eliminate constant arduino loop, but in result I realised that there are some troubles with my ported code, I can't rely on micros(), and also millis() returns higher values, seems that esp_timer_get_time return more adequate results, but I am not sure.

May be I should try another robust way to calculate diff in esp-idf?
But what will be with Arduino libs which uses standard millis/micros, for example method delayMicroseconds() uses micros() internally, I think it should be rewritten to use cycles instead for performance(but this method still gives me wrong results)

Sketch:

as component of esp-idf:

unsigned long prevcc;
unsigned long prevus;
unsigned long prevms;
uint64_t preveus;
unsigned long mm_micros() {
    unsigned long ct = cycles();
    unsigned long ut = micros();
    unsigned long mt = millis();
    uint64_t eus = esp_timer_get_time();
    if (mt - prevms < 1000) {
        ESP_LOGW("TIME API", "timing@cpu%u %lu(%lu(%lu)), %lu/%llu(%lu/%llu), in millis: %lu(%lu)", xPortGetCoreID(), ct, ct - prevcc, ECC_2_MICROS(ct - prevcc), ut, eus, ut - prevus, eus - preveus, mt, mt - prevms);
    }
    prevus = ut;
    prevms = mt;
    prevcc = ct;
    preveus = eus;
    return ut;
}

as Arduino IDE component:

uint32_t prevcc;
unsigned long prevus;
unsigned long prevms;
uint64_t preveus;
unsigned long mm_micros() {
    uint32_t cc = ESP.getCycleCount();
    unsigned long ut = micros();
    unsigned long mt = millis();
    uint64_t eus = esp_timer_get_time();
    if (mt - prevms < 1000) {
        Serial.printf("timing@cpu%u %u(%u(%u)) %lu/%llu(%lu/%llu), in millis: %lu(%lu)\n", xPortGetCoreID(), cc, cc - prevcc, (cc - prevcc) / 240, ut, eus, ut - prevus, eus - preveus, mt, mt - prevms);
    }
    prevus = ut;
    prevms = mt;
    preveus = eus;
    prevcc = cc;
    return ut;
}

Debug Messages:

as component of esp-idf:

W (8037534) TIME API: timing@cpu1 1044785094(4256331244(17734713)), 3207683041/7705431254(17734714/3921), in millis: 8037321(4)
W (8038230) TIME API: timing@cpu0 1129179091(84393997(351641)), 3208034678/7706101621(351637/670367), in millis: 8038017(696)
W (8044936) TIME API: timing@cpu1 1514182076(376265(1567)), 3209638855/7712489794(1561/2333), in millis: 8044723(2)
W (8045626) TIME API: timing@cpu0 1596910672(82728596(344702)), 3209983564/7713154637(344709W (8045629)
W (8052328) TIME API: timing@cpu1 1981228712(67886(282)), 3211584883/7719566021(277/277), in millis: 8052115(1)
W (8053022) TIME API: timing@cpu1 2027760812(46532100(193883)), 3211778775/7720230577(193892/664556), in millis: 8052809(694)
W (8059723) TIME API: timing@cpu1 2432887494(78965(329)), 3213466795/7726657220(323/323), in millis: 8059510(0)
W (8060417) TIME API: timing@cpu1 2481210626(48323132(201346)), 3213668147/7727306043(201352/648823), in millis: 8060204(694)

as Arduino IDE component:

timing@cpu1 634691767(482970(2012)) 2644549/2615061(2011/2011), in millis: 2614(2)
timing@cpu1 797158638(162466871(676945)) 3321495/3292006(676946/676945), in millis: 3291(677)
timing@cpu1 2074474690(322389(1343)) 8643645/8614156(1342/1341), in millis: 8613(1)
timing@cpu1 2236918638(162443948(676849)) 9320495/9291006(676850/676850), in millis: 9290(677)
timing@cpu1 3514217081(63517(264)) 14642572/14613083(264/263), in millis: 14612(0)
timing@cpu1 3676678638(162461557(676923)) 15319495/15290006(676923/676923), in millis: 15289(677)
timing@cpu1 659261895(77451(322)) 20642622/20613133(321/321), in millis: 20612(0)
timing@cpu1 821711342(162449447(676872)) 21319495/21290006(676873/676873), in millis: 21289(677)
timing@cpu1 2099265873(81147(338)) 26642639/26613150(337/336), in millis: 26612(0)
timing@cpu1 2261711342(162445469(676856)) 27319495/27290006(676856/676856), in millis: 27289(677)
timing@cpu1 3539240286(55848(232)) 32642532/32613043(231/231), in millis: 32612(0)
timing@cpu1 3701711342(162471056(676962)) 33319495/33290006(676963/676963), in millis: 33289(677)

As you can see I have 20ms penalty using millis() method, which isn't seen If I use diff provided from values of methods esp_timer_get_time.
micros() are reasonable on small range, but not always!

[igrr]

Please give #1424 a try, it should make micros and millis values more consistent.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed in 14 days if no further activity occurs. Thank you for your contributions.

[stale]

This stale issue has been automatically closed. Thank you for your contributions.