Cellular.getDataUsage is blocking application code for seconds at a time in multi threaded mode

Firmware
1

I am running an application built on spark firmware 0.6.1 on a Electron

I have SYSTEM_THREAD(ENABLED)

When I call Cellular.getDataUsage() , it blocks for at least 1.5 seconds every time

I think this is likely the intended/expected behaviour. I don’t think it should be.

Here is a test app demonstrating the behaviour:

#include "Particle.h"

PRODUCT_ID(xxxx);
PRODUCT_VERSION(xx);

//Configure how the app runs within the Particle ecosystem
SYSTEM_MODE(SEMI_AUTOMATIC);
SYSTEM_THREAD(ENABLED);

//Configure Particle system (runs this code before any Particle init code runs):
STARTUP(
   //Configure other Particle runtime parameters
   System.enableFeature(FEATURE_RETAINED_MEMORY);
   //Enable system reset information
   System.enableFeature(FEATURE_RESET_INFO);
   //Make sure that cloud DFU updates are enabled
   System.enableUpdates();
);


//Define log handler using serial monitor (dumps logs to serial monitor)
SerialLogHandler logHandler(LOG_LEVEL_ALL,
   {
      {"app"                  , LOG_LEVEL_ALL   },
   }
);

static Logger myLog("app.main");  //Logger object used in this "main.cpp" file


void setup() // Put setup code here to run once
{
   Serial.begin(115200);
   cellular_credentials_set("internet.com", "wapuser1", "wap", NULL);
   Particle.connect();
}


unsigned int last_cellupdate_millis = 0;
unsigned int last_serial_message_millis = 0;

CellularData dataUsage;

#define CELL_DATA_UPDATE_PERIOD 10000

void loop() // Put code here to loop forever
{
      if(Particle.connected()){
         static bool keep_alive_setting_sent = false;
         if(!keep_alive_setting_sent){
            Particle.keepAlive(55);
            keep_alive_setting_sent = true;
         }

         if( (millis() - last_cellupdate_millis) > CELL_DATA_UPDATE_PERIOD){
            unsigned int micros_before_cellupdate = micros();
            bool result = Cellular.getDataUsage(dataUsage);
            myLog.warn("Cellular.getDataUsage() blocked for %lu microseconds", (micros() - micros_before_cellupdate) );
            last_cellupdate_millis = millis();
         }
         else{
            if((millis() - last_serial_message_millis) > 5000){
               myLog.warn("waiting to get cell data update - %lu more milliseconds", CELL_DATA_UPDATE_PERIOD - (millis() - last_cellupdate_millis) );
               last_serial_message_millis = millis();
            }
         }
      }
}

and here is part of the output:

and here is the output from running that program:

