Particle.publish is blocking for seconds at a time in multi threaded mode

jaza_tom · April 4, 2018, 2:11pm

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

I have SYSTEM_THREAD(ENABLED)

When I call Particle.publish() , sometimes that call blocks for seconds on end. Here is my code:

   myLog.info("Particle.publish()");
   Serial.flush();
   uint32_t microsBefore = micros();
   bool returnVal = Particle.publish(eventName, eventData, ttl, PRIVATE);
   myLog.info("Publish blocked for %lu us", (micros() - microsBefore));

And here is example of the output from this code:

[Wed Apr 04 10:59:14.569 2018] 0000143132 [app.myParticle] INFO: Particle.publish()
[Wed Apr 04 10:59:14.574 2018] 0000143133 [comm.coap] TRACE: sending message id=43
[Wed Apr 04 10:59:14.574 2018] 0000143134 [system] TRACE: send 78
[Wed Apr 04 10:59:14.574 2018] socketSendTo(0,54.157.249.252,5684,,78)
[Wed Apr 04 10:59:14.574 2018]    143.128 AT send      37 "AT+USOST=0,\"54.157.249.252\",5684,78\r\n"
[Wed Apr 04 10:59:16.751 2018]    145.309 AT read  >    3 "\r\n@"
[Wed Apr 04 10:59:16.802 2018]    145.359 AT send      78 "\x17\xfe\xfd\x00\x01\x00\x00\x00\x00\x00S\x00A\x00\x01\x00\x00\x00\x00\x00S9\xfeq\x8f\xd0\x90/\xdf>\\\xd6x\x1a\xf7\x03\xa1\x1a\xb1t\xa2\x8bp\xa3\xd6\xcb\xcer\xd1\xdb\xda\xb7us\x90t\xd3\xecS6\x19\xf1\x82\xd9Vb8#\x811}!\xfd\t\x8b\xac\xe84"
[Wed Apr 04 10:59:16.943 2018]    145.501 AT read  +   16 "\r\n+USOST: 0,78\r\n"
[Wed Apr 04 10:59:16.953 2018]    145.511 AT read OK    6 "\r\nOK\r\n"
[Wed Apr 04 10:59:16.955 2018] 0000145517 [app.myParticle] INFO: Publish blocked for 2384064 us
[Wed Apr 04 10:59:16.982 2018] 0000145544 [app.main] WARN: Latency: app.UI_Manager (2668 ms)

It appears that spark firmware is blocking while waiting for the modem to respond.

It also appears that the millis() timestamps of the system messages above are out of order… which is highly suspicious. Specifically, this sequence doesn’t make sense timestamp-wise:

[Wed Apr 04 10:59:14.574 2018] 0000143134 [system] TRACE: send 78
[Wed Apr 04 10:59:14.574 2018] socketSendTo(0,54.157.249.252,5684,,78)
[Wed Apr 04 10:59:14.574 2018]    143.128 AT send      37 "AT+USOST=0,\"54.157.249.252\",5684,78\r\n"

Is this working as intended? I thought spark firmware uses interrupts to wait for modem responses…

In the above example, this blocks my app from running for 2.5 seconds! If this is functioning as intended, it would seem that I will have to queue all my publishing to happen overnight so as not to block my app’s UI from running… which isn’t acceptable…

Update:
Also tried using the Particle.publish(eventName, eventData, PRIVATE, NO_ACK); function signature with the same results.

rickkas7 · April 4, 2018, 2:24pm

I believe it does block in 0.6.1:

github.com

particle-iot/firmware/blob/release/v0.6.1/wiring/src/spark_wiring_cloud.cpp#L52


d.handler_data = p.dataPtr();


if (!spark_send_event(eventName, eventData, ttl, flags, &d) && !p.isDone()) {
    // Set generic error code in case completion callback wasn't invoked for some reason
    p.setError(spark::Error::UNKNOWN);
    p.fromDataPtr(d.handler_data); // Free wrapper object
}


// TODO: Return future object instead of synchronous waiting
spark::Future<void> f = p.future();
return f.wait().isSucceeded();
#else
return false; // spark::Future<void>::makeFailed(spark::Error::NOT_SUPPORTED);
#endif
}

Note that it’s different in 0.7.0:

github.com

particle-iot/firmware/blob/release/v0.7.0-rc.1/wiring/src/spark_wiring_cloud.cpp#L64


Promise<bool> p;
d.handler_callback = publishCompletionCallback;
d.handler_data = p.dataPtr();


if (!spark_send_event(eventName, eventData, ttl, flags.value(), &d) && !p.isDone()) {
    // Set generic error code in case completion callback wasn't invoked for some reason
    p.setError(Error::UNKNOWN);
    p.fromDataPtr(d.handler_data); // Free wrapper object
}


