[TW#17088] vTaskDelay accuracy

chegewara commented 6 years ago

I understand that is not accurate and sometimes delay set by vTaskDelay() can be longer than required, but how to explain delays shorter than we setup. Piece of code and logs:

    while(1){
        // do some stuff here
        vTaskDelay(2000);
    }

D (207877) BLEServer: << handleGATTServerEvent
D (209848)
......
D (210205) BLEServer: << handleGATTServerEvent
D (212175)
......
D (212531) BLEServer: << handleGATTServerEvent
D (214502)

Spritetm commented 6 years ago

Not entirely sure what the timestamps in your log are, nor what your tick frequency is set to, but vTaskDelay can be off (too quick) by one tick: it will count the current tick as one tick, even if that tick is 99% over.

chegewara commented 6 years ago

My tick frequency is 1000 so its about 1,5%. Close enough, thanks.

projectgus commented 6 years ago

So, if I calculate correctly. the deltas here (in miliseconds ie ticks) are:

1971
1970
1971

Is it possible each of the two logs are happening on different cores? Some work has been done to synchronise the time stamps between cores but there may still be a small offset.

Daivyge commented 6 years ago

you can try to use vTaskDelayUntil

chegewara commented 6 years ago

@projectgus As far as i understand esp-idf multicore functionality i can say its all logs from 1 task, which means its happening on the same core.

@Daivyge Thanks, i know, just wanted to understand this mechanism. Its not an issue per se, just how esp-idf works internally.

projectgus commented 6 years ago

As far as i understand esp-idf multicore functionality i can say its all logs from 1 task, which means its happening on the same core.

If the task is pinned to a core, then yes it's the same core.

If the task is not pinned to a core, then it can migrate between ticks - so it may be the same core or a different core.

You can include the output of xPortGetCoreID() in your log output to be sure.

It does seem like there's potentially a bug in the scheduler here (sleeping ~30 ticks less than requested), so feel free to keep this open if you like.

chegewara commented 6 years ago

Im not sure it is a bug. Like @Spritetm explained there is 1% fluctuation and from my logs we can see its 1,5%(it may be temperature dependent). To me its close enough, but if dev team may be thinking its potencialy bug then feel free to reopen. Im satisfied with explanation.

projectgus commented 6 years ago

Not 1%, there is a maximum of 1 tick of difference (the percentage he gave was an example of how the "first tick" the scheduler counts may only be 1% of that full tick's time). If I'm not wrong, you're seeing 30 ticks of difference.

chegewara commented 6 years ago

Yes, its about 30 ticks on every loop with vTaskDelay(2000) and tick rate 1000Hz.

Seems i have to deliver more informations. Its bluetooth LE application with 2 services, 11 characteristics and 5 descriptors in total. Logic is very simple because its skeleton to ble hid keyboard and as for now only thing its doing is sending key down and key up signals in loop when client is connected.

projectgus commented 6 years ago

Something unusual is happening here. If I write a trivial test case like this then I get expected behaviour: https://gist.github.com/projectgus/dbdb7c4789779aa7d3afd2432dd21f41

(Task migrates cores, and is sometimes delayed 10ms waiting for the "fuzzer" tasks, but never returns in less than 1000ms.)

Is there anything else you can tell us about your app configuration which might be relevant?

chegewara commented 6 years ago

This is application i am having issue with. After flashing and running it its required to connect hid keyboard to any device capable to do it, like smartphone or laptop.

https://github.com/chegewara/vtaskdelay_issue.git

chegewara commented 6 years ago

This is commit i am currently working on HEAD is now at 8688f0e Merge branch 'feature/monitor_log_toggle'

chegewara commented 6 years ago

Hi @projectgus, i have not tested if something has been changed in this matter, also i dont work with esp32 for few weeks now, except simple project esp32 + augmented reality. If you feel or know it has been fixed then it can be closed, thanks.

chegewara commented 6 years ago

I see 2 possibilities here:

its something wrong with C/C++
its my app fault

Each command line is triggered every 100 ms (in theory):

W (616702) MIDIDemo: command: 153, note: 48, data: 162, 217, 127
W (616762) MIDIDemo: command: 137, note: 48, data: 163, 150, 127
W (616822) MIDIDemo: command: 153, note: 51, data: 163, 209, 127
W (617002) MIDIDemo: command: 137, note: 51, data: 165, 133, 127
W (617062) MIDIDemo: command: 153, note: 57, data: 165, 194, 127
W (617182) MIDIDemo: command: 137, note: 57, data: 166, 185, 127
W (617242) MIDIDemo: command: 153, note: 56, data: 166, 245, 127
W (617362) MIDIDemo: command: 137, note: 56, data: 167, 237, 127
W (617482) MIDIDemo: command: 153, note: 51, data: 168, 229, 127
W (617542) MIDIDemo: command: 137, note: 51, data: 169, 162, 127
W (617722) MIDIDemo: command: 153, note: 54, data: 170, 213, 127
W (617722) MIDIDemo: command: 137, note: 54, data: 170, 215, 127
W (617842) MIDIDemo: command: 153, note: 51, data: 171, 205, 127
W (617962) MIDIDemo: command: 137, note: 51, data: 172, 197, 127
W (618022) MIDIDemo: command: 153, note: 58, data: 173, 129, 127
W (618262) MIDIDemo: command: 137, note: 58, data: 174, 241, 127
W (618262) MIDIDemo: command: 153, note: 51, data: 174, 243, 127
W (618322) MIDIDemo: command: 137, note: 51, data: 175, 174, 127
W (618502) MIDIDemo: command: 153, note: 56, data: 176, 225, 127
W (618622) MIDIDemo: command: 137, note: 56, data: 177, 218, 127

This example is running with tick rate 100 Hz and CPU freq 160MHz. Latest commit.

projectgus commented 6 years ago

Hi @chegewara ,

Can you post any code showing how this log line comes to be printed?

Angus

chegewara commented 6 years ago

Hi @projectgus Sure, but like i said, its midi app that is sending tone on/off with constant timing and i can clearly hear in client app on android or windows it does not sound like a metronome.

Above logs are from app that sends midi command to windows midi app, midi app is patching midi commands to midi device (in this case its the same esp32) and i am printing value from ble characteristic on received event:

class MyCallbacks : public BLECharacteristicCallbacks {
  void onWrite(BLECharacteristic* pChar){
    Serial.println(pChar->getValue().c_str());
  }
};

This is full app code if you want to test it (i can provide arduino code too): https://github.com/nkolban/esp32-snippets/issues/510#issuecomment-385625596

negativekelvin commented 6 years ago

I think based on the fact that your log timestamps are from a callback that depends on ble stack and rf channel parameters and they are all multiples of 60ms it suggests this could be due to your connection interval and nothing to do with task timing.

chegewara commented 6 years ago

@negativekelvin Try to explain this. The same example, the same testing environment but tick rate 1000 Hz and CPU freq 240MHz.

W (58744) MIDIDemo: command: 137, note: 55, data: 128, 162, 127
W (58819) MIDIDemo: command: 153, note: 54, data: 128, 231, 127
W (58931) MIDIDemo: command: 137, note: 54, data: 129, 215, 127
W (59044) MIDIDemo: command: 153, note: 56, data: 130, 201, 127
W (59156) MIDIDemo: command: 137, note: 56, data: 131, 184, 127
W (59231) MIDIDemo: command: 153, note: 51, data: 132, 131, 127
W (59344) MIDIDemo: command: 137, note: 51, data: 132, 244, 127
W (59456) MIDIDemo: command: 153, note: 53, data: 133, 228, 127
W (59569) MIDIDemo: command: 137, note: 53, data: 134, 213, 127
W (59644) MIDIDemo: command: 153, note: 50, data: 135, 159, 127
W (59831) MIDIDemo: command: 137, note: 50, data: 136, 182, 127
W (59869) MIDIDemo: command: 153, note: 60, data: 137, 129, 127
W (59981) MIDIDemo: command: 137, note: 60, data: 137, 241, 127
W (60056) MIDIDemo: command: 153, note: 48, data: 138, 188, 127
W (60169) MIDIDemo: command: 137, note: 48, data: 139, 173, 127

I can accept that something is wrong with my app, i can accept that its normal ble behavior, but i have "gift". Sometimes when i see numbers i can say there is something wrong even if i cant explain what it is. What i see here is inconsistency. For me this line should always delay my code of the same value even if BLE connection interval is messing with it, and should not be shorter than 100 ms. No matter what is time tick or cpu clock. vTaskDelay(100/portTICK_PERIOD_MS);

negativekelvin commented 6 years ago

Now they are multiples of 37. So you are saying 60:37::160mhz:240mhz? It would help if you print a log when the command is issued not just the callback.

chegewara commented 6 years ago

I will wait for official response.

projectgus commented 6 years ago

I agree adding log lines in MyTask is a very good suggestion, to compare log timestamps in MyTask with the callback timestamps - the latter happen in a different task and are subject to different timing constraints.

@negativekelvin's suggestion that this a property of the BLE connection interval sounds very likely to me. The library you're using seems to set 40ms - 80ms (1.25ms time interval units) as the default window of accepted connection intervals, and this in the ballpark of the amount of jitter you're getting: https://github.com/nkolban/esp32-snippets/blob/master/cpp_utils/BLEAdvertising.cpp#L42-L43

If you set both these values to the minimum allowed (BTM_BLE_CONN_INT_MIN_LIMIT == 0x09 == 11.25ms), you may find the callback timing tightens up significantly.

chegewara commented 6 years ago

@projectgus Thanks, if you dont think its an issue then i dont care if it is or not an issue.

projectgus commented 6 years ago

@chegewara I appreciate that you want the app's BLE MIDI timing to approve. I don't know what the root cause here is, or if there's an underlying issue in ESP-IDF. The suggestions I made above might help, or at least they will add more information to rule some things out.

If you have time to try the two things suggested above (logging in myTask as well as the callback, and reducing the requested BLE connection interval) then I'm happy to look at the results if the app still isn't behaving as expected.

chegewara commented 6 years ago

Let me know if you need explanation.

nRF Connect, 2018-05-03
ESP32 (24:0A:C4:03:B1:C2)
V   07:13:37.758    Connecting to 24:0A:C4:03:B1:C2...
D   07:13:37.758    gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D   07:13:38.080    [Callback] Connection state changed with status: 133 and new state: DISCONNECTED (0)
E   07:13:38.081    Error 133 (0x85): GATT ERROR
I   07:13:38.081    Disconnected
D   07:13:41.232    gatt.close()
D   07:13:41.238    wait(200)
V   07:13:41.442    Connecting to 24:0A:C4:03:B1:C2...
D   07:13:41.442    gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D   07:13:41.825    [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D   07:13:41.837    [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   07:13:41.837    Connected to 24:0A:C4:03:B1:C2
V   07:13:41.879    Discovering services...
D   07:13:41.879    gatt.discoverServices()
I   07:13:42.337    Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
D   07:13:42.499    [Callback] Services discovered with status: 0
I   07:13:42.499    Services discovered
V   07:13:42.525    Generic Attribute (0x1801)
- Service Changed [I] (0x2A05)
Generic Access (0x1800)
- Device Name [R] (0x2A00)
- Appearance [R] (0x2A01)
- Central Address Resolution [R] (0x2AA6)
Unknown Service (03b80e5a-ede8-4b33-a751-6ce34ec4c700)
- Unknown Characteristic [N R WNR] (7772e5db-3868-4112-a1a9-f2669d106bf3)
   Client Characteristic Configuration (0x2902)
D   07:13:42.525    gatt.setCharacteristicNotification(7772e5db-3868-4112-a1a9-f2669d106bf3, true)
I   07:13:42.587    Connection parameters updated (interval: 47.5ms, latency: 0, timeout: 5000ms)
V   07:13:45.654    Enabling notifications for 7772e5db-3868-4112-a1a9-f2669d106bf3
D   07:13:45.655    gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x0100)
I   07:13:45.721    Data written to descr. 00002902-0000-1000-8000-00805f9b34fb, value: (0x) 01-00
A   07:13:45.721    "Notifications enabled" sent
V   07:13:45.730    Notifications enabled for 7772e5db-3868-4112-a1a9-f2669d106bf3
I   07:13:45.817    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-30-7F
A   07:13:45.817    "(0x) 80-80-99-30-7F" received
I   07:13:45.912    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-30-7F
A   07:13:45.912    "(0x) 80-80-89-30-7F" received
I   07:13:46.006    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-33-7F
A   07:13:46.006    "(0x) 80-80-99-33-7F" received
I   07:13:46.101    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-33-7F
A   07:13:46.101    "(0x) 80-80-89-33-7F" received
I   07:13:46.198    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-36-7F
A   07:13:46.198    "(0x) 80-80-99-36-7F" received
I   07:13:46.294    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-36-7F
A   07:13:46.294    "(0x) 80-80-89-36-7F" received
I   07:13:46.437    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-38-7F
A   07:13:46.437    "(0x) 80-80-99-38-7F" received
I   07:13:46.531    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-38-7F
A   07:13:46.531    "(0x) 80-80-89-38-7F" received
I   07:13:46.625    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-33-7F
A   07:13:46.625    "(0x) 80-80-99-33-7F" received
I   07:13:46.721    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-33-7F
A   07:13:46.721    "(0x) 80-80-89-33-7F" received
I   07:13:46.817    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-32-7F
A   07:13:46.817    "(0x) 80-80-99-32-7F" received
I   07:13:46.912    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-32-7F
A   07:13:46.921    "(0x) 80-80-89-32-7F" received
I   07:13:47.053    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-34-7F
A   07:13:47.053    "(0x) 80-80-99-34-7F" received
I   07:13:47.148    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-34-7F
A   07:13:47.148    "(0x) 80-80-89-34-7F" received
I   07:13:47.243    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-3C-7F
A   07:13:47.244    "(0x) 80-80-99-3C-7F" received
I   07:13:47.338    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-3C-7F
A   07:13:47.339    "(0x) 80-80-89-3C-7F" received
I   07:13:47.431    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-38-7F
A   07:13:47.431    "(0x) 80-80-99-38-7F" received
I   07:13:47.527    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-38-7F
A   07:13:47.527    "(0x) 80-80-89-38-7F" received
I   07:13:47.669    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-39-7F
A   07:13:47.669    "(0x) 80-80-99-39-7F" received
I   07:13:47.764    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-39-7F
A   07:13:47.764    "(0x) 80-80-89-39-7F" received
I   07:13:47.860    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-33-7F
A   07:13:47.860    "(0x) 80-80-99-33-7F" received
I   07:13:47.953    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-33-7F
A   07:13:47.953    "(0x) 80-80-89-33-7F" received
I   07:13:48.048    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-38-7F
A   07:13:48.048    "(0x) 80-80-99-38-7F" received
I   07:13:48.143    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-38-7F
A   07:13:48.143    "(0x) 80-80-89-38-7F" received
I   07:13:48.239    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-32-7F
A   07:13:48.239    "(0x) 80-80-99-32-7F" received
I   07:13:48.333    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-32-7F
A   07:13:48.333    "(0x) 80-80-89-32-7F" received
I   07:13:48.476    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-32-7F
A   07:13:48.476    "(0x) 80-80-99-32-7F" received
I   07:13:48.571    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-32-7F
A   07:13:48.571    "(0x) 80-80-89-32-7F" received
I   07:13:48.668    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-37-7F
A   07:13:48.668    "(0x) 80-80-99-37-7F" received
I   07:13:48.763    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-37-7F
A   07:13:48.763    "(0x) 80-80-89-37-7F" received
I   07:13:48.857    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-39-7F
A   07:13:48.858    "(0x) 80-80-99-39-7F" received
I   07:13:48.959    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-39-7F
A   07:13:48.959    "(0x) 80-80-89-39-7F" received
I   07:13:49.047    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-39-7F
A   07:13:49.047    "(0x) 80-80-99-39-7F" received
I   07:13:49.190    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-39-7F
A   07:13:49.190    "(0x) 80-80-89-39-7F" received
I   07:13:49.285    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-31-7F
A   07:13:49.285    "(0x) 80-80-99-31-7F" received
I   07:13:49.382    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-31-7F
A   07:13:49.382    "(0x) 80-80-89-31-7F" received
I   07:13:49.475    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-39-7F
A   07:13:49.476    "(0x) 80-80-99-39-7F" received
I   07:13:49.576    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-39-7F
A   07:13:49.576    "(0x) 80-80-89-39-7F" received
I   07:13:49.664    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-34-7F
A   07:13:49.664    "(0x) 80-80-99-34-7F" received
I   07:13:49.808    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-34-7F
A   07:13:49.808    "(0x) 80-80-89-34-7F" received
I   07:13:49.904    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-32-7F
A   07:13:49.904    "(0x) 80-80-99-32-7F" received
I   07:13:49.998    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-32-7F
A   07:13:49.999    "(0x) 80-80-89-32-7F" received
I   07:13:50.092    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-3A-7F
A   07:13:50.092    "(0x) 80-80-99-3A-7F" received
I   07:13:50.186    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-3A-7F
A   07:13:50.186    "(0x) 80-80-89-3A-7F" received
I   07:13:50.291    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-31-7F
A   07:13:50.291    "(0x) 80-80-99-31-7F" received
I   07:13:50.376    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-31-7F
A   07:13:50.376    "(0x) 80-80-89-31-7F" received
I   07:13:50.520    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-32-7F
A   07:13:50.520    "(0x) 80-80-99-32-7F" received
I   07:13:50.616    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-32-7F
A   07:13:50.616    "(0x) 80-80-89-32-7F" received
I   07:13:50.710    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-35-7F
A   07:13:50.710    "(0x) 80-80-99-35-7F" received
I   07:13:50.805    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-35-7F
A   07:13:50.805    "(0x) 80-80-89-35-7F" received
I   07:13:50.904    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-35-7F
A   07:13:50.904    "(0x) 80-80-99-35-7F" received
I   07:13:50.995    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-35-7F
A   07:13:50.996    "(0x) 80-80-89-35-7F" received
I   07:13:51.096    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-34-7F
A   07:13:51.096    "(0x) 80-80-99-34-7F" received
I   07:13:51.234    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-34-7F
A   07:13:51.234    "(0x) 80-80-89-34-7F" received
I   07:13:51.328    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-36-7F
A   07:13:51.328    "(0x) 80-80-99-36-7F" received
I   07:13:51.429    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-36-7F
A   07:13:51.429    "(0x) 80-80-89-36-7F" received
I   07:13:51.529    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-33-7F
A   07:13:51.530    "(0x) 80-80-99-33-7F" received
I   07:13:51.611    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-33-7F
A   07:13:51.611    "(0x) 80-80-89-33-7F" received
I   07:13:51.708    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-33-7F
A   07:13:51.708    "(0x) 80-80-99-33-7F" received
I   07:13:51.849    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-33-7F
A   07:13:51.849    "(0x) 80-80-89-33-7F" received
I   07:13:51.946    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-35-7F
A   07:13:51.946    "(0x) 80-80-99-35-7F" received
I   07:13:52.039    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-35-7F
A   07:13:52.039    "(0x) 80-80-89-35-7F" received
I   07:13:52.180    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-35-7F
A   07:13:52.180    "(0x) 80-80-99-35-7F" received
I   07:13:52.230    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-35-7F
A   07:13:52.230    "(0x) 80-80-89-35-7F" received
I   07:13:52.332    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-33-7F
A   07:13:52.332    "(0x) 80-80-99-33-7F" received
I   07:13:52.419    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-33-7F
A   07:13:52.419    "(0x) 80-80-89-33-7F" received
I   07:13:52.562    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-35-7F
A   07:13:52.562    "(0x) 80-80-99-35-7F" received
I   07:13:52.656    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-35-7F
A   07:13:52.656    "(0x) 80-80-89-35-7F" received
V   07:13:52.686    Disconnecting...
D   07:13:52.686    gatt.disconnect()
D   07:13:52.693    [Callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I   07:13:52.693    Disconnected
D   07:13:52.752    [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I   07:13:52.752    Connected to 24:0A:C4:03:B1:C2
I   07:13:52.754    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-35-7F
A   07:13:52.754    "(0x) 80-80-99-35-7F" received
V   07:13:52.783    Discovering services...
D   07:13:52.783    gatt.discoverServices()
I   07:13:53.186    Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
D   07:13:53.356    [Callback] Services discovered with status: 0
I   07:13:53.356    Services discovered
V   07:13:53.381    Generic Attribute (0x1801)
- Service Changed [I] (0x2A05)
Generic Access (0x1800)
- Device Name [R] (0x2A00)
- Appearance [R] (0x2A01)
- Central Address Resolution [R] (0x2AA6)
Unknown Service (03b80e5a-ede8-4b33-a751-6ce34ec4c700)
- Unknown Characteristic [N R WNR] (7772e5db-3868-4112-a1a9-f2669d106bf3)
   Client Characteristic Configuration (0x2902)
D   07:13:53.381    gatt.setCharacteristicNotification(7772e5db-3868-4112-a1a9-f2669d106bf3, true)
I   07:13:53.476    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-3C-7F
A   07:13:53.476    "(0x) 80-80-89-3C-7F" received
I   07:13:53.477    Connection parameters updated (interval: 47.5ms, latency: 0, timeout: 5000ms)
I   07:13:53.559    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-34-7F
A   07:13:53.559    "(0x) 80-80-99-34-7F" received
I   07:13:53.653    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-34-7F
A   07:13:53.653    "(0x) 80-80-89-34-7F" received
I   07:13:53.798    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-31-7F
A   07:13:53.798    "(0x) 80-80-99-31-7F" received
I   07:13:53.894    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-31-7F
A   07:13:53.894    "(0x) 80-80-89-31-7F" received
I   07:13:53.989    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-3C-7F
A   07:13:53.989    "(0x) 80-80-99-3C-7F" received
I   07:13:54.083    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-3C-7F
A   07:13:54.083    "(0x) 80-80-89-3C-7F" received
I   07:13:54.176    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-35-7F
A   07:13:54.176    "(0x) 80-80-99-35-7F" received
I   07:13:54.275    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-35-7F
A   07:13:54.275    "(0x) 80-80-89-35-7F" received
D   07:13:54.384    [Callback] Connection state changed with status: 22 and new state: DISCONNECTED (0)
E   07:13:54.384    Error 22 (0x16): GATT CONN TERMINATE LOCAL HOST
I   07:13:54.384    Disconnected
D   07:13:54.491    [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED

projectgus commented 6 years ago

@chegewara This log seems to confirm a high BLE interval value being negotiated for the connection:

I   07:13:42.587    Connection parameters updated (interval: 47.5ms, latency: 0, timeout: 5000ms)

Based on this, BLE events (and the callbacks resulting from them) should be happening at 47.5ms intervals. So the sequence of events is something like:

myTask sleeps 100ms
myTask wakes up, initiates BLE operation, goes back to sleep
BT controller waits for the next 47.5ms connection interval period (could be a delay of anywhere from 0 to 47.5ms, depending on the relative timing of the two events), performs BLE operation.
Result goes into queue for callback, is pushed to callback
myTask wakes up again 100ms after it went to sleep, initiates next BLE operation

(Plus probably some small overhead due to tasks being scheduled, data being copied around, etc.)

chegewara commented 6 years ago

This two events occurs every 100 ms, as far as i can count something is not right here:

I   07:13:53.798    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-31-7F
A   07:13:53.798    "(0x) 80-80-99-31-7F" received
I   07:13:53.894    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-31-7F
A   07:13:53.894    "(0x) 80-80-89-31-7F" received

my math maybe is not academic but 894-798 is less than 100 ms. Have a nice day.

negativekelvin commented 6 years ago

Yes it is 96 which is exactly two connection intervals and I think there is another bug report on here somewhere about missed connection intervals. So if the commands are staying in the ble queue longer than expected this result could occur.

projectgus commented 6 years ago

The notification before those two happens at "07:13:53.653". So the time deltas are (798-653)=145ms (3 47.5ms) and (894-798)=96ms (2 47.5ms).

In total, I count 9 notifications in 798ms which means on average they are coming at close to 100ms intervals on average.

Why is this happening? Think of it like this:

myTask is pushing requests into a queue every 100ms
Separately, the BT controller is checking that queue every 47.5ms and it can process one request per interval at most. Sometimes it might skip an entire interval or two, if data is lost or there's RF interference at that moment in time. Only broadcasting at certain short intervals is the Low Energy part of BLE.

The solution is to change the acceptable BLE max_int and min_int intervals in your app to a lower value, so you get a lower connection interval period than 47.5ms.

47.5ms is fine for non real-time data (and uses less power), but you want real-time data for MIDI...

chegewara commented 6 years ago

@negativekelvin @projectgus You still dont understand? Those two events are trigerred and should be send every 100ms + eventually overhead but are received in less than 100 ms. Do we have time travel here? But you know what, im done here.

PS that has nothing to do with midi, its ble data send every 100+ ms but received in 90-ish ms

projectgus commented 6 years ago

Those two events are trigerred and should be send every 100ms + eventually overhead but are received in less than 100 ms

I understand that you think you are getting messages sent at less than 100ms intervals. But you aren't. I'll show you based on the log above:

07:13:53.400 - myTask pushes note 1 into the BLE queue to be sent. (80-80-89-3C-7F)

I   07:13:53.476    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-3C-7F
A   07:13:53.476    "(0x) 80-80-89-3C-7F" received <--- note 1
I   07:13:53.477    Connection parameters updated (interval: 47.5ms, latency: 0, timeout: 5000ms)

07:13:53.500 - myTask pushes note 2 into the BLE queue to be sent.  (80-80-99-34-7F)

I   07:13:53.559    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-34-7F
A   07:13:53.559    "(0x) 80-80-99-34-7F" received <-- note 2

07:13:53.600 - myTask pushes note 3 into the BLE queue to be sent.  (80-80-89-34-7F)

I   07:13:53.653    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-34-7F
A   07:13:53.653    "(0x) 80-80-89-34-7F" received  <-- note 3

07:13:53.700 - myTask pushes note 4 into the BLE queue to be sent.  (80-80-99-31-7F)

I   07:13:53.798    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-31-7F
A   07:13:53.798    "(0x) 80-80-99-31-7F" received  <-- note 4

07:13:53.800 - myTask pushes note 5 into the BLE queue to be sent.  (80-80-89-31-7F)

I   07:13:53.894    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-31-7F <-- note 5
A   07:13:53.894    "(0x) 80-80-89-31-7F" received <-- note 5

07:13:53.900 - myTask pushes note 6 into the BLE queue to be sent.  (80-80-99-3C-7F)

I   07:13:53.989    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-3C-7F  <-- note 6
A   07:13:53.989    "(0x) 80-80-99-3C-7F" received

07:13:54.000 - myTask pushes note 7 into the BLE queue to be sent.  (80-80-89-3C-7F)

I   07:13:54.083    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-3C-7F
A   07:13:54.083    "(0x) 80-80-89-3C-7F" received <-- note 7

07:13:54.100 - myTask pushes note 8 into the BLE queue to be sent.  (80-80-99-35-7F)

I   07:13:54.176    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-35-7F
A   07:13:54.176    "(0x) 80-80-99-35-7F" received <-- note 8

07:13:54.200 - myTask pushes note 9 into the BLE queue to be sent.  (80-80-89-35-7F)

I   07:13:54.275    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-35-7F
A   07:13:54.275    "(0x) 80-80-89-35-7F" received <-- note 9

This is how BLE works. BLE can only send data at the connection interval, which is negotiated for the connection. If you have a 47.5ms connection interval then you will only ever receive data at 47.5ms intervals. Because it's a wireless protocol, sometimes intervals are skipped because of interference or some other reason.

Because ESP-IDF is a multi-tasking system, sometimes multiple requests can end up backed up in a queue even though you put them in the queue at 100ms intervals.

If you look at my post a few comments above then I already linked you to the piece of code you need to change to get a shorter connection interval, needed for real-time data results (like you need for MIDI). I can almost guarantee that if you make this change and set an 11.25ms interval, the problem will go away.

chegewara commented 6 years ago

You forget i have vTaskDelay(100ms) betwen every note send or push to ble before send:

I   07:13:53.476    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-89-3C-7F
A   07:13:53.476    "(0x) 80-80-89-3C-7F" received <--- note 1
I   07:13:53.477    Connection parameters updated (interval: 47.5ms, latency: 0, timeout: 5000ms)
**vTaskDelay(100) <---- DELAY**
07:13:53.500 - myTask pushes note 2 into the BLE queue to be sent.  (80-80-99-34-7F)

I   07:13:53.559    Notification received from 7772e5db-3868-4112-a1a9-f2669d106bf3, value: (0x) 80-80-99-34-7F
A   07:13:53.559    "(0x) 80-80-99-34-7F" received <-- note 2
**vTaskDelay(100) <---- DELAY**
07:13:53.600 - myTask pushes note 3 into the BLE queue to be sent.  (80-80-89-34-7F)

And here you have 559-476 = 83 ms

projectgus commented 6 years ago

That's not how it works. When you call

pCharacteristic->setValue(midiPacket, 5); // packet, length in bytes)
pCharacteristic->notify();

This doesn't actually do anything at all with the BLE radio at that exact moment. It just queues the packet to be sent by the BLE radio the next time there is an opportunity (the opportunities happen every connection interval). It returns immediately, before anything happens at the BLE layer.

The callback is what happens after the radio has actually completed this notification or write (which is why it can happen at a weird time, as well).

So you are calling pCharacteristic->notify() at perfect 100ms intervals. But the actual radio isn't doing anything at 100ms intervals.

negativekelvin commented 6 years ago

Yes but there is phantom time before the first message is received because the transmitting device has to wait for the next connection interval.

Command at 0 Actually sent at 10 Command at 100 Actually sent at 106 Command at 200 Actually sent at 202

So at the receiving end it looks like they are 96ms apart

ourairquality commented 6 years ago

I might be seeing this issue too. Tried to simplify it down to the following example which compares the ticks to the system_get_time(). The two get out of sync quickly, losing ticks. The task is pinned to a core. Is there any workaround for this?

static void timing_test_task(void *pvParameters)
{
    TickType_t start_tick = xTaskGetTickCount();
    uint64_t start_usec = system_time_usec();

    uint32_t count;

    for (count = 0; ;count++) {
        TickType_t now_tick = xTaskGetTickCount();
        uint64_t now_usec = system_time_usec();

    TickType_t duration = 500 / portTICK_PERIOD_MS;

    TickType_t wait = (start_tick + (count + 1) * duration) - now_tick;
        vTaskDelay(wait);

        printf("%d %d %u\n", (int32_t)(now_tick - (start_tick + count * duration)), (int32_t)(now_usec - (start_usec + count * duration * 10000UL)), wait);
    }
}

ourairquality commented 6 years ago

Fwiw also checked CCOUNT and that is getting out of sync with the number of ticks too. The number of calls to xPortSysTickHandler seems to track the tick count, so might the problem be in the _xt_timer_int_catchup loop in portasm.S, might it not be looping enough to catch up on lost interrupts?

ourairquality commented 6 years ago

Sorry, the number of calls to xPortSysTickHandler looks ok.

Fwiw here is another idea. Only core 0 is allowed to increase the tick counter. When the scheduler is suspended the interrupt does not increment the tick counter, rather uxPendedTicks is increased. When scheduling is resumed xTaskResumeAll() calls xTaskIncrementTick() for each uxPendedTicks, but when called from core 1 this is a nop, yet is still decreases uxPendedTicks, and it looks like the ticks are lost there.

Not sure how this would be best fixed?

negativekelvin commented 6 years ago

@ourairquality yes that looks possibly interesting @igrr @Spritetm

https://github.com/espressif/esp-idf/blob/22fbcd276c90049b906702fde1744fd24d438be3/components/freertos/tasks.c#L2475

https://github.com/espressif/esp-idf/blob/22fbcd276c90049b906702fde1744fd24d438be3/components/freertos/tasks.c#L2245

projectgus commented 6 years ago

Hi @ourairquality ,

Thanks for providing these details and the analysis.

I think this is a different issue to the one originally reported here (the original issue was about vTaskDelay() returning with a lower tick count than expected. In this case tick count will look normal but wall time is longer than expected due to the lost ticks).

I'm going to open another issue to continue this discussion.

Angus

espressif / esp-idf

[TW#17088] vTaskDelay accuracy #1400