Esp32-snippets: Memory leak in BLECharacteristic::notify()

Created on 1 Jan 2019 · 25Comments · Source: nkolban/esp32-snippets

The call to m_value.getValue().length() to log the message length in BLECharacteristic::notify() is causing an 84 byte memory leak.
I've added extra log statements, logging the ESP.getFreeHeap() value before and after that call (and in the method calling notify() and this is the result:

[D][BLEObserver.cpp:35] notification(): Free memory Master before notify(): 66524
[D][BLECharacteristic.cpp:485] notify(): Free memory on notify()::Enter : 66524
[D][BLECharacteristic.cpp:486] notify(): >> notify: length: 10
[D][BLECharacteristic.cpp:487] notify(): Free memory on notify(), After LOGD m_value.getValue().length(): 66440
[D][BLECharacteristic.cpp:495] notify(): << notify: No connected clients.
[D][BLEObserver.cpp:37] notification(): Free memory Master after notify(): 66440

This occurs with every call of notify, eventually draining all resources

I'm assuming that this has something to do with the way the std::string m_Value is returned by getValue()method. I tried replacing m_value.getValue().length() with m_value_getLength() but with the same results

bug study required

Source

Bascy

All 25 comments

I dont see a single byte leak here, at least with BLE arduino v1.0.1 version. Could you try?

01:20:14.774 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:20:14.774 -> 176188
01:20:14.774 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:20:14.774 -> 176188
01:20:14.774 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:20:14.774 -> 176188
01:20:14.774 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:20:14.816 -> 176188
01:20:14.816 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:20:14.816 -> 176188
01:20:14.816 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:20:14.816 -> 176188
01:20:14.816 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:20:14.816 -> 176188
01:20:14.816 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:20:14.816 -> 176188
01:20:14.863 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:20:14.863 -> 176188
01:20:14.863 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:20:14.863 -> 176188
01:20:14.863 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:20:14.863 -> 176188
01:20:14.863 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:20:14.863 -> 176188
01:20:14.863 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:20:14.863 -> 176188
01:20:14.910 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:20:14.910 -> 176188
01:20:14.910 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:20:14.910 -> 176188
01:20:14.910 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:20:14.910 -> 176188
01:20:14.910 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:20:14.910 -> 176188
01:20:14.910 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:20:14.956 -> 176188
01:20:14.956 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:20:14.956 -> 176188
01:20:14.956 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:20:14.956 -> 176188
01:20:14.956 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:20:14.956 -> 176188

chegewara on 30 Jan 2019

01:24:23.375 -> 176188
01:24:23.375 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:24:23.375 -> 176152
01:24:23.422 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:24:23.422 -> 176188
01:24:23.422 -> [E][BLECharacteristicMap.cpp:87] handleGATTServerEvent(): 42
01:24:23.422 -> 176188

chegewara on 30 Jan 2019

Can you post the source code from your tests, so we run the same tests?
I'm thinking it might have to do with the arduino esp32 library we're using, or at least something in the implementation of std:string.

Bascy on 30 Jan 2019

https://github.com/nkolban/ESP32_BLE_Arduino/blob/master/examples/BLE_notify/BLE_notify.ino

Just changed delay to 10ms:
https://github.com/nkolban/ESP32_BLE_Arduino/blob/master/examples/BLE_notify/BLE_notify.ino#L96

If its not a problem please try latest PR, there is few bugfixes.

chegewara on 30 Jan 2019

Increasing the handles to 256 and sending a long string, will reproduce the memory loss

setup() modification:

  // Create the BLE Service
  BLEService *pService = pServer->createService(BLEUUID(SERVICE_UUID), 256);

loop() modification:

    if (deviceConnected) {
        char buf[100];
        sprintf(buf, "This is a long string to test if that will lead to memory loss %d", value);
        pCharacteristic->setValue((uint8_t*)buf, strlen(buf));
        pCharacteristic->notify();
        Serial.print("Freeheap: ");
        Serial.println(ESP.getFreeHeap());
        value++;
        delay(3); // bluetooth stack will go into congestion, if too many packets are sent, in 6 hours test i was able to go as low as 3ms
    }