return p.future();
#else
return Future<bool>(Error::NOT_SUPPORTED);
#endif
}

In 0.7.0, it returns a spark::Future, so if you don’t check the return value it won’t block.

I’m not 100% sure that’s how it works, but I think that’s how it works.

jaza_tom · April 4, 2018, 3:10pm

I have just tried upgrading my Electron to system version 0.7.0 , then I compiled my app for system version 0.7.0 (using po-util), and I changed my code to this:

   myLog.info("Particle.publish()");
   Serial.flush();
   uint32_t microsBefore = micros();
   Particle.publish(eventName, eventData, ttl, PRIVATE);
   myLog.info("Publish blocked for %lu us", (micros() - microsBefore));

And I get the same result as above… namely:

[Wed Apr 04 12:06:41.133 2018] 0000099883 [app.myParticle] INFO: Particle.publish()
[Wed Apr 04 12:06:41.135 2018] 0000099884 [comm.coap] TRACE: sending message id=af
[Wed Apr 04 12:06:41.135 2018] 0000099884 [system] TRACE: send 78
[Wed Apr 04 12:06:41.135 2018] socketSendTo(0,54.157.249.252,5684,,78)
[Wed Apr 04 12:06:41.135 2018]     99.880 AT send      37 "AT+USOST=0,\"54.157.249.252\",5684,78\r\n"
[Wed Apr 04 12:06:43.125 2018]    101.871 AT read  >    3 "\r\n@"
[Wed Apr 04 12:06:43.176 2018]    101.921 AT send      78 "\x17\xfe\xfd\x00\x01\x00\x00\x00\x00\x00\xd2\x00A\x00\x01\x00\x00\x00\x00\x00\xd2\xc3\x98\xae\x05\xb8\x13>\xc8V)%G\x8e\xaeO`\xba%@\xc6M\xd5\x8c*\x03+\x98\xbe,c54`\x00QKB\x9a\x0f\xdeGG\xc3`\xdd\xe9_H>N\xca\xa6\xc2\xe4\x1b\xc3\xf3"
[Wed Apr 04 12:06:43.317 2018]    102.063 AT read  +   16 "\r\n+USOST: 0,78\r\n"
[Wed Apr 04 12:06:43.327 2018]    102.073 AT read OK    6 "\r\nOK\r\n"
[Wed Apr 04 12:06:43.328 2018] 0000102078 [app.myParticle] INFO: Publish blocked for 2194161 us
[Wed Apr 04 12:06:43.337 2018] 0000102088 [comm.coap] TRACE: sending message id=b0
[Wed Apr 04 12:06:43.338 2018] 0000102088 [system] TRACE: send 33
[Wed Apr 04 12:06:43.338 2018] socketSendTo(0,54.157.249.252,5684,,33)
[Wed Apr 04 12:06:43.340 2018]    102.083 AT send      37 "AT+USOST=0,\"54.157.249.252\",5684,33\r\n"
[Wed Apr 04 12:06:43.352 2018]    102.097 AT read  >    3 "\r\n@"
[Wed Apr 04 12:06:43.358 2018] 0000102108 [app.main] WARN: Latency: app.UI_Manager (2482 ms)

So, in release/v0.7.0 , Particle.publish() still blocks for seconds on end, and the out-of-order millis() timestamps shown in the system debug messages are still present.

jaza_tom · April 4, 2018, 6:10pm

I have created an issue on GitHub for this problem:

https://github.com/particle-iot/firmware/issues/1516

jaza_tom · April 5, 2018, 4:45pm

Update:

I posted a related issue here:

It seems that if you keep hammering the modem with Cellular.getDataUsage() (on the order of twice per second) once an Electron has successfully connected to the internet, then subsequent calls to Particle.publish() don't block for very long.

My working theory is that if the modem doesn't receive an AT command from the STM32 regularly (say for more than a second) then it goes into some sort of lower power quasi-sleep mode which makes subsequent AT commands take longer to respond to. So hammering it keeps the modem "awake", thus reducing latency associated with synchronous AT commands.

Topic		Replies	Views
Particle.publish sometimes blocks for tens of seconds on Electron Firmware electron	3	432	March 31, 2022
Cellular.getDataUsage is blocking application code for seconds at a time in multi threaded mode Firmware	2	978	April 9, 2018
Particle.publish() hangs on Photon when called in listening mode with SYSTEM_THREAD(ENABLED) Firmware	2	1231	December 23, 2015
Fire and forget, non-blocking Particle Publish Firmware	3	1601	July 24, 2017
List of synchronous blocking spark firmware functions for multi-threaded applications Firmware	4	838	October 27, 2019

Particle.publish is blocking for seconds at a time in multi threaded mode

Related topics