Hi All,
I have made some test firmware that essentially spams Serial print as frequently as possible and sends a big json string to my PC, which I then track and graph using dearpygui (really good python based ui).
At the moment I am using Serial.println every 20 ms. I am having trouble checking vitals and using particle functions. Is this related to my overusing of Serial.println?
I have tried using System.thread(enabled) and without.
Thanks in advance
I think you might be overrunning the USB serial buffer. The default for USB serial is to block when the output buffer is full, which is probably affecting the system performance. The setting of blockOnOverrun defaults to true and affects this behavior.
However, if you don't block, excess data is discarded, which you also probably don't want. Instead, use availableForWrite to write your data in chunks only when there is enough room in the serial buffer to write the data.
Thanks Rick, I am sending a json string (~400 chars), seems like the buffer is 256, so this is most likely it.
I am going to try split my json in two halves and send them one after the other. I taught I was making my life easy for myself sending a json string, but i guess the bloat from the keys pushed me over the 256. I will revert back when solved.
For anyone who may stumble across this later. I am keeping my Serial prints below 256 and I am throttling my Serial prints using the following:
void bench_test::serialPrintDelayWatchdog(){
for (size_t i = 0; i < 100; i++){
if(Serial.availableForWrite()<256){
delay(1);
} else {
Serial.print(i);
break;
}
}
}
The Serial.print() in there was just so I could get an idea of the delays required.
Quick Question,
What is the behavior of Serial.availableForWrite() when I am not connected to my PC via serial.
Will my delay watchdog function above ever reach the break statement?
EDIT: I am now trying to print to the Serial as fast as possible, but only printing when Serial.availableForWrite() is 256. I am also printing less than 256. But I am still seeing the same behavior, where after a few mins of running, I can no longer call vitals from the console or use particle functions.
I would inject the delay only when the free space "approaches" zero.
Otherwise you'd delay when there would still be 255 of 256 bytes to use even when you only intend to write less then that.
It's also not best practivce to "assume" the maximum size of your buffer, unless you have set your own buffer via acquireSerialBuffer().
I'd also not use delay() for that but rather go a non-blocking approach.
Hey Scruff, thanks for the reply.
Just thinking out loud here, but would love your input. So to go non blocking, I could just check that Serial.availableForWrite() is greater than my char array. I have also split up my big json char array into two smaller jsons (there may be more jsons to come) so as to keep each Serial.println below 256. If I check Serial.availableForWrite() before printing, it may end up that I will always skip the second json if the first json hasn't cleared yet.
There are many possible ways to skin that cat, but one I'd consider is using the Serial.availableForWrite() result as len parameter for Serial.write(buf, len). This way you only ever send as many bytes as the buffer can take - obviously while keeping track what portion of your full payload you already sent and what should follow next.
Yeah that sounds like a good way to go.
I am still seeing the blocking behavior even though now I am printing less than 256 and only when the full buffer is available. I have also put Particle.process() before each print as well.
I am running SYSTEM_THREAD(ENABLED); and SYSTEM_MODE(AUTOMATIC);.
I am going to just make a completely empty project that spams serial similarly to what my app is doing and see if the issue persists. While overrunning the USB serial buffer may have exacerbated the issue, it may not be the only cause.
Can you show a working test code that exhibits that behaviour?
Meanwhile you can check this (rough & untested) code 
SYSTEM_THREAD(ENABLED)
//SYSTEM_MODE(SEMI_AUTOMATIC)
char longText[5000];
void send(bool restart = false);
void setup() {
// fill long text
for (int i=0; i < sizeof(longText); i++) {
longText[i] = (i % 0x5F) + 0x20;
}
}
void loop() {
send();
// do other stuff while the buffer drains
}
void send(bool restart) {
static int idx = 0;
if (idx >= sizeof(longText) || restart) idx = 0;
// may have an off-by-one issue ;-)
int chunkSize = min(Serial.availableForWrite()-1, sizeof(longText) - idx);
Serial.write((const uint8_t*)&longText[idx], chunkSize);
idx += chunkSize;
}
My code is split out to a bunch of singletons, but I will try and reproduce issue on a one file app and revert.
Thanks for assistance.
So while I may have been overrunning the serial buffer previously, I think something else is going on. I have implemented the following function that is run every iteration of the main loop.
void cloudKeepAlive(){
unsigned long processtimer = millis();
while(!Particle.connected() && (millis()-processtimer<10000)){
Particle.process();
}
if(millis()-processtimer>5000){
Log.info("Cloud Keep Alive Ran for: %u", millis()-processtimer);
}
}
If it was a blocking issue then I was hoping the above would solve the issue. The problem is that the device is breathing cyan, so thinks it's connected, but I cannot communicate with the device from the particle console, ie. vitals, signal or particle functions. So it seems like the device thinks that it is connected when it is not. I did read in the api that if particle.process is not being called enough that the device can think its connected when infact it is not.
EDIT: One other thing I have noticed is that when I try to push a new firmware to device using workbench cloud flash, I still get the started event but it will fail to update. Does the started event mean that the cloud has successfully connected to the particle?
I am still seeing this weird behavior where the particle thinks its still connected to the cloud (breathing cyan), but I am unable to check vitals or call a particle function. When I try to flash a new firmware to the device in this state, I will get a started on the event console, but it will always fail.
It seems like when it gets to this state, I can't just reset the device, I need to remove power and then put power back before it will connect again, once power is removed and replaced, it connects no problem.
The instructions for Particle.process are mostly only relevant when not using threading mode, or using MANUAL mode, neither of which are recommended. Under normal circumstances you should never need to call it.
I didn't see a mention of the kind of device, but cellular devices can go up to the keep-alive period (23 minutes) without realizing that they can no longer be communicated to from the cloud side. So it's not unexpected that cellular devices could breathe cyan and not be able to be communicated with from the cloud side.
The mostly likely two possibilities are:
There actually is a cellular issue which is preventing the cloud from communicating with the device. This could be debugged using the USB serial logs, except you're also using them for other purposes so you might need to find a different way.
The other is some code path that prevents the loop() function from returning. This will prevent a number of cloud operations like calling functions from working properly because these are dispatched between calls to loop. You should try to return from loop as often as possible, even with threading enabled.
However, since resetting the device does not solve the problem, there's a third possibility. The difference between reset and removing power is that the cellular modem is reset only on removing power, not after pressing the reset button or System.reset(). Something is likely causing the cellular modem to not work properly, which would also explain not being able to communicate from the cloud. For this you really want to be able to see the LOG_LEVEL_TRACE calls from Device OS. If you are not using the UART serial port, you could redirect those logs to UART TX and use a FT232-type 3.3V UART to USB adapter to view the logs.
I'll try force the issue and capture some trace logs.
Sorry I was mistaken here. If I reset the device (B5SOM) it will think its connected, ie. it passes Particle.connected() and breathes cyan, but the issue where i am unable to check vitals, call particle functions or flash new firmware persists.
See below for a log trace, for when I restart the device until it thinks its connected.
Serial monitor opened successfully:
0000001752 [ncp.at] TRACE: > AT
0000001754 [ncp.at] TRACE: < OK
0000002253 [ncp.at] TRACE: > AT
0000002255 [ncp.at] TRACE: < OK
0000002255 [ncp.at] TRACE: > ATO
0000002258 [ncp.at] TRACE: < CONNECT 150000000
0000005258 [ncp.client] WARN: Resumed into a broken PPP session
0000005258 [ncp.client] ERROR: Failed to enter data mode
0000005259 [net.ppp.client] ERROR: Failed to dial
0000005259 [net.ppp.client] TRACE: State CONNECTING -> CONNECT
0000005259 [net.pppncp] TRACE: NCP event 3
0000005260 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_DOWN
0000005261 [system.nm] TRACE: Interface 4 power state changed: POWERING_DOWN
0000005262 [ncp.client] TRACE: Try powering modem off using AT command
0000005264 [ncp.at] TRACE: > AT+QPOWD
0000005323 [ncp.at] TRACE: < OK
0000005324 [ncp.client] TRACE: Waiting the modem to be turned off...
0000005363 [net.ppp.client] TRACE: State CONNECT -> CONNECTING
0000019959 [net.pppncp] TRACE: NCP event 3
0000019959 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_DOWN
0000019960 [system.nm] TRACE: Interface 4 power state changed: DOWN
0000019960 [ncp.client] TRACE: It takes 14636 ms to power off the modem.
0000019961 [mux] INFO: Stopping GSM07.10 muxer
0000019961 [mux] INFO: Gracefully stopping GSM07.10 muxer
0000019961 [mux] INFO: Closing all muxed channels
0000019962 [mux] INFO: Closing mux channel 1
0000019962 [mux] INFO: Closing mux channel 2
0000019963 [mux] INFO: Muxed channel 3 already closed
0000019963 [mux] INFO: Muxed channel 4 already closed
0000019964 [mux] INFO: GSM07.10 muxer thread exiting
0000019964 [ncp.client] TRACE: NCP connection state changed: 1
0000019965 [net.pppncp] TRACE: NCP event 2
0000019965 [net.pppncp] TRACE: State changed event: 1
0000019965 [mux] INFO: GSM07.10 muxer stopped
0000019966 [ncp.client] TRACE: Soft power off modem successfully
0000019966 [ncp.client] TRACE: Deinit modem serial.
0000019967 [net.pppncp] ERROR: Failed to initialize cellular NCP client: -210
0000024977 [ncp.client] ERROR: Failed to enter data mode
0000024977 [net.ppp.client] ERROR: Failed to dial
0000024978 [net.ppp.client] TRACE: State CONNECTING -> CONNECT
0000024978 [ncp.client] TRACE: Modem already off
0000024979 [ncp.client] TRACE: Soft power off modem successfully
0000024980 [ncp.client] TRACE: Deinit modem serial.
0000024981 [ncp.client] TRACE: NCP connection state changed: 0
0000024982 [net.pppncp] TRACE: NCP event 2
0000024982 [net.pppncp] TRACE: State changed event: 0
0000024983 [ncp.client] TRACE: NCP state changed: 0
0000024983 [net.pppncp] TRACE: NCP event 1
0000024982 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN data=0
0000024984 [net.ppp.client] TRACE: State CONNECT -> DISCONNECT
0000024984 [ncp.client] TRACE: Powering modem on, ncpId: 0x62
0000024986 [net.pppncp] TRACE: NCP event 3
0000024986 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_UP
0000024988 [system.nm] TRACE: Interface 4 power state changed: POWERING_UP
0000024989 [net.ppp.client] TRACE: State DISCONNECT -> DISCONNECTING
0000024992 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN data=0
0000024992 [net.ppp.client] TRACE: PPP thread event ERROR data=5
0000024993 [net.pppncp] ERROR: PPP error event data=5
0000024993 [net.ppp.client] TRACE: PPP thread event DOWN data=0
0000024993 [net.ppp.client] TRACE: State DISCONNECTING -> DISCONNECTED
0000024996 [net.ppp.client] TRACE: State DISCONNECTED -> READY
0000035979 [net.pppncp] TRACE: NCP event 3
0000035979 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_UP
0000035980 [system.nm] TRACE: Interface 4 power state changed: UP
0000035980 [ncp.client] TRACE: Modem powered on
0000036020 [ncp.at] TRACE: > AT
0000036020 [ncp.at] TRACE: < RDY
0000036041 [ncp.at] TRACE: < OK
0000036041 [ncp.client] TRACE: NCP ready to accept AT commands
0000036042 [ncp.at] TRACE: > AT+CFUN?
0000036098 [ncp.at] TRACE: < +CFUN: 0
0000036098 [ncp.at] TRACE: < OK
0000036098 [ncp.at] TRACE: > AT+CFUN=1,0
0000036105 [ncp.at] TRACE: < +CME ERROR: 3
0000037105 [ncp.at] TRACE: > AT+CFUN?
0000037110 [ncp.at] TRACE: < +CFUN: 1
0000037111 [ncp.at] TRACE: < OK
0000037111 [ncp.at] TRACE: > AT+IFC=2,2
0000037114 [ncp.at] TRACE: < OK
0000037114 [ncp.at] TRACE: > AT
0000037116 [ncp.at] TRACE: < OK
0000037116 [ncp.at] TRACE: > AT+IPR=460800
0000037120 [ncp.at] TRACE: < OK
0000038120 [ncp.at] TRACE: > AT
0000038120 [ncp.at] TRACE: < OK
0000038121 [ncp.at] TRACE: > AT+CPIN?
0000038122 [ncp.at] TRACE: < +CPIN: READY
0000038123 [ncp.at] TRACE: < OK
0000038123 [ncp.at] TRACE: > AT+CCID
0000038125 [ncp.at] TRACE: < +CCID: 89883070000023239831
0000038125 [ncp.at] TRACE: < OK
0000038125 [ncp.at] TRACE: > AT+QDSIM=0
0000038126 [ncp.at] TRACE: < OK
0000038127 [ncp.at] TRACE: > AT+CMUX=0,0,7,1509,,,,,
0000038128 [ncp.at] TRACE: < OK
0000038129 [mux] INFO: Starting GSM07.10 muxer
0000038130 [mux] INFO: Opening mux channel 0
0000038130 [mux] INFO: GSM07.10 muxer thread started
0000038232 [mux] INFO: Opening mux channel 1
0000038234 [ncp.at] TRACE: > AT
0000038234 [ncp.at] TRACE: < +CGEV: ME DETACH
0000038235 [ncp.at] TRACE: < POWERED DOWN
0000038236 [ncp.at] TRACE: < OK
0000038236 [ncp.client] TRACE: NCP state changed: 1
0000038236 [net.pppncp] TRACE: NCP event 1
0000038237 [ncp.at] TRACE: > AT+QCFG="cmux/urcport",1
0000038240 [ncp.at] TRACE: < OK
0000038240 [ncp.at] TRACE: > AT+CGEREP=1,0
0000038242 [ncp.at] TRACE: < OK
0000038243 [net.ppp.client] TRACE: PPP thread event ADM_UP data=0
0000038247 [ncp.at] TRACE: > AT+CFUN=1,0
0000038248 [ncp.at] TRACE: < OK
0000038249 [ncp.at] TRACE: > AT+CCID
0000038251 [ncp.at] TRACE: < +CCID: 89883070000023239831
0000038252 [ncp.at] TRACE: < OK
0000038253 [ncp.at] TRACE: > AT+CGDCONT=1,"IP","super"
0000038257 [ncp.at] TRACE: < OK
0000038257 [ncp.at] TRACE: > AT+CFUN=1,0
0000038259 [ncp.at] TRACE: < OK
0000038260 [ncp.at] TRACE: > AT+CREG=2
0000038261 [ncp.at] TRACE: < OK
0000038262 [ncp.at] TRACE: > AT+CGREG=2
0000038264 [ncp.at] TRACE: < OK
0000038264 [ncp.at] TRACE: > AT+CEREG=2
0000038266 [ncp.at] TRACE: < OK
0000038266 [ncp.client] TRACE: NCP connection state changed: 1
0000038266 [net.pppncp] TRACE: NCP event 2
0000038267 [net.pppncp] TRACE: State changed event: 1
0000038268 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN data=0
0000038268 [ncp.at] TRACE: > AT+COPS?
0000038270 [ncp.at] TRACE: < +COPS: 0
0000038270 [ncp.at] TRACE: < OK
0000038271 [ncp.at] TRACE: > AT+CEREG?
0000038273 [ncp.at] TRACE: < +CEREG: 2,2
0000038273 [ncp.at] TRACE: < OK
0000038274 [ncp.at] TRACE: > AT+CREG?
0000038276 [ncp.at] TRACE: < +CREG: 2,2
0000038276 [ncp.at] TRACE: < OK
0000038277 [ncp.at] TRACE: > AT+CGREG?
0000038279 [ncp.at] TRACE: < +CGREG: 2,2
0000038279 [ncp.at] TRACE: < OK
0000039279 [ncp.at] TRACE: < +CREG: 5,"9D70","0175706",7
0000039280 [ncp.at] TRACE: > AT+CIMI
0000039280 [ncp.at] TRACE: < +CGREG: 5,"9D70","0175706",7
0000039282 [ncp.at] TRACE: < +CEREG: 5,"9D70","0175706",7
0000039284 [ncp.at] TRACE: < 234103519410929
0000039284 [ncp.at] TRACE: < OK
0000039384 [ncp.client] TRACE: NCP connection state changed: 2
0000039384 [mux] INFO: Opening mux channel 2
0000039426 [net.pppncp] TRACE: NCP event 100
0000039426 [net.pppncp] TRACE: New auth info
0000039429 [net.pppncp] TRACE: NCP event 2
0000039429 [net.pppncp] TRACE: State changed event: 2
0000039430 [net.ppp.client] TRACE: PPP thread event LOWER_UP data=0
0000039430 [net.ppp.client] TRACE: State READY -> CONNECT
0000039431 [ncp.at] TRACE: > AT+CIMI
0000039433 [ncp.at] TRACE: < 234103519410929
0000039433 [ncp.at] TRACE: < OK
0000039435 [net.ppp.client] TRACE: State CONNECT -> CONNECTING
0000040439 [ncp.at] TRACE: > AT
0000040440 [ncp.at] TRACE: < OK
0000040441 [ncp.at] TRACE: > ATO
0000040443 [ncp.at] TRACE: < NO CARRIER
0000040444 [ncp.at] TRACE: > ATD*99***1#
0000040462 [ncp.at] TRACE: < CONNECT 150000000
0000040463 [net.ppp.client] TRACE: PPP phase -> Initialize
0000040463 [net.ppp.client] TRACE: PPP phase -> Establish
0000040464 [lwip.ppp] TRACE: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x5852915c> <pcomp> <accomp>]
0000040471 [lwip.ppp] TRACE: rcvd [LCP ConfReq id=0x0 <asyncmap 0x0> <auth 0xc223 05> <magic 0x112e39af> <pcomp> <accomp>]
0000040473 [lwip.ppp] TRACE: sent [LCP ConfNak id=0x0 <auth pap>]
0000040475 [lwip.ppp] TRACE: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x5852915c> <pcomp> <accomp>]
0000040478 [lwip.ppp] TRACE: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <auth pap> <magic 0x112e39af> <pcomp> <accomp>]
0000040479 [lwip.ppp] TRACE: sent [LCP ConfAck id=0x1 <asyncmap 0x0> <auth pap> <magic 0x112e39af> <pcomp> <accomp>]
0000040480 [lwip.ppp] TRACE: sent [LCP EchoReq id=0x0 magic=0x5852915c]
0000040481 [net.ppp.client] TRACE: PPP phase -> Authenticate
0000040481 [lwip.ppp] TRACE: sent [PAP AuthReq id=0x1 user="" password=""]
0000040485 [lwip.ppp] TRACE: rcvd [LCP DiscReq id=0x2 magic=0x112e39af]
0000040488 [lwip.ppp] TRACE: rcvd [LCP EchoRep id=0x0 magic=0x112e39af 58 52 91 5c]
0000040490 [lwip.ppp] TRACE: rcvd [PAP AuthAck id=0x1 ""]
0000040490 [net.ppp.client] TRACE: PPP phase -> Network
0000040491 [lwip.ppp] TRACE: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <msdns1 8.8.8.8> <msdns2 8.8.4.4>]
0000040527 [lwip.ppp] TRACE: rcvd [IPCP ConfReq id=0x0]
0000040527 [lwip.ppp] TRACE: sent [IPCP ConfAck id=0x0]
0000040530 [lwip.ppp] TRACE: rcvd [IPCP ConfNak id=0x1 <addr 100.85.178.202> <msdns1 8.8.4.4> <msdns2 8.8.8.8>]
0000040530 [lwip.ppp] TRACE: sent [IPCP ConfReq id=0x2 <addr 100.85.178.202> <msdns1 8.8.4.4> <msdns2 8.8.8.8>]
0000040535 [lwip.ppp] TRACE: rcvd [IPCP ConfAck id=0x2 <addr 100.85.178.202> <msdns1 8.8.4.4> <msdns2 8.8.8.8>]
0000040540 [system.nm] INFO: State changed: IFACE_UP -> IFACE_LINK_UP
0000040541 [net.ppp.client] TRACE: PPP thread event UP data=0
0000040541 [net.ppp.client] TRACE: State CONNECTING -> CONNECTED
0000040542 [system.nm] INFO: State changed: IFACE_LINK_UP -> IP_CONFIGURED
0000040543 [net.ppp.client] TRACE: PPP phase -> Running
0000040545 [net.pppncp] TRACE: Negotiated MTU: 1500
0000040545 [system] INFO: Cloud: connecting
0000040551 [system] INFO: Cloud socket connected
0000040552 [comm.protocol.handshake] INFO: Establish secure connection
0000040557 [comm.dtls] INFO: session has 0 uses
0000040573 [comm.dtls] INFO: (CMPL,RENEG,NO_SESS,ERR) restoreStatus=0
0000040573 [comm.dtls] INFO: out_ctr 0,1,0,0,0,0,0,75, next_coap_id=3e
0000040575 [comm.dtls] INFO: restored session from persisted session data. next_msg_id=62
0000040576 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 2
0000040948 [ncp.at] TRACE: > AT+CFUN?
0000040951 [ncp.at] TRACE: < +CFUN: 1
0000040951 [ncp.at] TRACE: < OK
0000040953 [ncp.at] TRACE: > AT+CCID
0000040955 [ncp.at] TRACE: < +CCID: 89883070000023239831
0000040956 [ncp.at] TRACE: < OK
0000040957 [ncp.at] TRACE: > AT+CGSN
0000040959 [ncp.at] TRACE: < 868986060851202
0000040959 [ncp.at] TRACE: < OK
0000040960 [ncp.at] TRACE: > AT+CGMR
0000040962 [ncp.at] TRACE: < EG91EFBR06A07M4G
0000040962 [ncp.at] TRACE: < OK
0000040963 [comm.protocol.handshake] INFO: Skipping HELLO message
0000040964 [comm.coap] TRACE: Sending CoAP message
0000040965 [comm.coap] TRACE: CON 0.00 size=4 token= id=63
0000040968 [comm.coap] TRACE: Sending CoAP message
0000040968 [comm.coap] TRACE: CON POST /E/particle/device/updates/enabled size=44 token= id=64
0000040972 [comm.coap] TRACE: Sending CoAP message
0000040972 [comm.coap] TRACE: CON POST /E/particle/device/updates/forced size=44 token= id=65
0000040976 [comm.coap] TRACE: Sending CoAP message
0000040976 [comm.coap] TRACE: CON GET /t size=7 token=c1 id=66
0000041151 [comm.dtls] INFO: session cmd (CLS,DIS,MOV,LOD,SAV): 4
0000041153 [comm.coap] TRACE: Received CoAP message
0000041153 [comm.coap] TRACE: ACK 0.00 size=4 token= id=63
0000041176 [comm.coap] TRACE: Received CoAP message
0000041178 [comm.coap] TRACE: ACK 2.05 size=10 token=c1 id=66
0000041178 [comm.protocol] INFO: Received TIME response: 1704314727
0000041280 [comm.coap] TRACE: Received CoAP message
0000041280 [comm.coap] TRACE: ACK 0.00 size=4 token= id=65
0000041382 [comm.coap] TRACE: Received CoAP message
0000041382 [comm.coap] TRACE: ACK 0.00 size=4 token= id=64
0000041484 [system] INFO: Cloud connected
0000041484 [app] INFO: connected to the cloud in 41484 ms
This topic was automatically closed 182 days after the last reply. New replies are no longer allowed.