High CPU Utilization during BLE Scan caused by hsdk threads

[weiwang1]

Hi,
We are running a BLE scanning test process by using hsdk library to communicate with the NXP bluetooth chip to preform BLE scan.
After this test process starts scanning by calling GAPStartScanningRequest function (hsdk-c), it takes full CPU utilization 99% when the number of Bluetooth devices in the test setup is around 1500.
And even we reduce the number of Bluetooth devices to low (less than 100), it still takes around 30%.
Using top command to track:

/root # top -p 6131
top - 14:08:00 up 2:11, 2 users, load average: 2.38, 2.52, 2.58
Tasks: 4 total, 1 running, 3 sleeping, 0 stopped, 0 zombie
Cpu(s): 39.2%us, 73.2%sy, 0.0%ni, 90.7%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 830384k total, 691512k used, 138872k free, 0k buffers
Swap: 0k total, 0k used, 0k free, 324160k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
6132 cli 20 0 23636 1256 612 R 78 0.2 0:03.58 DTR                   (DeviceThreadRoutine hsdk/physical/PhysicalDevice.c)
6133 cli 20 0 23636 1256 612 S 20 0.2 0:01.55 FTR                     (FramerThreadRoutine hsdk/protocol/Framer.c)
6131 cli 20 0 23636 1256 612 S 0 0.2 0:00.01 blescantest
6134 cli 20 0 23636 1256 612 S 0 0.2 0:00.00 blescantest

From the strace tracking result:
/root # strace -T -r -c -p 6132
Process 6132 attached - interrupt to quit
^CProcess 6132 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
45.13 0.021352 1 30736 poll
34.71 0.016425 1 30736 read
14.98 0.007089 0 30735 write
5.18 0.002450 0 30736 gettimeofday
0.00 0.000000 0 4 futex
------ ----------- ----------- --------- --------- ----------------
100.00 0.047316 122947 total
/root # strace -T -r -c -p 6133
Process 6133 attached - interrupt to quit
^CProcess 6133 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
95.04 0.106040 2 47379 poll
4.96 0.005539 0 47379 read
0.00 0.000000 0 49 write
0.00 0.000000 0 38 mprotect
0.00 0.000000 0 6 futex
------ ----------- ----------- --------- --------- ----------------
100.00 0.111579 94851 total

Is there any fix for the problem?

Thanks.
Best regards,
Tony Wang

[weiwang1]

Hi Mario,

Thanks for the info. I created the internal case "Case 00253739".
Please help check.

Thanks.

Tony

[weiwang1]

Hi Mario,

Thanks for effort to reproduce this issue.
There is a max device number setting and scan time duration. If the max device number is exceeded or scan time duration expires, the application calls GAPStopScanningRequest to abort scanning process.

One hash table is used to store all the scan entries, when an scan entry is reported, it is checked if it is duplicated or a new one to be stored.

Best regards,

Tony.

[mario_castaneda]

Hi Tony,

I tested by my side and I was getting a very high CPU utilization. However, I realize that my application was entering in the while (1) after all the application process. 

However, I implemented a semaphore after setting the scan command and the CPU utilization is around 4%.

Please see the code below.

    sem_init(&mutex, 0, 0);
    /* Factory reset */
    printf("\nTX: FSCI-CPUReset.Request\n");
    SendFrame(framer, factory_rst);
    sleep(5);
    printf("\nStart Scanning Request\n");

    SendFrame(framer, set_scan_data);
    sem_wait(&mutex); //wait state

    SendFrame(framer, set_scan_stop);
    sleep(1);
    printf("\nScan Done\n");

    while (1)
    {
 
    }‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

The sem_post(&mutex) is calling in the callback when I achieve the 80 devices, in this case.

Is it possible that you could provide your implementation?

You could submit an internal question and the communication will be only you and me.

https://community.nxp.com/docs/DOC-329745 

Regards,

Mario

[weiwang1]

Hi Mario,
We just use "ps" and "top" command to get the cpu usage for the test process.