[Thu Apr 05 09:46:37.348 2018] [ Modem::getDataUsage ] = = = = = = = = = =
[Thu Apr 05 09:46:37.350 2018]     66.141 AT send      12 "AT+UGCNTRD\r\n"
[Thu Apr 05 09:46:37.357 2018]     66.151 AT read  +   42 "\r\n+UGCNTRD: 31,103101,73635,103101,73635\r\n"
[Thu Apr 05 09:46:37.369 2018]     66.162 AT read OK    6 "\r\nOK\r\n"
[Thu Apr 05 09:46:37.370 2018] 0000066162 [app.main] WARN: Cellular.getDataUsage() blocked for 21373 microseconds
[Thu Apr 05 09:46:37.370 2018] 0000066162 [app.main] WARN: waiting to get cell data update - 10000 more milliseconds
[Thu Apr 05 09:46:42.370 2018] 0000071164 [app.main] WARN: waiting to get cell data update - 4998 more milliseconds
[Thu Apr 05 09:46:47.370 2018] 
[Thu Apr 05 09:46:47.370 2018] [ Modem::getDataUsage ] = = = = = = = = = =
[Thu Apr 05 09:46:47.370 2018]     76.163 AT send      12 "AT+UGCNTRD\r\n"
[Thu Apr 05 09:46:49.109 2018]     77.903 AT read  +   42 "\r\n+UGCNTRD: 31,103101,73635,103101,73635\r\n"
[Thu Apr 05 09:46:49.120 2018]     77.914 AT read OK    6 "\r\nOK\r\n"
[Thu Apr 05 09:46:49.120 2018] 0000077914 [app.main] WARN: Cellular.getDataUsage() blocked for 1751380 microseconds
[Thu Apr 05 09:46:49.122 2018] 0000077914 [app.main] WARN: waiting to get cell data update - 10000 more milliseconds
[Thu Apr 05 09:46:54.121 2018] 0000082916 [app.main] WARN: waiting to get cell data update - 4998 more milliseconds
[Thu Apr 05 09:46:59.121 2018] 
[Thu Apr 05 09:46:59.121 2018] [ Modem::getDataUsage ] = = = = = = = = = =
[Thu Apr 05 09:46:59.122 2018]     87.915 AT send      12 "AT+UGCNTRD\r\n"
[Thu Apr 05 09:47:00.449 2018]     89.245 AT read  +   42 "\r\n+UGCNTRD: 31,103101,73635,103101,73635\r\n"
[Thu Apr 05 09:47:00.461 2018]     89.256 AT read OK    6 "\r\nOK\r\n"
[Thu Apr 05 09:47:00.462 2018] 0000089256 [app.main] WARN: Cellular.getDataUsage() blocked for 1341403 microseconds
[Thu Apr 05 09:47:00.464 2018] 0000089256 [app.main] WARN: waiting to get cell data update - 10000 more milliseconds
[Thu Apr 05 09:47:05.462 2018] 0000094258 [app.main] WARN: waiting to get cell data update - 4998 more milliseconds
[Thu Apr 05 09:47:10.463 2018] 
[Thu Apr 05 09:47:10.463 2018] [ Modem::getDataUsage ] = = = = = = = = = =
[Thu Apr 05 09:47:10.464 2018]     99.257 AT send      12 "AT+UGCNTRD\r\n"
[Thu Apr 05 09:47:12.202 2018]    100.997 AT read  +   42 "\r\n+UGCNTRD: 31,103101,73635,103101,73635\r\n"
[Thu Apr 05 09:47:12.213 2018]    101.008 AT read OK    6 "\r\nOK\r\n"
[Thu Apr 05 09:47:12.215 2018] 0000101008 [app.main] WARN: Cellular.getDataUsage() blocked for 1751393 microseconds
[Thu Apr 05 09:47:12.215 2018] 0000101008 [app.main] WARN: waiting to get cell data update - 10000 more milliseconds
[Thu Apr 05 09:47:17.215 2018] 0000106010 [app.main] WARN: waiting to get cell data update - 4998 more milliseconds
[Thu Apr 05 09:47:22.214 2018] 
[Thu Apr 05 09:47:22.214 2018] [ Modem::getDataUsage ] = = = = = = = = = =
[Thu Apr 05 09:47:22.217 2018]    111.009 AT send      12 "AT+UGCNTRD\r\n"
[Thu Apr 05 09:47:23.544 2018]    112.339 AT read  +   42 "\r\n+UGCNTRD: 31,103101,73635,103101,73635\r\n"
[Thu Apr 05 09:47:23.555 2018]    112.350 AT read OK    6 "\r\nOK\r\n"
[Thu Apr 05 09:47:23.557 2018] 0000112350 [app.main] WARN: Cellular.getDataUsage() blocked for 1341401 microseconds

_
_
So, it would appear that a call to Cellular.getDataUsage() amounts to a synchronous call via AT commands to the modem, which blocks the app for about 1 - 2 seconds

I think what would make way more sense is if the spark firmware silently and automatically kept tabs on the cellular data usage by automatically periodically querying the modem for cellular data usage on the system thread. Then, calls by the application thread to Cellular.getDataUsage() would simply return the latest known data usage.

I have created a feature request for this on GitHub:

2

Update:

I have found that blocking issues go down substantially if the modem’s data registers are queried at much faster frequency.

I modified above code to wait only 500 ms in between calls to Cellular.getDataUsage() and now it is only blocking for about 20 ms per call.

If the network connection is lost, then the first call to Cellular.getDataUsage() after the connection is re-established seems to work. Calling Cellular.getDataUsage() which Particle.connected() is FALSE seems to screw up the Electron connectivity process

3

Update:

The problems are still present even though the vast majority of calls are still only taking about 20 ms.

When the modem is busy dealing with network connectivity changes, a call to Cellular.getDataUsage() still blocks for me. Sometimes it blocks for as long as 10 seconds!

It would really nice if there was a way to use the Particle API in multi-threaded mode and be guaranteed that calls to the API would not block my app code…