Imp become Blocked

Hardware
#1

The late days I am experimenting that some become blocked for several second (or even minutes). I’ve been working with the same program for several months and until now I haven’t realized of that problem.

The imp is monitoring a signal every second, showing the value on a display and sending the oportune log, and, when the imp become blocked, it stop from showing new values on the display and at the same time it doesn’t make any log.

When the imp gets back from blocked state the most strange thing is that it logs like it weren’t blocked the past time, posting on the second all the logs that were missed, an even on a strange order (12:24:04 before 12:24:03):

14-10-06 12:23:45 UTC+2 [Device] Ruido (1 seg) = 55dB [0.0037516] 2014-10-06 12:24:04 UTC+2 [Device] Ruido (1 seg) = 49dB [0.00198612] 2014-10-06 12:24:04 UTC+2 [Device] Ruido (1 seg) = 49.2dB [0.00202131] 2014-10-06 12:24:04 UTC+2 [Device] Ruido (1 seg) = 49.6dB [0.00212928] 2014-10-06 12:24:04 UTC+2 [Device] Media== 520 2014-10-06 12:24:04 UTC+2 [Device] Ruido (1 seg) = 49dB [0.00197997] 2014-10-06 12:24:04 UTC+2 [Agent] 200 2014-10-06 12:24:04 UTC+2 [Agent] {"lt":0.0,"lg":0.0,"d":52.0,"t":1412591044219,"n":"","dx":null,"st":0} 2014-10-06 12:24:04 UTC+2 [Device] Ruido (1 seg) = 47.4dB [0.0017445] 2014-10-06 12:24:04 UTC+2 [Device] Ruido (1 seg) = 61.2dB [0.00760162] 2014-10-06 12:24:04 UTC+2 [Device] Ruido (1 seg) = 49.2dB [0.00202331] 2014-10-06 12:24:04 UTC+2 [Device] Ruido (1 seg) = 60.9dB [0.00734752] 2014-10-06 12:24:04 UTC+2 [Device] Ruido (1 seg) = 45.5dB [0.0015484] 2014-10-06 12:24:04 UTC+2 [Device] Ruido (1 seg) = 45.1dB [0.00150838] 2014-10-06 12:24:04 UTC+2 [Device] Ruido (1 seg) = 47.6dB [0.00177097] 2014-10-06 12:25:03 UTC+2 [Device] Ruido (1 seg) = 59.6dB [0.00634411] 2014-10-06 12:25:03 UTC+2 [Device] Ruido (1 seg) = 47.2dB [0.00171882] 2014-10-06 12:25:03 UTC+2 [Device] Ruido (1 seg) = 49.5dB [0.00212112] 2014-10-06 12:25:03 UTC+2 [Device] Ruido (1 seg) = 49.8dB [0.00224712] 2014-10-06 12:25:03 UTC+2 [Device] Ruido (1 seg) = 62.8dB [0.00910632] 2014-10-06 12:25:03 UTC+2 [Device] Ruido (1 seg) = 59dB [0.0059088] 2014-10-06 12:25:03 UTC+2 [Device] Ruido (1 seg) = 53dB [0.00300842] 2014-10-06 12:25:03 UTC+2 [Device] Ruido (1 seg) = 58.2dB [0.0054414] 2014-10-06 12:25:03 UTC+2 [Device] Ruido (1 seg) = 63dB [0.00934966] 2014-10-06 12:25:03 UTC+2 [Device] Ruido (1 seg) = 63.7dB [0.0100866] 2014-10-06 12:25:03 UTC+2 [Device] Ruido (1 seg) = 59.9dB [0.00656876] 2014-10-06 12:25:03 UTC+2 [Device] Ruido (1 seg) = 56.7dB [0.00459086] 2014-10-06 12:25:03 UTC+2 [Device] Ruido (1 seg) = 56.2dB [0.00431295] 2014-10-06 12:25:03 UTC+2 [Device] Ruido (1 seg) = 53.7dB [0.00324038] 2014-10-06 12:25:03 UTC+2 [Device] Ruido (1 seg) = 51.6dB [0.00254736] 2014-10-06 12:25:03 UTC+2 [Device] Ruido (1 seg) = 51.4dB [0.00250373] 2014-10-06 12:25:03 UTC+2 [Device] Ruido (1 seg) = 52.7dB [0.00290927] 2014-10-06 12:25:03 UTC+2 [Device] Ruido (1 seg) = 52.8dB [0.00293469]

I’ve tried with and without wifi signal and it doesn’t seem to be related. The code itself doesn’t explain that behavior that results randomly and with a duration that could be from 5 seconds to even minutes (that made me to setup the imp again)

Any clue to this behaviour, not only to the blocking but to the logging too?

#2

The order doesn’t appear strange, 12:25:03 comes after 12:24:04. Remember that the Agent and Device are not synchronous so their messages may not appear interleaved in the manner you may expect. If you are using server.log() at the device level, consider adding +"time: "+time() or +"time: "+(hardware.millis()/1000)to the end of your string.

#3

The IDE has a mechanism built in to prevent too many log messages from appearing at the same time (which can result in the IDE essentially hanging). If you are logging too many messages, this may be what’s happening / causing the odd behaviour.

#4

I just make one log a second, however, when it blocks it doesn’t do anything and after some time throws all the logs at he same second.

It’s strange because if it was really blocked, it should just make one log after the blocking period. Instead it post the past logs like it were actually thinking and not blocked, but physically you can see it is blocked.

Could it be that an internal event were stoping others events and let them on the stack ?

#5

Possibly?

Is the behaviour intermittent, or fairly consistent (i.e - has this only happened once or twice, or does it happen often).