[D][BLECharacteristic.cpp:203] handleGATTServerEvent(): >> handleGATTServerEvent: Unknown
[D][BLECharacteristic.cpp:631] setValue(): >> setValue: length=66, data=546869732069732061206c6f6e6720737472696e6720746f207465737420696620746861742077696c6c206c65616420746f206d656d6f7279206c6f737320333333, characteristic UUID=beb5483e-36e1-4688-b7f5-ea07361b26a8
[D][BLECharacteristic.cpp:459] handleGATTServerEvent(): << handleGATTServerEvent
[D][BLECharacteristic.cpp:638] setValue(): << setValue
[D][BLEServer.cpp:280] handleGATTServerEvent(): << handleGATTServerEvent
[D][BLECharacteristic.cpp:484] notify(): >> notify: length: 66
[W][BLECharacteristic.cpp:515] notify(): - Truncating to 20 bytes (maximum notify size)
[D][BLECharacteristic.cpp:533] notify(): << notify
[D][BLEDevice.cpp:108] gattServerEventHandler(): gattServerEventHandler [esp_gatt_if: 4] ... Unknown
Freeheap: 128480
[D][BLECharacteristic.cpp:203] handleGATTServerEvent(): >> handleGATTServerEvent: Unknown
[D][BLECharacteristic.cpp:631] setValue(): >> setValue: length=66, data=546869732069732061206c6f6e6720737472696e6720746f207465737420696620746861742077696c6c206c65616420746f206d656d6f7279206c6f737320333334, characteristic UUID=beb5483e-36e1-4688-b7f5-ea07361b26a8
[D][BLECharacteristic.cpp:459] handleGATTServerEvent(): << handleGATTServerEvent
[D][BLECharacteristic.cpp:638] setValue(): << setValue
[D][BLEServer.cpp:280] handleGATTServerEvent(): << handleGATTServerEvent
[D][BLECharacteristic.cpp:484] notify(): >> notify: length: 66
[W][BLECharacteristic.cpp:515] notify(): - Truncating to 20 bytes (maximum notify size)
[D][BLECharacteristic.cpp:533] notify(): << notify
[D][BLEDevice.cpp:108] gattServerEventHandler(): gattServerEventHandler [esp_gatt_if: 4] ... Unknown
Freeheap: 128396
[D][BLECharacteristic.cpp:203] handleGATTServerEvent(): >> handleGATTServerEvent: Unknown
[D][BLECharacteristic.cpp:631] setValue(): >> setValue: length=66, data=546869732069732061206c6f6e6720737472696e6720746f207465737420696620746861742077696c6c206c65616420746f206d656d6f7279206c6f737320333335, characteristic UUID=beb5483e-36e1-4688-b7f5-ea07361b26a8
[D][BLECharacteristic.cpp:459] handleGATTServerEvent(): << handleGATTServerEvent
[D][BLECharacteristic.cpp:638] setValue(): << setValue
[D][BLEServer.cpp:280] handleGATTServerEvent(): << handleGATTServerEvent
[D][BLECharacteristic.cpp:484] notify(): >> notify: length: 66
[W][BLECharacteristic.cpp:515] notify(): - Truncating to 20 bytes (maximum notify size)
[D][BLECharacteristic.cpp:533] notify(): << notify
[D][BLEDevice.cpp:108] gattServerEventHandler(): gattServerEventHandler [esp_gatt_if: 4] ... Unknown
Freeheap: 128312

Bascy on 2 Feb 2019

BLEService *pService = pServer->createService(BLEUUID(SERVICE_UUID), 256);
This call does not set MTU to 256, its setting 256 handles in service.

chegewara on 2 Feb 2019

You are right, its the handles
In our system the client app sets the MTU to 255

But still i see the memory leak occuring now

Bascy on 2 Feb 2019

I believe there is memory leak. I will try to recreate it and fix.

Your esp32 server code does not have MTU setup at all. Look at this line:
[W][BLECharacteristic.cpp:515] notify(): - Truncating to 20 bytes (maximum notify size)

This mean that esp32 or peer device mtu is 23.

chegewara on 2 Feb 2019

No, in the test script the bluetooth is not connected to our system, but to nRFConnect
There the MTU is not set

Bascy on 2 Feb 2019

I just discover you can set the MTU in nRFConnect. After setting it to 255 the logs shows as follows:

[D][BLEDevice.cpp:108] gattServerEventHandler(): gattServerEventHandler [esp_gatt_if: 4] ... Unknown
[D][BLECharacteristic.cpp:631] setValue(): >> setValue: length=66, data=546869732069732061206c6f6e6720737472696e6720746f207465737420696620746861742077696c6c206c65616420746f206d656d6f7279206c6f737320363832, characteristic UUID=beb5483e-36e1-4688-b7f5-ea07361b26a8
[D][BLEServer.cpp:153] handleGATTServerEvent(): >> handleGATTServerEvent: Unknown
[D][BLECharacteristic.cpp:638] setValue(): << setValue
[D][BLECharacteristic.cpp:203] handleGATTServerEvent(): >> handleGATTServerEvent: Unknown
[D][BLECharacteristic.cpp:484] notify(): >> notify: length: 66
[D][BLECharacteristic.cpp:459] handleGATTServerEvent(): << handleGATTServerEvent
[D][BLECharacteristic.cpp:533] notify(): << notify
[D][BLEServer.cpp:280] handleGATTServerEvent(): << handleGATTServerEvent
Freeheap: 98300
[D][BLEDevice.cpp:108] gattServerEventHandler(): gattServerEventHandler [esp_gatt_if: 4] ... Unknown
[D][BLECharacteristic.cpp:631] setValue(): >> setValue: length=66, data=546869732069732061206c6f6e6720737472696e6720746f207465737420696620746861742077696c6c206c65616420746f206d656d6f7279206c6f737320363833, characteristic UUID=beb5483e-36e1-4688-b7f5-ea07361b26a8
[D][BLEServer.cpp:153] handleGATTServerEvent(): >> handleGATTServerEvent: Unknown
[D][BLECharacteristic.cpp:638] setValue(): << setValue
[D][BLECharacteristic.cpp:203] handleGATTServerEvent(): >> handleGATTServerEvent: Unknown
[D][BLECharacteristic.cpp:484] notify(): >> notify: length: 66
[D][BLECharacteristic.cpp:459] handleGATTServerEvent(): << handleGATTServerEvent
[D][BLECharacteristic.cpp:533] notify(): << notify
[D][BLEServer.cpp:280] handleGATTServerEvent(): << handleGATTServerEvent
Freeheap: 98216
[D][BLEDevice.cpp:108] gattServerEventHandler(): gattServerEventHandler [esp_gatt_if: 4] ... Unknown
[D][BLECharacteristic.cpp:631] setValue(): >> setValue: length=66, data=546869732069732061206c6f6e6720737472696e6720746f207465737420696620746861742077696c6c206c65616420746f206d656d6f7279206c6f737320363834, characteristic UUID=beb5483e-36e1-4688-b7f5-ea07361b26a8
[D][BLEServer.cpp:153] handleGATTServerEvent(): >> handleGATTServerEvent: Unknown
[D][BLECharacteristic.cpp:638] setValue(): << setValue
[D][BLECharacteristic.cpp:203] handleGATTServerEvent(): >> handleGATTServerEvent: Unknown
[D][BLECharacteristic.cpp:484] notify(): >> notify: length: 66
[D][BLECharacteristic.cpp:459] handleGATTServerEvent(): << handleGATTServerEvent
[D][BLECharacteristic.cpp:533] notify(): << notify
[D][BLEServer.cpp:280] handleGATTServerEvent(): << handleGATTServerEvent
Freeheap: 98132

Bascy on 2 Feb 2019

I also tried it without increasing the handles, and the memoryleak is still there (as expected)

Bascy on 2 Feb 2019

Which version of library are you using?

chegewara on 2 Feb 2019

HEAD of master branch

Bascy on 2 Feb 2019

HEAD of master branch

Arduino library or this repository?

chegewara on 2 Feb 2019

ESP_BLE_Arduino

Bascy on 2 Feb 2019

Like i said, there is few bugfixes in latest PR in this repsoitory. I dont want to create arduino PR before i fix most bugs. Could you try to create library from this repository and perform test?

https://github.com/nkolban/esp32-snippets/blob/master/cpp_utils/ArduinoBLE.md#replacing-the-version-that-comes-with-arduino-esp32

chegewara on 2 Feb 2019

Im not sure what you are asking me here ...
I'm not using Arduin o IDE, but Eclipse with Sloeber 4.3 plugin, ESP32_BLE_Arduino repo is cloned in its own folder, which is added as library to the test project

Bascy on 2 Feb 2019

I remember now. There was small leak i found lately in BLECharacteristic.cpp. Im not sure it was the only reason.
In this function is missing delete p2902;:
https://github.com/nkolban/ESP32_BLE_Arduino/blob/master/src/BLECharacteristic.cpp#L483-L534

https://github.com/nkolban/esp32-snippets/blob/master/cpp_utils/BLECharacteristic.cpp#L540

chegewara on 2 Feb 2019

Ok, that might solve it
I do think you should also add the deletestatement before the other return statements in that method btw

Bascy on 3 Feb 2019

👍1

I have created a pull request with the fix of this memory leak, but actually i don't understand why you should delete the p2902 object, as this is a pointer to an object in a std::map.
I thought I read somewhere that std::map.first returns a copy of the object in the map-item, but trying to make this visible with some simple test code are not successful.

Do you know why the delete is necessary ?

Bascy on 3 Feb 2019

You are correct, we cant delete p2902, because this will cause crash next time we will try to find it. My bad, sorry.

chegewara on 3 Feb 2019

Ok, i'll revoke the pull request
That leaves the question why there is a memory leak

Bascy on 3 Feb 2019

I am a little busy now, but i will try to find it. As you can see i could not recreate memory leak, but with your settings i will perform more tests.

chegewara on 3 Feb 2019

👍1

I can confirm this as I'm experiencing the same thing, calling notify() causes a memory leak that eventually forces it to restart. If sending smaller sized values then its not that apparent, but when sending larger values (over 60 bytes) over and over again in a loop, then the heap gets consumed very quickly.
In my case I'm using a while loop that keeps sending out a large file chunked down into 180 bytes, every time notify is called (with a delay of 10ms) within that while loop, memory is leaked. Once we are out of the while loop, resources are freed. Sending out 150k bytes consumes over 25k of heap.

Edit: This only happens when sending fast notify's, if the delay is large (>=12ms) then there is no leak issue. Memory leak only starts to happen when the delay is very short( < 10ms). It also seems that it is correlated to the lost data, when sending quickly, around 10-15% of data is lost, when this happens, it eats out memory.