There is not too much test step since since we ran our own test application which linked to hsdk library.
Here is the main skeleton of our test application.

void ble_scan_test(void)
{
       ...
       // Setting GAPStartScanningRequest_t ScanningParams
       bistat = _btif->BleSetScanParams(g_scan_interval /*0xa0*/, g_scan_window/*0xa0*/, scan_dur/*1*/,                         g_one_scan_nb_devices/*200*/);
      ...
      // start discovery scan
      bistat = _btif->BleStartScan(); // Call GAPStartScanningRequest to start scan
      ...
      // After scanned device exceeds 1500, the scan is aborted
}

void BtTestCback(int event, BI_EVENT *data)
{
       // print the scan result
}

void BleFsciCallback(void * container)
{
       bleEvtContainer_t * cntnr = (bleEvtContainer_t *)container;
       ...
       switch (cntnr->id)
       {
             ...

             case GAPScanningEventDeviceScannedIndication_FSCI_ID:
             {
                     GAPScanningEventDeviceScannedIndication_t * dev = &(cntnr->Data.GAPScanningEventDeviceScannedIndication);
                     ...
                    _clientCback(event, &data);
                    break;
            }
            ...
      }
}

int iotInit()
{
      int rc;
     config = defaultConfigurationData();
     setBaudrate(config, UART_BAUDRATE /*115200*/);

    device = InitPhysicalDevice(UART, config, serial_port, GLOBAL);

     rc = OpenPhysicalDevice(device); // Create DeviceThreadRoutine

     framer = InitializeFramer(device, FSCI, LENGTH_FIELD_SIZE, CRC_FIELD_SIZE, _LITTLE_ENDIAN); // Create  FramerThreadRoutine

     /* Subscribe to incoming events with the callback */
     AttachToFramer(framer, device, BleFsciCallback);

     return BISTATUS_OK;
}

int btif_init()
{
      ...
      int bistat = _btif->Open(BtTestCback); // register _clientcallback = BtTestCback and call iotInit

      ...
      //Reset NXP Ble Chip
      ...

      return BISTATUS_OK;
}

int main()
{
     int bistat = btif_init();
     if (bistat == STATUS_OK)
    {
         ble_scan_test();
    }

    return 0;
}

[mario_castaneda]

Hi Tony,

Sorry for my late reply.

I think I reproduced the high High CPU Utilization during BLE Scan. I am running more tests to t find out this high utilization.

Just to confirm, how are you aborting the scan process? or How are you counting the devices that you received?

Could you please provide this part of this process?

      // start discovery scan
      bistat = _btif->BleStartScan(); // Call GAPStartScanningRequest to start scan
      ...
      // After scanned device exceeds 1500, the scan is aborted
‍‍‍‍

Regards,

Mario

[weiwang1]

Hi Mario,

Thanks for the reply.

Yes, our test application calls the GAPStartScanningRequest to start scanning.

Actually, we have another product which has same the NXP bluetooth chip but burned with the firmware supporting HCI not FSCI. And the test application also adopts standards HCI command to communicate with the bluetooth chip.
Within the same test case, the CPU usage of the process (HCI) is around 1%~2% with 1500 device nodes.
Moreover, our customer has another solution for bluetooth chip and they also confirmed that scanning 1500 device nodes only takes around 1% cpu usage.

I have tried to change baud rate and this change can reduce the cpu usage but sacrifice the performance. 

Thanks.

[mario_castaneda]

Hi Tony,

Sorry for my misunderstanding. I was confused with how are you measuring the CPU utilization.

However, I am trying to reproduce this issue by my side, is it possible that you could provide your implementation for this GAPStartScanningRequest. I will try to use the same steps that you are following.

Regards,

Mario

[mario_castaneda]

Hi Tony,

Just to confirm, you are calling the GAPStartScanningRequest  and are getting 99% of CPU Utilization.

I am not sure what is the issue that you are facing. But, assuming that the device is changing for the 3 adv channels, it requests some time to set the new channel and if the device is reporting 1500 this behaviour is expected.

Regards,

Mario