esp_wifi_get_tsf_time takes "long" time to execute ~48us

[david@millares.se]

I try to use esp_wifi_get_tsf_time on esp32s2 to timestamp an periodic event on the connected stations. My problem is that esp_wifi_get_tsf_time takes around 48 micro-seconds to evaluate and the periodic event is faster than that (< 30us)

Is there a way to speed up the reading of the TSF time?

I have tried set up an HW timer to the value of TSF to improve read time. That works but I lose precision and can't compare the timestamp from different stations.

[danyo93]

Use the

Code: Select all

esp_mesh_get_tsf_time()

function in esp_mesh.h (https://github.com/espressif/esp-idf/bl ... sh.h#L1515), it's way faster (<1us).

Here's a console log of 25 consecutive TSF timestamp readouts using the mesh-lib function:

Code: Select all

␛[0;32mI (8884) SyncTSF: <------------------- TIMESTAMP LOG START ------------------->␛[0m
␛[0;32mI (8884) SyncTSF: TSF Timestamp idx 0: 740327222␛[0m
␛[0;32mI (8884) SyncTSF: TSF Timestamp idx 1: 740327227␛[0m
␛[0;32mI (8884) SyncTSF: TSF Timestamp idx 2: 740327228␛[0m
␛[0;32mI (8894) SyncTSF: TSF Timestamp idx 3: 740327229␛[0m
␛[0;32mI (8894) SyncTSF: TSF Timestamp idx 4: 740327230␛[0m
␛[0;32mI (8904) SyncTSF: TSF Timestamp idx 5: 740327231␛[0m
␛[0;32mI (8904) SyncTSF: TSF Timestamp idx 6: 740327231␛[0m
␛[0;32mI (8914) SyncTSF: TSF Timestamp idx 7: 740327232␛[0m
␛[0;32mI (8914) SyncTSF: TSF Timestamp idx 8: 740327233␛[0m
␛[0;32mI (8924) SyncTSF: TSF Timestamp idx 9: 740327234␛[0m
␛[0;32mI (8934) SyncTSF: TSF Timestamp idx 10: 740327235␛[0m
␛[0;32mI (8934) SyncTSF: TSF Timestamp idx 11: 740327236␛[0m
␛[0;32mI (8944) SyncTSF: TSF Timestamp idx 12: 740327237␛[0m
␛[0;32mI (8944) SyncTSF: TSF Timestamp idx 13: 740327238␛[0m
␛[0;32mI (8954) SyncTSF: TSF Timestamp idx 14: 740327238␛[0m
␛[0;32mI (8954) SyncTSF: TSF Timestamp idx 15: 740327239␛[0m
␛[0;32mI (8964) SyncTSF: TSF Timestamp idx 16: 740327240␛[0m
␛[0;32mI (8964) SyncTSF: TSF Timestamp idx 17: 740327241␛[0m
␛[0;32mI (8974) SyncTSF: TSF Timestamp idx 18: 740327242␛[0m
␛[0;32mI (8974) SyncTSF: TSF Timestamp idx 19: 740327243␛[0m
␛[0;32mI (8984) SyncTSF: TSF Timestamp idx 20: 740327244␛[0m
␛[0;32mI (8984) SyncTSF: TSF Timestamp idx 21: 740327245␛[0m
␛[0;32mI (8994) SyncTSF: TSF Timestamp idx 22: 740327245␛[0m
␛[0;32mI (9004) SyncTSF: TSF Timestamp idx 23: 740327246␛[0m
␛[0;32mI (9004) SyncTSF: TSF Timestamp idx 24: 740327247␛[0m
␛[0;32mI (9014) SyncTSF: <-------------------- TIMESTAMP LOG END -------------------->␛[0m

--- exit ---

And here is the same using the WiFi-lib function:

Code: Select all

␛[0;32mI (8914) SyncTSF: <------------------- TIMESTAMP LOG START ------------------->␛[0m
␛[0;32mI (8914) SyncTSF: TSF Timestamp idx 0: 1143745768␛[0m
␛[0;32mI (8914) SyncTSF: TSF Timestamp idx 1: 1143745870␛[0m
␛[0;32mI (8924) SyncTSF: TSF Timestamp idx 2: 1143745952␛[0m
␛[0;32mI (8924) SyncTSF: TSF Timestamp idx 3: 1143746034␛[0m
␛[0;32mI (8934) SyncTSF: TSF Timestamp idx 4: 1143746116␛[0m
␛[0;32mI (8934) SyncTSF: TSF Timestamp idx 5: 1143746198␛[0m
␛[0;32mI (8944) SyncTSF: TSF Timestamp idx 6: 1143746280␛[0m
␛[0;32mI (8944) SyncTSF: TSF Timestamp idx 7: 1143746362␛[0m
␛[0;32mI (8954) SyncTSF: TSF Timestamp idx 8: 1143746444␛[0m
␛[0;32mI (8954) SyncTSF: TSF Timestamp idx 9: 1143746527␛[0m
␛[0;32mI (8964) SyncTSF: TSF Timestamp idx 10: 1143746609␛[0m
␛[0;32mI (8964) SyncTSF: TSF Timestamp idx 11: 1143746691␛[0m
␛[0;32mI (8974) SyncTSF: TSF Timestamp idx 12: 1143746773␛[0m
␛[0;32mI (8974) SyncTSF: TSF Timestamp idx 13: 1143746855␛[0m
␛[0;32mI (8984) SyncTSF: TSF Timestamp idx 14: 1143746937␛[0m
␛[0;32mI (8994) SyncTSF: TSF Timestamp idx 15: 1143747019␛[0m
␛[0;32mI (8994) SyncTSF: TSF Timestamp idx 16: 1143747101␛[0m
␛[0;32mI (9004) SyncTSF: TSF Timestamp idx 17: 1143747183␛[0m
␛[0;32mI (9004) SyncTSF: TSF Timestamp idx 18: 1143747266␛[0m
␛[0;32mI (9014) SyncTSF: TSF Timestamp idx 19: 1143747348␛[0m
␛[0;32mI (9014) SyncTSF: TSF Timestamp idx 20: 1143747438␛[0m
␛[0;32mI (9024) SyncTSF: TSF Timestamp idx 21: 1143747520␛[0m
␛[0;32mI (9024) SyncTSF: TSF Timestamp idx 22: 1143747602␛[0m
␛[0;32mI (9034) SyncTSF: TSF Timestamp idx 23: 1143747684␛[0m
␛[0;32mI (9034) SyncTSF: TSF Timestamp idx 24: 1143747766␛[0m
␛[0;32mI (9044) SyncTSF: <-------------------- TIMESTAMP LOG END -------------------->␛[0m

Note however, that the mesh function will only read the STA MAC's TSF-timer value. So to use this function with an AP, you'd either have to put it in APSTA mode and use the STA's TSF-timer for synchronization or you find a way to start the STA TSF-timer without the STA actually running.

[david@millares.se]

Thanks esp_timer_get_time() is way faster, around 10us (instead of 48us). I will test if that is fast enough for my application.

I have tested to read it once every second in an GPIO ISR. One interesting thing is if I read it twice the second read is fast <2us

Example code:

Code: Select all

static void IRAM_ATTR gpio_isr_handler(void* arg)
{
  start_time = esp_timer_get_time();
  tsf_time1 = esp_mesh_get_tsf_time();
  tsf_time2 = esp_mesh_get_tsf_time();
  end_time = esp_timer_get_time();
  esp_rom_printf("%lld %lld (%lld us)\n", tsf_time1, tsf_time2, end_time - start_time);
}

Single read

Code: Select all

3577430718 (10 us)
3578430716 (9 us)
3579430717 (9 us)
3580430715 (9 us)
3581430716 (9 us)

esp-idf: git-sha 73db142403c6e5b763a0e1c07312200e9b622673
Double read

Code: Select all

3572430714 3572430716 (7 us)
3573430716 3573430718 (9 us)
3574430716 3574430718 (10 us)
3575430716 3575430718 (9 us)
3576430716 3576430718 (9 us)

[danyo93]

Yeah, if you look at my log of esp_mesh_get_tsf_time() you can see that the first read also was slower than the rest. That's a bit unfortunate. Maybe it's worth opening a GitHub issue since it seems to be deterministic behavior.